Slow logging

Yes, sometimes it happens... Please report any bugs here
Locked
w9mdb
Old Man
Posts: 434
Joined: 13 Jul 2014, 12:05

Slow logging

Post by w9mdb »

Once in while...perhaps once per day or less one QSO will take an inordinately long time to log.

Logging is being done from JTAlert.
It's been doing this for a long time I just never complained about it before.

It's mainly noticeable as JTAlert complains when the QSO isn't logged within 5 seconds.

Meanwhile, Log4OM is doing a lot of disk I/O for perhaps 20 seconds or so before the QSO shows up in the Log4OM window.

So is there some cleanup or maintenance being done one the database once in a while? Using the sqlite db.

73
Mike W9MDB
User avatar
NN7D
Log4OM Alpha Team
Posts: 816
Joined: 19 Feb 2014, 19:44

Re: Slow logging

Post by NN7D »

Hi Mike,

You might make sure you are starting Log4OM, your JT65 program, and JT-Alert all as Administrator. Also, what operating system are you on, and how many QSO's in your log?

If above does not help, do the following - enable Trace + SQL Logging mode - Help\Debug Mode\Trace, then try logging again and when you get the delay, go to Help\Send Bug report and follow the directions. Then send the zip file bug report to me at svtdoug (at) gmail (dot) c0m.

Note: If issue does not appear right away, and you shut down Log4OM, when you restart you will have to enable Trace + SQL mode again.

Doug - W7DRM
Doug - NN7D
Gig Harbor, WA, USA
w9mdb
Old Man
Posts: 434
Joined: 13 Jul 2014, 12:05

Re: Slow logging

Post by w9mdb »

I've found two instances of slow logging.
One was when my internet connection was down.
It appears that the QSO is not logged until it's done trying to upload to all web sites. Perhaps that's the intent but I'd be more tempted to update the database first, then update the QSO-sent statuses independently.

But here's another case where it looks like the QRZ lookup took an extremely long time. I had successfully logged a QSO at 8:17 and then the 2nd one at 08:21 took 35 seconds to get the QRZ lookup. Is there some timeout in that section of code that it did a retry?

JTAlert expects to see the database updated within 5 seconds. This is not a major problem but I imagine others might get somewhat disconcerted when JTAlert shows a logging failure or that it takes so long for it to show up on Log4OM so I'm just trying to see if there's a known problem or perhaps a better way by logging something immediately and then updating it later (perhaps a drop and insert later to minimize code changes?).

2016-03-30 08:17:04.2807 INFO: AdifManagement: Begin ADIF import
2016-03-30 08:17:04.2843 INFO: AdifManagement: End of ADIF import
2016-03-30 08:17:04.2873 INFO: #=qcoFPcEBAlLNM6ZABBNyo74xi64gW6GTmArn3_V1N66s=: BEGIN: Add QSO From external event Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:04.2898 INFO: QrzComManagement: QRZ.COM begin update QSO
2016-03-30 08:17:04.3058 INFO: QrzComManagement: Begin search for KC9QPM
2016-03-30 08:17:04.7251 INFO: QrzComManagement: search completed
2016-03-30 08:17:04.7296 INFO: SharedFunctionsManagement: Checking External Informations. Initial values: DXCC 291 COUNTRY United States
2016-03-30 08:17:04.7640 INFO: SharedFunctionsManagement: Check Country got United States
2016-03-30 08:17:04.7690 INFO: SharedFunctionsManagement: Filling informations from Clublog Zone Exception
2016-03-30 08:17:04.7720 INFO: QrzComManagement: update QSO completed
2016-03-30 08:17:05.1658 INFO: EqslManagement: Send single qso start
2016-03-30 08:17:05.1768 INFO: AdifManagement: Begin EQSL row creation for Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.1768 INFO: HamQthManagement: Send single qso start
2016-03-30 08:17:05.1928 INFO: AdifManagement: Begin HamQTH row creation for Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.1928 INFO: QrzComUpload: UPLOAD begin upload QSO to QRZ.COM Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.1973 INFO: AdifManagement: End HamQTH row creation for Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.2018 INFO: AdifManagement: Begin export single QSO to ADIF string
2016-03-30 08:17:05.2018 INFO: HRDLogManagement: UPLOAD begin upload QSO Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.2109 INFO: AdifManagement: Export QSO to ADIF file completed
2016-03-30 08:17:05.2155 INFO: ClubLogManagement: UPLOAD begin upload QSO Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.2255 INFO: AdifManagement: Begin ClubLog row creation for Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.2300 INFO: AdifManagement: End ClubLog row creation for Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.3702 INFO: AdifManagement: Begin HRDLog row creation for Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.3732 INFO: AdifManagement: End HRDLog row creation for Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.4701 INFO: QrzComUpload: LOGID=235926248&COUNT=1&RESULT=OK
2016-03-30 08:17:05.6913 INFO: #=qcoFPcEBAlLNM6ZABBNyo74xi64gW6GTmArn3_V1N66s=: QSO Added via External Form for QSO : Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:05.7009 INFO: TCPEventManager: QSO Added via AddQso TCP for QSO : Call: KC9QPM Date: 20160330 Time: 131500 Band: 40m Mode: JT65
2016-03-30 08:17:06.4860 INFO: EqslManagement: Send qso completed
2016-03-30 08:17:07.0821 INFO: HamQthManagement: HamQTH upload completed QSO inserted
2016-03-30 08:17:07.0857 INFO: HamQthManagement: Send qso completed
2016-03-30 08:21:12.9941 INFO: AdifManagement: Begin ADIF import
2016-03-30 08:21:12.9971 INFO: AdifManagement: End of ADIF import
2016-03-30 08:21:13.0004 INFO: #=qcoFPcEBAlLNM6ZABBNyo74xi64gW6GTmArn3_V1N66s=: BEGIN: Add QSO From external event Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:13.0034 INFO: QrzComManagement: QRZ.COM begin update QSO
2016-03-30 08:21:13.0203 INFO: QrzComManagement: Begin search for AI4CH
2016-03-30 08:21:47.9921 INFO: QrzComManagement: search completed
2016-03-30 08:21:47.9991 INFO: SharedFunctionsManagement: Checking External Informations. Initial values: DXCC 291 COUNTRY United States
2016-03-30 08:21:48.0595 INFO: SharedFunctionsManagement: Check Country got United States
2016-03-30 08:21:48.0635 INFO: SharedFunctionsManagement: Filling informations from Clublog Zone Exception
2016-03-30 08:21:48.0665 INFO: QrzComManagement: update QSO completed
2016-03-30 08:21:48.2790 INFO: EqslManagement: Send single qso start
2016-03-30 08:21:48.2830 INFO: HamQthManagement: Send single qso start
2016-03-30 08:21:48.2870 INFO: QrzComUpload: UPLOAD begin upload QSO to QRZ.COM Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.2910 INFO: HRDLogManagement: UPLOAD begin upload QSO Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.2945 INFO: ClubLogManagement: UPLOAD begin upload QSO Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.5112 INFO: AdifManagement: Begin EQSL row creation for Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7100 INFO: #=qcoFPcEBAlLNM6ZABBNyo74xi64gW6GTmArn3_V1N66s=: QSO Added via External Form for QSO : Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7190 INFO: TCPEventManager: QSO Added via AddQso TCP for QSO : Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7288 INFO: AdifManagement: Begin export single QSO to ADIF string
2016-03-30 08:21:48.7288 INFO: AdifManagement: Begin HamQTH row creation for Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7358 INFO: AdifManagement: Export QSO to ADIF file completed
2016-03-30 08:21:48.7369 INFO: AdifManagement: Begin HRDLog row creation for Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7288 INFO: AdifManagement: Begin ClubLog row creation for Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7529 INFO: AdifManagement: End HRDLog row creation for Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7438 INFO: AdifManagement: End HamQTH row creation for Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.7568 INFO: AdifManagement: End ClubLog row creation for Call: AI4CH Date: 20160330 Time: 131800 Band: 40m Mode: JT65
2016-03-30 08:21:48.9316 INFO: QrzComUpload: RESULT=OK&LOGID=235929122&COUNT=1
2016-03-30 08:21:49.3887 ERROR: *** HamQthManagement: The remote server returned an error: (400) Bad Request. ******* [Function: #=qB2FcvZcvHUhKS0zNhvOQyg==] System.Net.WebException: The remote server returned an error: (400) Bad Request.
at System.Net.HttpWebRequest.GetResponse()
at LogOM.BL.HamQthManagement.#=qB2FcvZcvHUhKS0zNhvOQyg==(QSO #=qATfE9RwKHiV0BljiDCr2dw==, String #=qL9OSK6GgRvhxlybnyQWHhg==, String #=qjk682VCpBUUiKAvmYxxTnQ==, String #=qZe1rlz37UhntXrVJA6_J9Q==, String #=qlWFTl3cz6lzgnrQVsmJnKQ==)
2016-03-30 08:21:49.3922 ERROR: *** HamQthManagement: HamQTH SendQSO error ******* [Function: #=qB2FcvZcvHUhKS0zNhvOQyg==] System.Net.WebException: The remote server returned an error: (400) Bad Request.
at System.Net.HttpWebRequest.GetResponse()
at LogOM.BL.HamQthManagement.#=qB2FcvZcvHUhKS0zNhvOQyg==(QSO #=qATfE9RwKHiV0BljiDCr2dw==, String #=qL9OSK6GgRvhxlybnyQWHhg==, String #=qjk682VCpBUUiKAvmYxxTnQ==, String #=qZe1rlz37UhntXrVJA6_J9Q==, String #=qlWFTl3cz6lzgnrQVsmJnKQ==)
2016-03-30 08:21:49.3952 INFO: HamQthManagement: Send qso completed
2016-03-30 08:21:50.9089 INFO: EqslManagement: Send qso completed
User avatar
VK7XX
Old Man
Posts: 433
Joined: 24 Jan 2013, 04:07
Location: Planet Earth on Tasmania Island
Contact:

Re: Slow logging

Post by VK7XX »

w9mdb wrote:I've found two instances of slow logging.
One was when my internet connection was down.
It appears that the QSO is not logged until it's done trying to upload to all web sites. Perhaps that's the intent but I'd be more tempted to update the database first, then update the QSO-sent statuses independently.
(boldface added by me) thats a good idea Mike. Maybe you would like to post this in the feature suggestions forum also.

see you on JT

John
VK7XX
User avatar
IW3HMH
Site Admin
Posts: 2925
Joined: 21 Jan 2013, 14:20
Location: Quarto d'Altino - Venezia (ITA)
Contact:

Re: Slow logging

Post by IW3HMH »

Sounds correct to me too that data should be persisted into database before external updated.
I've checked and the only activity made by Log4Om before saving QSO into database is a lookup on external services (hamqth/qrz/qrzcq) to find and fill all relevant informations related to the logged QSO.

Upload to external services are made after QSO has been persisted into the database.

The lookup, anyway, could create lag.
I have plans to add an internet connection check on startup, to disable all those activities when working disconnected
Daniele Pistollato - IW3HMH
w9mdb
Old Man
Posts: 434
Joined: 13 Jul 2014, 12:05

Re: Slow logging

Post by w9mdb »

The internet connection setting I think should be done periodically or perhaps before logging. Even once every 10 minutes or so to check its status.
In my case it was a situation where the internet went down while running so a startup check wouldn't catch it.
73
Mike W9MDB
Locked