View Issue Details

IDProjectCategoryView StatusLast Update
00032991 - BacklogBugpublic2019-04-18 14:31
ReporterKB3NPHAssigned To 
PrioritynormalSeverityminorReproducibilityalways
Status newResolutionopen 
Summary0003299: V6.5.0.207 Connecting to DX cluster locks Logbook
DescriptionTicket #162197 - Did remote into customer's computer. When running HRD and loading Logbook, everything functions properly until you connect to any DX node. Tested this with several including WA9PIE-2.

As soon as you open the DX cluster and the system starts updating the WSIs for the spots coming in, the DX cluster locks Logbook so that the only way out is to kill it in Task Manager.

In DX Cluster options we even set the # of initial spots to 50. When the cluster node is opened, it will display maybe 3 or 4 updated spots and indicate that on the toolbar. The updating # will indicate 50+ records updating, but it seems never to catch up, no matter how long you sit and watch the updates.

We tried repairing the C++ 2017 Redist, also ran the repair on the Access 2016 Redist. Ran Malwarebytes, Nothing we normally do to resolve this problem helped.

Recovered a LogFile from Logbook to see if anything in there could give a clue as to what the problem is. I have posted it in the Dump Folder in a folder identified by this Mantis Issue#.

TagsNo tags attached.
ModuleLogbook
Sub-ModuleDX Cluster
TestingNot Started

Relationships

related to 0003248 resolvedK7ZCZ 2 - Next Dev List (Holding Area) bad parameters for ODBC recordsets throughout Logbook 
related to 0002797 closedWA9PIE Ham Radio Deluxe Logbook stops displaying spots normally (they're grey'd out and have the search folder icon in the far left column) 
related to 0002919 resolvedKB3NPH 1 - Backlog DX Cluster WSI Lookups stalling DX Cluster 
has duplicate 0003298 resolvedK7ZCZ 2 - Next Dev List (Holding Area) Running DX Cluster totally locks up any logging functions 

Activities

K7ZCZ

2019-04-16 18:55

administrator   ~0007866

The logfile shwos that Access is very (!) slow on this customer's computer. Lookups for "AM70S" (AM7zeroS, not AM7ohS) take a very long time:

13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3148): [connection = 00CAE0B8, threadNumber = 1, callsign = "AM70S"] 45378733 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3197): [connection = 00CAE0B8, threadNumber = 1, callsign = "AM70S"] 15840 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3590): [connection = 00CAE0B8, threadNumber = 1, callsign = "AM70S"] 22988 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3647): [connection = 00CAE0B8, threadNumber = 1, callsign = "AM70S"] 4141 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3590): [connection = 00CAE0B8, threadNumber = 1, callsign = "AM70S"] 2094 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3647): [connection = 00CAE0B8, threadNumber = 1, callsign = "AM70S"] 5573 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3705): [connection = 00CAE0B8, threadNumber = 1, callsign = "AM70S"] 2852 microseconds
13:12:06  CDXCObject     lookup of "AM70S" took 127032 milliseconds


Since Access takes more than two minutes (127 seconds) to look up a single call, it's unlikely the cluster will keep up an incomnig rate of a few entries per minute. (I don't think the full lifetime of the AM70S lookup is visible in the log.)

Another call overlaps with AM70S; Access takes more than 75 seconds to complete the work for IK2YDJ:

13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (2490): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 45378948 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (2791): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 15628 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3064): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 8557 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3113): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 1695 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3148): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 3471 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3197): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 2110 microseconds
13:12:06  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3590): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 12999 microseconds
13:12:09  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3647): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 3283594 microseconds
13:12:09  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3590): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 3137 microseconds
13:12:09  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3647): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 2361 microseconds
13:12:09  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (3705): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 3873 microseconds
13:12:09  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (4466): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 103697 microseconds
13:12:09  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (4511): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 81336 microseconds
13:12:09  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (4511): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 5748 microseconds
13:12:10  Stopwatch      c:\hrd65\logbook\hrdlogbook\backgroundprocessingthreadlookups.cpp (4511): [connection = 00CAE398, threadNumber = 0, callsign = "IK2YDJ"] 134439 microseconds
13:12:10  CDXCObject     lookup of "IK2YDJ" took 75723 milliseconds


The first query for IK2YDJ takes about 45 seconds to execute.

A couple of other lookups are visible with very long total times:

13:13:11  CDXCObject     lookup of "EB3TC" took 61777 milliseconds
13:13:11  CDXCObject     lookup of "AM70A" took 61902 milliseconds


For acceptable performance, lookups shouldn't be taking much longer than 2000 millseconds. For good performane, 500 milliseconds is about the top of the acceptable range. These two toom more than a minute each.

The bad record set and connection parameters (see Mantis 3248) are selecting an expensive isolation level, which might be at the root of the problem. That's the only active issue I'm trackign which I think could relate to this kind of performance. Otherwise, we need more observations from the effected customers to understnd what's happening as I'm not able to directly reproduce the problem myslef.

Issue History

Date Modified Username Field Change
2019-04-16 13:51 KB3NPH New Issue
2019-04-16 18:55 K7ZCZ Note Added: 0007866
2019-04-17 08:47 K7ZCZ Relationship added has duplicate 0003298
2019-04-17 09:40 K7ZCZ Relationship added related to 0003248
2019-04-18 14:29 K7ZCZ Relationship added related to 0002797
2019-04-18 14:31 K7ZCZ Relationship added related to 0002919