View Issue Details

IDProjectCategoryView StatusLast Update
0002222Ham Radio DeluxeBugpublic2019-03-31 11:13
ReporterK7ZCZAssigned ToK7ZCZ 
PrioritynormalSeveritycrashReproducibilitysometimes
Status closedResolutionfixed 
PlatformIntel i7-5960XOSWindows 10 Professional x64OS Version1703
Product Version6.4.0.780 
Target VersionFixed in Version6.5.0.207 
Summary0002222: Logbook: restoring large XML backup causes out of memory crash
DescriptionRestoring 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 Reproduce1) 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!CTextInputClientFreeThread::PutHasFocus(bool) Unknown
     msctf.dll!CTextInputClientWrapper::PutHasFocus(bool) Unknown
     TextInputFramework.dll!TextInputHost::PutHasFocusInternal(bool,unsigned long) Unknown
     TextInputFramework.dll!TextInputHost::PutHasFocus(bool) 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
     user32.dll!___ClientCallWinEventProc@4() Unknown
     ntdll.dll!_KiUserCallbackDispatcher@12() Unknown
     win32u.dll!_NtUserSetFocus@4() Unknown
     user32.dll!_MB_DlgProc@16() Unknown
     user32.dll!__InternalCallWinProc@20() Unknown
     user32.dll!_UserCallDlgProcCheckWow@32() Unknown
     user32.dll!_DefDlgProcWorker@24() Unknown
     user32.dll!_DefDlgProcW@16() Unknown
     user32.dll!__InternalCallWinProc@20() Unknown
     user32.dll!_UserCallWinProcCheckWow@36() Unknown
     user32.dll!_CallWindowProcW@20() Unknown
     HRDLogbook.exe!_AfxActivationWndProc(HWND__ * hWnd=0x00141ce4, unsigned int nMsg=272, unsigned int wParam=1190408, long lParam=63941120) Line 471 C++
     [External Code]
> 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++
     [External Code]
     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++
     [External Code]
TagsNo tags attached.
ModuleLogbook
Sub-ModuleData
Testing Beta Successful

Relationships

related to 0002219 closedK7ZCZ Logbook: Loading an XML backup is very slow due to the use of a DOM parser 
related to 0002696 closedWA9PIE Importing Logfile 155,000 + QSO's crashes LB 

Activities

K7ZCZ

2018-10-29 17:56

manager   ~0006355

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

K7ZCZ

2019-02-20 11:45

manager   ~0007458

Some performance fixes are made in this check, and some small improvement in memory usage too.
https://hrdsoftware.visualstudio.com/HRD/_versionControl/changeset/4837

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.

WA9PIE

2019-02-21 21:21

administrator   ~0007486

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

WA9PIE

2019-02-21 21:25

administrator   ~0007487

Last edited: 2019-02-21 21:27

View 2 revisions

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.)

K7ZCZ

2019-02-22 01:05

manager   ~0007488

This issue is about restoring an XML backup, not about creating one.

K7ZCZ

2019-03-03 10:40

manager   ~0007566

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.

K7ZCZ

2019-03-07 10:48

manager   ~0007632

fixed with this checkin:
https://hrdsoftware.visualstudio.com/HRD/_versionControl/changeset/4887

WA9PIE

2019-03-08 12:06

administrator   ~0007641

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?)

K7ZCZ

2019-03-08 12:39

manager   ~0007642

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.

g3ucq

2019-03-09 05:55

viewer   ~0007644

Unable to test as I do not have a large enough database.

WA9PIE

2019-03-10 17:41

administrator   ~0007658

Validated with the a very large 181k QSO log.

Issue History

Date Modified Username Field Change
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 => 6.5.0.202
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 6.5.0.202 => 6.5.0.207
2019-03-31 11:13 WA9PIE Project 3 - Current Dev List => Ham Radio Deluxe