View Issue Details
|ID||Project||Category||View Status||Date Submitted||Last Update|
|0001707||Ham Radio Deluxe||Bug||public||2014-08-25 11:13||2017-08-05 18:27|
|Target Version||Fixed in Version||18.104.22.1681|
|Summary||0001707: Large ADIF import causes Logbook to crash|
|Description||I have a user (osTicket #491667) reports the following:|
I get a "Encountered an improper argument." error when importing the attached ADIF file in Logbook.
His ADIF had 60,000 records. If he split it in half, each half imported fine.
|Steps To Reproduce||Import the attached ADIF into an empty Logbook database.|
|Tags||No tags attached.|
AdifFile.zip (883,075 bytes)
I did this test myself with a large log. I can confirm that it does generate an error. I'll be attaching a log to this record that has over 125,000 QSOs in it for testing.
It's possible that there was bad data in the guy's log. I'm cleaning up this log and will repeat this.
I've got a few tweaks in place that are aimed at improving performance for the ADIF import process. There's an incredible amount of N^2 algorithms (searching lists of fields again again, by string name) and some dubious code to delete values from the list view which ends up sending thousands of messages through a loop in Windows.
The investigation also exposes inefficiency in the logbook's storage, which does one memory allocation per cell in the logbook. Since each record has about 240 columns, a 65,000 row logbook import will cause more than 15 million allocations and deletions. During the import process, this issue is exacerbated by the way the lifecycle of CLogbookQSORecordset objects is managed.
In both debug and release builds of the current codebase (after 6.4.650) on my desktop under Visual Studio, I'm able to perform this import without the application crashing.
When I try against a copy of 6.4.649 installed in a VM, the import appears to work successfully then falls over with this message box:
Encountered an improper argument.
I'm a bit helpless to debug this; the messgae box offers no information about what call, where in the code, encountered a problem. I think the only way I can proceed is to install some debugging tools into my VM, then get a call stack that shows where this message box occurs. That might give some hints about what is actually going wrong.
Meanwhile, I can check in changes that help with the efficiency a little ...
After importing a large number of records, the Logbook view will realize it has too many items. It will start removing items in a tight little loop; that loop gets the count of items in the control, see if it's higher than the limit, then deletes an item. Thing is, getting the number of items in the control sends a Windows message to the control, and that's not very efficient.
I've tweaked the code to get the number of items in the control and keep it in a local variable. The loop still sends one message per deletion, but that's absolutely necessary ... and fewer than two messages per deletion.
I think part of this was related to the changes that were made to the WSI... and it was so laborious to update WSI (importing with cluster connection)... every record imported seemed to refresh the entire cluster... but since we buried that code for a while, I don't think this has happened.
Mike - we should chat about this a bit and I can explain it further.
Turns out this is caused by a data structure that implements the "log file" view in the Logbook. This view contains trace messages that, I presume, are intended to be useful in debugging customer problems. The import process would emit a log file string for each record imported, causing the log file view to decide it wants to prune itself. The code to perform the pruning was broken: it would try to delete a negative number of records, which resulted in the "improper argument" exception. Unfortunately, recent changes to the code caused a locked critical section to leak when the exception was thrown, and that's just a disaster; either more "improper arguments" would appear, or a hang would happen waiting for the orphaned critsec.
I've fixed three things:
1) Fixed the math so the log file data structure correctly prunes itself.
2) Removed a completely unused array involved with the log file view. This saves about 200,000 bytes of memory.
3) Removed the trace message in the first place. It was useless, since there's no way to know which user-visible record it referenced.
There's a couple more improvements which can be made, so I've dropped a couple TODO comments in the cdoe to remind me about them at a future date.
Fixed with this change set:
||Confirm Fix in 669|
||I don't have a log file big enough to test, sorry.|
||Using Mike's log above I had no problems using the Steps to Reproduce. Fixed for me.|
||All completed during the 670 build/release.|
|2014-08-25 11:13||WA9PIE||New Issue|
|2014-08-25 11:13||WA9PIE||File Added: AdifFile.zip|
|2014-10-08 22:05||WA9PIE||Project||3 - Current Dev List => 2 - Next Dev List (Holding Area)|
|2015-09-17 13:40||WA9PIE||Category||Logbook => Bug|
|2015-09-22 16:37||WA9PIE||Fix Build||TBD => (select)|
|2015-09-22 16:37||WA9PIE||Report Build||22.214.171.1244 => (select)|
|2015-09-22 16:37||WA9PIE||Proposed Release||=> (select)|
|2015-09-22 16:37||WA9PIE||Summary||Bug: Large ADIF import causes Logbook to crash => Large ADIF import causes Logbook to crash|
|2016-12-04 13:10||WA9PIE||Reported in Release||6.2 => 6.3|
|2016-12-04 13:10||WA9PIE||Reported in Build (ie. 377)||(select) => 610|
|2016-12-04 13:10||WA9PIE||Note Added: 0003074|
|2016-12-04 13:10||WA9PIE||Assigned To||=> WA9PIE|
|2016-12-04 13:10||WA9PIE||Status||new => confirmed|
|2016-12-04 13:26||WA9PIE||Note Edited: 0003074||View Revisions|
|2017-03-05 14:21||WA9PIE||Assigned To||WA9PIE => W4PC|
|2017-06-07 01:16||K7ZCZ||Assigned To||W4PC => K7ZCZ|
|2017-06-07 13:42||K7ZCZ||Note Added: 0003204|
|2017-06-09 03:23||K7ZCZ||Note Added: 0003206|
|2017-06-19 22:58||WA9PIE||Project||2 - Next Dev List (Holding Area) => 3 - Current Dev List|
|2017-06-19 23:01||WA9PIE||Note Added: 0003223|
|2017-07-26 19:31||K7ZCZ||Relationship added||related to 0002158|
|2017-07-30 23:30||K7ZCZ||Note Added: 0003790|
|2017-07-30 23:31||K7ZCZ||Status||confirmed => resolved|
|2017-07-30 23:31||K7ZCZ||Resolution||open => fixed|
|2017-07-30 23:31||K7ZCZ||Testing||=> Not Started|
|2017-07-30 23:31||K7ZCZ||Note Added: 0003791|
|2017-08-02 07:33||K7ZCZ||Fixed in Version||=> 126.96.36.1999|
|2017-08-03 10:15||PD9FER||Note Added: 0003866|
|2017-08-03 11:36||n4kit||Note Added: 0003872|
|2017-08-03 16:18||g3ucq||Note Added: 0003880|
|2017-08-05 18:07||WA9PIE||Testing||Not Started => Not Tested|
|2017-08-05 18:09||WA9PIE||Fixed in Version||188.8.131.529 => 184.108.40.2060|
|2017-08-05 18:10||WA9PIE||Project||3 - Current Dev List => Ham Radio Deluxe|
|2017-08-05 18:13||WA9PIE||Note Added: 0003920|
|2017-08-05 18:13||WA9PIE||Status||resolved => closed|
|2017-08-05 18:27||WA9PIE||Fixed in Version||220.127.116.110 => 18.104.22.1681|