View Issue Details
|ID||Project||Category||View Status||Date Submitted||Last Update|
|0002222||Ham Radio Deluxe||Bug||public||2017-08-19 15:30||2019-03-31 11:13|
|Platform||Intel i7-5960X||OS||Windows 10 Professional x64||OS Version||1703|
|Target Version||Fixed in Version||220.127.116.11|
|Summary||0002222: Logbook: restoring large XML backup causes out of memory crash|
|Description||Restoring a very large XML backup uses memory (because of the use of an all-at-once DOM approach for loading the XML). The logbook has a pretty inefficient in-memory structure for its data, and as a result consumes a large amount of memory.|
A logbook backup fo about 120,000 records regularly crashes a debug build of the Logbook application.
|Steps To Reproduce||1) Open logbook|
2) Create a new database, fresh
3) Restore large (120,000 records) QSO XML backup
4) It's pretty slow. It finishes, and press "Finish" in the dialog box
5) After a pause, the logbook will crash with an out of memory exception. It may simply crash, it may render the "out of memory" box, or something else. Low-memory handling in the application is very poor.
Note that I happen to be using a debug build. It's not as efficient as a retail build for sure, but all that means is that the limit of rows/data imported is lower.
|Additional Information|| TextInputFramework.dll!`Microsoft::WRL::Module<1,class Microsoft::WRL::Details::DefaultModule<1> >::Create(void)'::`2'::`dynamic atexit destructor for 'moduleSingleton''(void) Unknown|
TextInputFramework.dll!TextInputHost::PutHasFocusInternal(bool,unsigned long) Unknown
msctf.dll!CThreadInputMgr::OnInputFocusEvent(unsigned long,struct HWND__ *,long,long,unsigned long,unsigned long) Unknown
msctf.dll!WinEventProc(struct HWINEVENTHOOK__ *,unsigned long,struct HWND__ *,long,long,unsigned long,unsigned long) Unknown
HRDLogbook.exe!_AfxActivationWndProc(HWND__ * hWnd=0x00141ce4, unsigned int nMsg=272, unsigned int wParam=1190408, long lParam=63941120) Line 471 C++
> HRDLogbook.exe!CWinApp::ShowAppMessageBox(CWinApp * pApp=0x029c2670, const wchar_t * lpszPrompt=0x03cfad6c, unsigned int nType=4144, unsigned int nIDPrompt=0) Line 122 C++
HRDLogbook.exe!CWinApp::DoMessageBox(const wchar_t * lpszPrompt=0x03cfad6c, unsigned int nType=4144, unsigned int nIDPrompt=0) Line 39 C++
HRDLogbook.exe!AfxMessageBox(const wchar_t * lpszText=0x03cfad6c, unsigned int nType=4144, unsigned int nIDHelp=0) Line 141 C++
HRDLogbook.exe!CException::ReportError(unsigned int nType=4144, unsigned int nError=61705) Line 109 C++
HRDLogbook.exe!CWinApp::ProcessWndProcException(CException * e=0x029e1590, const tagMSG * pMsg=0x03fddd74) Line 1030 C++
HRDLogbook.exe!AfxProcessWndProcException(CException * e=0x029e1590, const tagMSG * pMsg=0x03fddd74) Line 214 C++
HRDLogbook.exe!AfxCallWndProc(CWnd * pWnd=0x0d0619e0, HWND__ * hWnd=0x005a1862, unsigned int nMsg=273, unsigned int wParam=32983, long lParam=0) Line 290 C++
HRDLogbook.exe!AfxWndProc(HWND__ * hWnd=0x005a1862, unsigned int nMsg=273, unsigned int wParam=32983, long lParam=0) Line 435 C++
HRDLogbook.exe!AfxInternalPumpMessage() Line 181 C++
HRDLogbook.exe!CWinThread::PumpMessage() Line 900 C++
HRDLogbook.exe!CWinThread::Run() Line 629 C++
HRDLogbook.exe!CWinApp::Run() Line 787 C++
HRDLogbook.exe!AfxWinMain(HINSTANCE__ * hInstance=0x000c0000, HINSTANCE__ * hPrevInstance=0x00000000, wchar_t * lpCmdLine=0x03fd3210, int nCmdShow=10) Line 47 C++
HRDLogbook.exe!wWinMain(HINSTANCE__ * hInstance=0x000c0000, HINSTANCE__ * hPrevInstance=0x00000000, wchar_t * lpCmdLine=0x03fd3210, int nCmdShow=10) Line 26 C++
|Tags||No tags attached.|
||LibXML looks like a good candidate for a streaming parser. A thoughtful decision chart (with good annotations) is available on StackOverflow: https://stackoverflow.com/questions/9387610/what-xml-parser-should-i-use-in-c|
Some performance fixes are made in this check, and some small improvement in memory usage too.
This checkin does not resolve the fundamental issue of using a document-oriented XML parser, so there's still significant memory pressure when loading an XML backup.
What I'm about to report conflicts a bit with the summary of this issue. But this is the one we agreed to track the XML problem with. This problem seems to have to do with the creation of an XML backup during the ADIF import process.
Word from WB2REM as follows:
He tells me that he was not previously able to do the ADIF import while the backup was enabled. So there was no (intentional) attempt to create a backup after the ADIF was imported (that would have caused the dump). I asked him to disable his backup options, attempt the import of the same file, and report back.
"Mike, I think that worked. I unchecked backup when closing. Created a blank new log. Imported the large 187,000 adi. I then put backup on close again. I Added a few QSOs and closed and backed up. It didn't do a minidump and was able to locate the backup. I then tried to export the full log adi and I was successful."
So... from this, what WB2REM is telling us is this:
- when the ADIF import was done while the backup option was enabled, Logbook ran the machine out of memory and Logbook crashed
- when the ADIF import was done while the backup options were disabled, Logbook imported the ADIF without error
- his backup option was set to create a backup on closing (which was not what was expected)
Recommendation from WA9PIE:
- it makes no sense to enable the backup process to run during the process of importing an ADIF or restoring a log in XML
- it makes no sense to allow the DX cluster to calculate WSIs during the process of importing an ADIF or restoring a log in XML
After importing the ADIF, I attempted to create a backup of that file. The program crashed and created a mini-dump. I'll post it to GD in Mantis 2222.
(Thus far, I've been unable to locate the minidump.)
||This issue is about restoring an XML backup, not about creating one.|
This fix is code complete. It's pretty risky, so I've sent some email to the team to discuss how we might test it. I haven't yet received a reply.
The improvement is substantial. Informal benchmarking is dangerous, but:
Before the fix, restoring a backup with 126,665 records into Access on my development machine took more than 19 minutes.
After the fix, the same operation completes in about 90 seconds. The new implementation is about 13 times faster.
fixed with this checkin:
I 'think' this is in the 202 build, but FIV isn't updated for this record.
Meanwhile, I did a deeper dive into WB2REM's log (181k QSOs). His DXCC awards totals were off in such an obvious way that I started looking for why (it showed 338 worked... and 3 needed... that's a total of 341... and there are only 340 total in the list). I found that this log, exported to ADIF from DXLabs DXkeeper, had 13 QSOs where the DXCC numeric is "666". (Which seems rather evil to me.) I changed them to the correct values manually (Notepad++). I'm going to run some tests using the fixed version. But it causes me to wonder if this creates a problem for the import/export/backup/restore. (In other words - what does the program do on import if it can't find a country with a DXCC=666? Does it go into some endless loop trying to find 666 in the Country List until it runs the machine out of memory?)
||The cause of high memory usage is as documented here and in 2219. It doesn't involve a loop. DXCC numbers are not looked up during the restore process.|
||Unable to test as I do not have a large enough database.|
||Validated with the a very large 181k QSO log.|
|2017-08-19 15:30||K7ZCZ||New Issue|
|2017-08-19 16:29||K7ZCZ||Relationship added||related to 0002219|
|2017-09-18 00:14||WA9PIE||Project||3 - Current Dev List => 2 - Next Dev List (Holding Area)|
|2018-04-13 10:23||WA9PIE||Project||2 - Next Dev List (Holding Area) => 3 - Current Dev List|
|2018-04-30 18:19||K7ZCZ||Relationship added||related to 0002696|
|2018-10-29 17:56||K7ZCZ||Note Added: 0006355|
|2019-02-20 11:45||K7ZCZ||Note Added: 0007458|
|2019-02-21 21:21||WA9PIE||Note Added: 0007486|
|2019-02-21 21:21||WA9PIE||Assigned To||=> K7ZCZ|
|2019-02-21 21:21||WA9PIE||Status||new => assigned|
|2019-02-21 21:25||WA9PIE||Note Added: 0007487|
|2019-02-21 21:27||WA9PIE||Note Edited: 0007487||View Revisions|
|2019-02-22 01:05||K7ZCZ||Note Added: 0007488|
|2019-03-03 10:40||K7ZCZ||Note Added: 0007566|
|2019-03-07 10:48||K7ZCZ||Status||assigned => resolved|
|2019-03-07 10:48||K7ZCZ||Resolution||open => fixed|
|2019-03-07 10:48||K7ZCZ||Note Added: 0007632|
|2019-03-08 12:06||WA9PIE||Note Added: 0007641|
|2019-03-08 12:39||K7ZCZ||Note Added: 0007642|
|2019-03-08 12:40||K7ZCZ||Fixed in Version||=> 18.104.22.168|
|2019-03-09 05:55||g3ucq||Note Added: 0007644|
|2019-03-10 17:41||WA9PIE||Status||resolved => closed|
|2019-03-10 17:41||WA9PIE||Description Updated||View Revisions|
|2019-03-10 17:41||WA9PIE||Additional Information Updated||View Revisions|
|2019-03-10 17:41||WA9PIE||Testing||Not Started => Beta Successful|
|2019-03-10 17:41||WA9PIE||Note Added: 0007658|
|2019-03-31 11:13||WA9PIE||Fixed in Version||22.214.171.124 => 126.96.36.199|
|2019-03-31 11:13||WA9PIE||Project||3 - Current Dev List => Ham Radio Deluxe|