Need Help debugging performance issue (SOLVED)

[smfabac]

I've searched the form posts but have not found my situation for reference. Please accept my apologies if I missed a relevant thread.

I am currently running BkTtimeSync version 1.11.3 on a Windows 10 PC to create a NTP time server for a private network unconnected to the Internet using a GPS receiver. The Windows 10 PC is a users desktop machine running multiple Putty sessions to connect to a UNIX application. The Users PC is left on 24 hours and not shut down unless the BktTimeSync is having trouble. The Windows power plan is set to "always on" and the PC does not enter sleep or suspend  modes.  The power plan on the SSD system disk is "always on"  as the SSD is not a spinning disk.

BktTimeSync.exe gets time from the GPS receiver and sets the Windows 10 PC clock. I use Meinberg NTP 4.2.8  to share the pc clock time to the network using NTP with the PC's configured IPv4 address of 192.168.10.44.

I see that BktTimeSync Version 1.12.1 is available.  But before I install the 1.12.1 version I want to run the setting I am using and the observed results by the form to see if anyone has experienced the same issue and successfully resolved it with a configuration change or software update.  The problem I describe below may be caused by a simple misunderstanding of the configuration options.

I have attached the developed settings I use for BktTimeSync:
   

The configuration has proven unreliable and I suggested to the PC user to reboot the Windows 10 PC on Friday of each week before leaving the office.

I have two issues demonstrated in the BktTimeSyncLog.txt fragments below,  BktTimeSync successfully sets the PC's clock from 00:00 to 17:59 each day (or from the time the Windows PC is rebooted during the day) and then at 18:00 experiences  "The time difference is greater than the specified maximum correction, NOT synchronized clock." This repeats on a daily basis.  Although the configuration is set to check/set the time every five minutes (and does this when successful) once BktTimeSync decides that the difference is greater then the maximum correction, it tries once every 60 seconds thereafter until the change over from 23:59 to 00:00 and then without human intervention once again sets the PC's clock.

BktTimeSyncLog.txt:

Last Sync :Monday, November 13, 2023 17:53:01 --> Local clock offset was 0.00400 seconds
Last Sync :Monday, November 13, 2023 17:58:01 --> Local clock offset was 0.00300 seconds
Last Sync :Monday, November 13, 2023 18:03:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, November 13, 2023 18:04:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, November 13, 2023 18:05:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, November 13, 2023 18:06:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
...
Last Sync :Monday, November 13, 2023 23:58:00 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, November 13, 2023 23:59:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Tuesday, November 14, 2023 00:00:00 --> Local clock offset was -0.313000 seconds
Last Sync :Tuesday, November 14, 2023 00:00:01 --> Local clock offset was -0.001000 seconds
Last Sync :Tuesday, November 14, 2023 00:05:00 --> Local clock offset was 0.018000 seconds
Last Sync :Tuesday, November 14, 2023 00:10:01 --> Local clock offset was 0.009000 seconds
...
Last Sync :Tuesday, November 14, 2023 17:50:01 --> Local clock offset was 0.009000 seconds
Last Sync :Tuesday, November 14, 2023 17:55:01 --> Local clock offset was 0.00600 seconds
Last Sync :Tuesday, November 14, 2023 18:00:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Tuesday, November 14, 2023 18:01:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Tuesday, November 14, 2023 18:02:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Tuesday, November 14, 2023 18:03:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
...
Last Sync :Tuesday, November 14, 2023 23:58:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Tuesday, November 14, 2023 23:59:00 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Wednesday, November 15, 2023 00:00:01 --> Local clock offset was -0.22000 seconds
Last Sync :Wednesday, November 15, 2023 00:00:01 --> Local clock offset was 0.05500 seconds
Last Sync :Wednesday, November 15, 2023 00:05:01 --> Local clock offset was 0.07700 seconds
Last Sync :Wednesday, November 15, 2023 00:10:01 --> Local clock offset was -0.00000 seconds
...
Last Sync :Wednesday, November 15, 2023 10:58:01 --> Local clock offset was -0.00000 seconds
Last Sync :Wednesday, November 15, 2023 11:03:00 --> Local clock offset was 0.08800 seconds
Last Sync :Wednesday, November 15, 2023 11:08:01 --> Local clock offset was -0.02000 seconds <-- Last Log entry as found on 11/28

Final question: Does BktTimeSync have any setting to automatically limit the size of the BktTimeSyncLog.txt file?  The 1.11.3 version I installed in March 2023 created a large log file discovered when I responded to the Client's office on 11/28 (copied it to the UNIX server as it was too large to open with notepad or word pad):

-rwxr--r-- 1 root  sys  1268745653 Nov 15 11:08 BktTimeSyncLog.txt
# wc -l BktTimeSyncLog.txt
17,622,312 BktTimeSyncLog.txt  (comma's added for readability)

The BktTimeSync control panel shown above would not respond to "Sync Now" button click  when I tried to use it on 11/28 before shutting down BktTimeSync, changing the log file and rebooting the Windows 10  PC  (log file too large?).

The last displayed line was in the BktTimeSync control panel was:
Last Sync: Wednesday, November 15,  2023 11:08:01
Time was successfully synchronized using GPS receiver
local clock offset was -0.002000 seconds

Any suggestions on how to resolve the problems identified above or recommended changes to the sync check interval (10 minutes, 30 minutes 60 minutes?) is  eagerly anticipated.

TIA

[iz2bkt]

Hi,

a 5-minute interval is really too frequent and necessary only if you have a computer with clock issues; 60 minutes is more than sufficient for most computers. If you need atomic-level precision synchronization, you should use a low-latency internet connection.

Very strange is the issue that you're not synchronizing between 18:00 and 24:00. It seems like your GPS is receiving incorrect data during this time period. To verify, you should enable the diagnostic log and attach it to the post.

The maximum synchronization log limit cannot be configured, but you can only disable it or set up a scheduled Windows operation to clear it at your preferred times.

[smfabac]

Hi,

a 5-minute interval is really too frequent and necessary only if you have a computer with clock issues; 60 minutes is more than sufficient for most computers. If you need atomic-level precision synchronization, you should use a low-latency internet connection.

Very strange is the issue that you're not synchronizing between 18:00 and 24:00. It seems like your GPS is receiving incorrect data during this time period. To verify, you should enable the diagnostic log and attach it to the post.

The maximum synchronization log limit cannot be configured, but you can only disable it or set up a scheduled Windows operation to clear it at your preferred times.

I'll switch to 60 minutes as you suggest.

The network is isolated from the Internet for a reason ergo the need for GPS time standard for the isolated network.

I'll enable diagnostic log and post its results.

Please offer an explanation as to why the interval switches from the specified every 5 minutest when BktTimeSync is successful in setting the PC clock to once each minute  when the "The time difference is greater than the specified maximum correction, NOT synchronized clock" error occurs.  That seems to be a programming design issue.

I appreciate that the BktTimeSync is developed and maintained to support amateur Radio field use to sync the users laptop clock. I am not an amateur  radio operator and don't expect that a users laptop will be on for periods greater then 24 to 48 hours in a stretch and so no one may have witnessed the 18:00 to 24:00 event on an un-manned laptop.

And last, please check the settings in the image I posted and comment if any of my settings seem unusual or counter productive.

Steve

[iz2bkt]

The configuration is OK. 
The issue at 18:00 could be attributed to a bug in the calculation of the difference between UTC and local time. When you can, please send me the diagnostic log from 17:58 to 18:10. 
While I debug the program, you can try setting the Max corr. to 24 hours, or set it to 0 to disable the check

[smfabac]

The configuration is OK. 
The issue at 18:00 could be attributed to a bug in the calculation of the difference between UTC and local time. When you can, please send me the diagnostic log from 17:58 to 18:10. 
While I debug the program, you can try setting the Max corr. to 24 hours, or set it to 0 to disable the check

I've not changed any settings in the BktTimeSync control panel beyond enabling the diagnostic log so as not to introduce any changes to the current configuration that may affect the data logged to the diagnostic log.



LogDiag.txt:

Mon Dec  4 17:50:01 2023 --> Sync GPS OK, next to :Mon Dec  4 17:55:00 2023Mon Dec  4 17:55:00 2023 --> Sync start P1
Mon Dec  4 17:55:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 17:55:01 2023 --> GPS rx str: $GPRMC,235501.00,A,3859.21059,N,09421.10166,W,0.169,,041223,,,D*69

Mon Dec  4 17:55:01 2023 --> Sync GPS OK, next to :Mon Dec  4 18:00:00 2023Mon Dec  4 18:00:00 2023 --> Sync start P1
Mon Dec  4 18:00:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:00:01 2023 --> GPS rx str: $GPRMC,000001.00,A,3859.21017,N,09421.10005,W,0.014,,051223,,,D*6C

Mon Dec  4 18:00:01 2023 -->
Mon Dec  4 18:01:00 2023 --> Sync start P1
Mon Dec  4 18:01:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:01:01 2023 --> GPS rx str: $GPRMC,000101.00,A,3859.21142,N,09421.10258,W,0.260,,051223,,,D*67

Mon Dec  4 18:01:01 2023 -->
Mon Dec  4 18:02:00 2023 --> Sync start P1
Mon Dec  4 18:02:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:02:01 2023 --> GPS rx str: $GPRMC,000201.00,A,3859.21350,N,09421.09472,W,0.383,,051223,,,D*6F

Mon Dec  4 18:02:01 2023 -->
Mon Dec  4 18:03:00 2023 --> Sync start P1
Mon Dec  4 18:03:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:03:01 2023 --> GPS rx str: $GPRMC,000301.00,A,3859.21235,N,09421.10212,W,0.121,,051223,,,D*6E

Mon Dec  4 18:03:01 2023 -->
Mon Dec  4 18:04:00 2023 --> Sync start P1
Mon Dec  4 18:04:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:04:01 2023 --> GPS rx str: $GPRMC,000401.00,A,3859.21404,N,09421.09421,W,0.355,,051223,,,D*62

Mon Dec  4 18:04:01 2023 -->
Mon Dec  4 18:05:00 2023 --> Sync start P1
Mon Dec  4 18:05:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:05:01 2023 --> GPS rx str: $GPRMC,000501.00,A,3859.21296,N,09421.10011,W,0.388,,051223,,,D*61

Mon Dec  4 18:05:01 2023 -->
Mon Dec  4 18:06:00 2023 --> Sync start P1
Mon Dec  4 18:06:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:06:01 2023 --> GPS rx str: $GPRMC,000601.00,A,3859.21121,N,09421.10085,W,0.298,,051223,,,D*60

Mon Dec  4 18:06:01 2023 -->
Mon Dec  4 18:07:00 2023 --> Sync start P1
Mon Dec  4 18:07:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:07:01 2023 --> GPS rx str: $GPRMC,000701.00,A,3859.21289,N,09421.10542,W,0.062,,051223,,,D*69

Mon Dec  4 18:07:01 2023 -->
Mon Dec  4 18:08:00 2023 --> Sync start P1
Mon Dec  4 18:08:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:08:01 2023 --> GPS rx str: $GPRMC,000801.00,A,3859.21047,N,09421.10445,W,0.074,,051223,,,D*67

Mon Dec  4 18:08:01 2023 -->
Mon Dec  4 18:09:00 2023 --> Sync start P1
Mon Dec  4 18:09:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:09:01 2023 --> GPS rx str: $GPRMC,000901.00,A,3859.20913,N,09421.11154,W,1.050,,051223,,,D*6C

Mon Dec  4 18:09:01 2023 -->
Mon Dec  4 18:10:00 2023 --> Sync start P1
Mon Dec  4 18:10:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:10:01 2023 --> GPS rx str: $GPRMC,001001.00,A,3859.20999,N,09421.10246,W,0.250,,051223,,,D*64

Mon Dec  4 18:10:01 2023 -->
Mon Dec  4 18:11:00 2023 --> Sync start P1
Mon Dec  4 18:11:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 18:11:01 2023 --> GPS rx str: $GPRMC,001101.00,A,3859.20887,N,09421.10149,W,0.055,,051223,,,D*60

...

Mon Dec  4 23:57:01 2023 -->
Mon Dec  4 23:58:00 2023 --> Sync start P1
Mon Dec  4 23:58:00 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 23:58:00 2023 --> GPS rx str: $GPRMC,055800.00,A,3859.20620,N,09421.09837,W,0.139,,051223,,,D*69

Mon Dec  4 23:58:00 2023 -->
Mon Dec  4 23:59:00 2023 --> Sync start P1
Mon Dec  4 23:59:01 2023 --> GPS rx str P1 - BuffLen=68
Mon Dec  4 23:59:01 2023 --> GPS rx str: $GPRMC,055901.00,A,3859.21209,N,09421.10070,W,0.138,,051223,,,D*65

Mon Dec  4 23:59:01 2023 -->
Tue Dec  5 00:00:00 2023 --> Sync start P1
Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPRMC,060001.00,A,3859.21314,N,09421.10348,W,0.202,,051223,,,D*65

Tue Dec  5 00:00:01 2023 -->
Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=35
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPVTG,,T,,M,0.202,N,0.374,K,D*26

Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=80
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPGGA,060001.00,3859.21314,N,09421.10348,W,2,09,0.96,291.9,M,-29.1,M,,0000*6A

Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=60
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPGSA,A,3,12,19,46,25,06,09,11,05,29,,,,1.79,0.96,1.51*08

Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPGSV,4,1,13,04,00,032,,05,33,193,24,06,40,050,28,09,10,062,19*7A

Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPGSV,4,2,13,11,71,014,42,12,64,248,17,17,02,111,,19,22,103,24*78

Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPGSV,4,3,13,20,69,161,,25,39,301,28,29,11,299,29,46,32,228,29*70

Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=29
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPGSV,4,4,13,48,35,223,*42

Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=52
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPGLL,3859.21314,N,09421.10348,W,060001.00,A,D*7B

Tue Dec  5 00:00:01 2023 --> Sync start P1
Tue Dec  5 00:00:01 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:00:01 2023 --> GPS rx str: $GPRMC,060002.00,A,3859.21305,N,09421.10345,W,0.376,,051223,,,D*69

Tue Dec  5 00:00:02 2023 --> Sync GPS OK, next to :Tue Dec  5 00:05:00 2023Tue Dec  5 00:05:00 2023 --> Sync start P1
Tue Dec  5 00:05:00 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:05:00 2023 --> GPS rx str: $GPRMC,060501.00,A,3859.21174,N,09421.10012,W,0.080,,051223,,,D*60

Tue Dec  5 00:05:01 2023 --> Sync GPS OK, next to :Tue Dec  5 00:10:00 2023Tue Dec  5 00:10:00 2023 --> Sync start P1
Tue Dec  5 00:10:01 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:10:01 2023 --> GPS rx str: $GPRMC,061001.00,A,3859.21213,N,09421.10104,W,0.167,,051223,,,D*68

Tue Dec  5 00:10:01 2023 --> Sync GPS OK, next to :Tue Dec  5 00:15:00 2023Tue Dec  5 00:15:00 2023 --> Sync start P1
Tue Dec  5 00:15:01 2023 --> GPS rx str P1 - BuffLen=68
Tue Dec  5 00:15:01 2023 --> GPS rx str: $GPRMC,061501.00,A,3859.21110,N,09421.10078,W,0.236,,051223,,,D*60

BktTimeSynclog.txt:

Last Sync :Monday, December 04, 2023 17:50:01 --> Local clock offset was 0.001000 seconds
Last Sync :Monday, December 04, 2023 17:55:01 --> Local clock offset was -0.002000 seconds
Last Sync :Monday, December 04, 2023 18:00:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:01:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:02:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:03:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:04:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:05:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:06:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:07:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:08:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:09:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 18:10:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
...
Last Sync :Monday, December 04, 2023 23:58:00 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Monday, December 04, 2023 23:59:01 --> The time difference is greater than the specified maximum correction, NOT synchronized clock
Last Sync :Tuesday, December 05, 2023 00:00:01 --> Local clock offset was -0.323000 seconds
Last Sync :Tuesday, December 05, 2023 00:00:01 --> Local clock offset was 0.021000 seconds
Last Sync :Tuesday, December 05, 2023 00:05:00 --> Local clock offset was 0.016000 seconds
Last Sync :Tuesday, December 05, 2023 00:10:01 --> Local clock offset was -0.005000 seconds





Steve

[iz2bkt]

I've not changed any settings in the BktTimeSync control panel beyond enabling the diagnostic log so as not to introduce any changes to the current configuration that may affect the data logged to the diagnostic log.



LogDiag.txt:

Thanks Steve

[iz2bkt]

Hello Steve, 
the issue has been resolved in version 1.13.0. 
I also recommend unchecking the box [Do not check the date].

[smfabac]

Hello Steve, 
the issue has been resolved in version 1.13.0. 
I also recommend unchecking the box [Do not check the date].

I have downloaded 1.13.0 and installed it. The installation/upgrade went smoother then I'd hoped. I simply disabled the log check marks and exited the 1.11.3 version then ran the 1.13.0 install file with run as administrator. The 1.13.0 version finished the install and started up. I re-enabled the log check marks,  left the interval at five minutes, set max correction to 0 and unchecked the Do not check the date. I rebooted The Windows 10 PC to make sure that BktTimesync starts automatically and it did. I'll check the logs again tomorrow to see the result and switch to every 60 minutes.



   


Thank you for a great program!

Steve

[smfabac]

Hello Steve, 
the issue has been resolved in version 1.13.0. 
I also recommend unchecking the box [Do not check the date].

Looks good with 1.13.0:
Last Sync :Wednesday, December 06, 2023 17:51:01 --> Local clock offset was 0.010000 seconds
Last Sync :Wednesday, December 06, 2023 17:56:01 --> Local clock offset was 0.006000 seconds
Last Sync :Wednesday, December 06, 2023 18:01:01 --> Local clock offset was 0.000000 seconds
Last Sync :Wednesday, December 06, 2023 18:06:01 --> Local clock offset was -0.003000 seconds
Last Sync :Wednesday, December 06, 2023 18:11:01 --> Local clock offset was -0.007000 seconds
Last Sync :Wednesday, December 06, 2023 18:16:01 --> Local clock offset was 0.006000 seconds
Last Sync :Wednesday, December 06, 2023 18:21:01 --> Local clock offset was -0.002000 seconds
...
Last Sync :Wednesday, December 06, 2023 23:51:01 --> Local clock offset was 0.000000 seconds
Last Sync :Wednesday, December 06, 2023 23:56:01 --> Local clock offset was 0.007000 seconds
Last Sync :Thursday, December 07, 2023 00:01:01 --> Local clock offset was -0.004000 seconds
Last Sync :Thursday, December 07, 2023 00:06:00 --> Local clock offset was 0.003000 seconds
Last Sync :Thursday, December 07, 2023 00:11:01 --> Local clock offset was 0.008000 seconds

I've set 60 minutes as you suggested, left BktTimeSynclog check box ticked, unchecked "Diagnostic Log" and cleared it.

Thanks again.
Steve

[iz2bkt]

Looks good with 1.13.0:

I've set 60 minutes as you suggested, left BktTimeSynclog check box ticked, unchecked "Diagnostic Log" and cleared it.

Thanks again.
Steve

Hi Steve,
thank you for the tests.