Back at work now, so can check on things properly. It's been logging fine and producing the graphs, I had only one isrunning file from Saturday at 12:01
It seems the midday current stats took a long time to complete, thus keeping HG612_Stats open.
Looking at the current stats error log I can see that it was graph6 that took over a minute, this looks very similar to the problem I've been having on my server. No other programs were open, no virus scans either.
Looking through the other Graph6 log entries, it normally take 7 - 10 seconds to complete, and it is only this one entry which takes a lot longer, though there are not many entries - the first entry is 14-10-2013
Snippets from all three logs are below.
19/10/2013 11:59:02.562 - End of HG612_stats.exe program, EXIT error code = 0
19/10/2013 11:59:02.593 - End of HG612_stats.exe program, closing ERROR.LOG
19/10/2013 12:01:01.031 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 0 seconds
19/10/2013 12:01:01.140 - From IsRunningVB.exe, HG612_current_stats.exe is running 1 instances.
19/10/2013 12:01:19.093 - HG612_current_stats.exe has now completed, so HG612_stats.exe is resuming.
19/10/2013 12:01:19.093 - Temp File ONGOING-ISRUNNING-120119-093.TXT was created
19/10/2013 12:01:19.281 - *** Now in exit_2_instances as there are 2 instances of HG612_stats.exe running. Status = 1.
19/10/2013 12:01:19.312 - *** In exit_2_instances - Closing ERROR.LOG. Status = 1.
19/10/2013 12:00:00.859 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 0 seconds
19/10/2013 12:00:00.968 - HG612_current_stats.exe was NOT running
19/10/2013 12:00:00.968 - Temp File ONGOING-ISRUNNING-120000-968.TXT was created
19/10/2013 12:00:01.234 - malloc() O.K.
19/10/2013 12:00:01.234 - Initializing Winsock
19/10/2013 12:00:01.234 - WSAStartup() SUCCESSFUL!!!
19/10/2013 12:00:01.234 - Starting getaddrinfo()
19/10/2013 12:00:01.234 - getaddrinfo() O.K.
19/10/2013 12:00:01.234 - Starting socket()
19/10/2013 12:00:01.234 - socket() O.K.
19/10/2013 12:00:01.234 - Starting connect()
19/10/2013 12:00:01.250 - connect() O.K.
19/10/2013 12:00:02.078 - About to reply(xdslcmd info --stats)
19/10/2013 12:00:02.078 - reply(xdslcmd info --stats) O.K.
19/10/2013 12:00:02.281 - get_data() O.K.
19/10/2013 12:00:02.281 - About to determine the xDSL mode
19/10/2013 12:00:02.281 - Modem in use = HG622
19/10/2013 12:00:02.281 - About to parse_stats()
19/10/2013 12:00:02.281 - parse_stats completed
19/10/2013 12:00:02.281 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
19/10/2013 12:00:02.281 - reply(xdslcmd info --pbParams) O.K.
19/10/2013 12:00:02.484 - get_data() O.K.
19/10/2013 12:00:02.484 - About to parse_pbParams_data()
19/10/2013 12:00:02.484 - parse_pbParams_data() completed
19/10/2013 12:00:02.484 - About to exit Busybox
19/10/2013 12:00:02.484 - Busybox exited
19/10/2013 12:00:02.750 - About to exit ATP
19/10/2013 12:00:02.750 - ATP exited
19/10/2013 12:00:02.750 - Logged out of modem O.K.
19/10/2013 12:00:02.781 - Current data harvested at 1382180400 seconds past the epoch
19/10/2013 12:00:02.781 - About to get_log_data()
19/10/2013 12:00:02.781 - Previous log stats date/time = 1382180340 seconds past the epoch
19/10/2013 12:00:02.781 - time_difference = 1 minutes
19/10/2013 12:00:02.781 - About to calc_ES_delta()
19/10/2013 12:00:02.781 - About to calc_RSCorr_delta()
19/10/2013 12:00:02.781 - ds_RSCorr_THIS_PERIOD = 595053
19/10/2013 12:00:02.781 - us_RSCorr_THIS_PERIOD = 0
19/10/2013 12:00:02.781 - About to calc_RSUnCorr_delta()
19/10/2013 12:00:02.781 - About to calc_RS_delta()
19/10/2013 12:00:02.781 - About to calc_OHF_delta()
19/10/2013 12:00:02.781 - About to calc_OHFErr_delta()
19/10/2013 12:00:02.781 - About to calc_HEC_delta()
19/10/2013 12:00:02.781 - About to calc_CRC_delta()
19/10/2013 12:00:02.781 - About to calc_FEC_delta()
19/10/2013 12:00:02.781 - About to calc_Bitswap_delta()
19/10/2013 12:00:02.781 - Appending data to C:\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log
19/10/2013 12:00:02.781 - Closing MSLOGFILE.log
19/10/2013 12:00:02.781 - END of 1 minute sampling
19/10/2013 12:00:02.812 - About to close(sockfd)
19/10/2013 12:00:02.812 - About to freeadddrinfo(res)
19/10/2013 12:00:02.812 - About to WSACleanup()
19/10/2013 12:00:02.843 - About to free(txbuf)
19/10/2013 12:00:02.906 - About to free(rxbuf)
19/10/2013 12:00:03.000 - Current sync speeds are DS 33690 kbps US 6076 kbps, AS = 373909
19/10/2013 12:00:03.000 - Previous sync speeds were DS 33690 kbps US 6076 kbps, AS = 373849
19/10/2013 12:00:03.031 - Sync speeds have NOT changed since the previous data harvest
19/10/2013 12:00:03.062 - ONGOING-ISRUNNING-120000-968.TXT DELETED
*********************************************************************************************************************
19/10/2013 12:00:03.062 - Scheduled Current_Stats logging is switched ON via the ini file
19/10/2013 12:00:03.062 - Current_Stats_Datum = 00
19/10/2013 12:00:03.062 - Current_Stats_Interval = 12
19/10/2013 12:00:03.093 - (Time in Hours - Datum) Modulus Interval i.e. (12 - 0) % 12 = 0
19/10/2013 12:00:03.093 - (Time in Minutes) = 00
19/10/2013 12:00:03.109 - RUN HG612_current_stats.exe
*********************************************************************************************************************
19/10/2013 12:01:28.609 - Scheduled Daily_Graphing is switched ON via the ini file
19/10/2013 12:01:28.609 - Daily_Graphing_hour = 23
19/10/2013 12:01:28.609 - Daily_Graphing_minutes = 58
19/10/2013 12:01:28.609 - Current Time is Hours 12, Minutes 01
19/10/2013 12:01:28.625 - scheduled Daily_Graphing is NOT due yet
*********************************************************************************************************************
19/10/2013 12:01:28.625 - End of HG612_stats.exe program, EXIT error code = 0
19/10/2013 12:01:28.656 - End of HG612_stats.exe program, closing ERROR.LOG
19/10/2013 12:02:00.375 - [ IN HG612_stats.EXE ] - Start of 1 minute sampling - delayed by user setting of 0 seconds
19/10/2013 12:02:00.468 - HG612_current_stats.exe was NOT running
19/10/2013 12:02:00.468 - Temp File ONGOING-ISRUNNING-120200-468.TXT was created
19/10/2013 12:02:00.625 - malloc() O.K.
19/10/2013 12:02:00.625 - Initializing Winsock
19/10/2013 12:02:00.625 - WSAStartup() SUCCESSFUL!!!
19/10/2013 12:02:00.625 - Starting getaddrinfo()
19/10/2013 12:02:00.625 - getaddrinfo() O.K.
19/10/2013 12:02:00.625 - Starting socket()
19/10/2013 12:02:00.640 - socket() O.K.
19/10/2013 12:02:00.640 - Starting connect()
19/10/2013 12:02:00.640 - connect() O.K.
19/10/2013 12:02:01.375 - About to reply(xdslcmd info --stats)
19/10/2013 12:02:01.375 - reply(xdslcmd info --stats) O.K.
19/10/2013 12:02:01.562 - get_data() O.K.
19/10/2013 12:02:01.562 - About to determine the xDSL mode
19/10/2013 12:02:01.562 - Modem in use = HG622
19/10/2013 12:02:01.562 - About to parse_stats()
19/10/2013 12:02:01.562 - parse_stats completed
19/10/2013 12:02:01.562 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
19/10/2013 12:02:01.562 - reply(xdslcmd info --pbParams) O.K.
19/10/2013 12:02:01.765 - get_data() O.K.
19/10/2013 12:02:01.765 - About to parse_pbParams_data()
19/10/2013 12:02:01.765 - parse_pbParams_data() completed
19/10/2013 12:02:01.765 - About to exit Busybox
19/10/2013 12:02:01.765 - Busybox exited
19/10/2013 12:02:01.953 - About to exit ATP
19/10/2013 12:02:01.953 - ATP exited
19/10/2013 12:02:01.953 - Logged out of modem O.K.
19/10/2013 12:02:01.968 - Current data harvested at 1382180520 seconds past the epoch
19/10/2013 12:02:01.968 - About to get_log_data()
19/10/2013 12:02:01.968 - Previous log stats date/time = 1382180400 seconds past the epoch
19/10/2013 12:02:01.968 - time_difference = 2 minutes
19/10/2013 12:02:01.968 - WARNING!!! time_difference is more than 1 minute - Ignoring previous logged time
19/10/2013 12:02:01.968 - About to calc_ES_delta()
19/10/2013 12:02:01.968 - About to calc_RSCorr_delta()
19/10/2013 12:02:01.968 - ds_RSCorr_THIS_PERIOD = 0
19/10/2013 12:02:01.968 - us_RSCorr_THIS_PERIOD = 0
19/10/2013 12:02:01.968 - About to calc_RSUnCorr_delta()
19/10/2013 12:02:01.968 - About to calc_RS_delta()
19/10/2013 12:02:01.968 - About to calc_OHF_delta()
19/10/2013 12:02:01.968 - About to calc_OHFErr_delta()
19/10/2013 12:02:01.968 - About to calc_HEC_delta()
19/10/2013 12:02:01.968 - About to calc_CRC_delta()
19/10/2013 12:02:01.968 - About to calc_FEC_delta()
19/10/2013 12:02:01.968 - About to calc_Bitswap_delta()
19/10/2013 12:02:01.968 - Appending data to C:\HG612_Modem_Stats\Ongoing_Stats\modem_stats.log
19/10/2013 12:02:01.968 - Closing MSLOGFILE.log
19/10/2013 12:02:01.968 - END of 1 minute sampling
19/10/2013 12:02:02.000 - About to close(sockfd)
19/10/2013 12:02:02.000 - About to freeadddrinfo(res)
19/10/2013 12:02:02.000 - About to WSACleanup()
19/10/2013 12:02:02.031 - About to free(txbuf)
19/10/2013 12:02:02.078 - About to free(rxbuf)
19/10/2013 12:02:02.156 - Current sync speeds are DS 33690 kbps US 6076 kbps, AS = 374029
19/10/2013 12:02:02.156 - Previous sync speeds were DS 33690 kbps US 6076 kbps, AS = 373909
19/10/2013 12:02:02.187 - Sync speeds have NOT changed since the previous data harvest
19/10/2013 12:02:02.203 - ONGOING-ISRUNNING-120200-468.TXT DELETED
*********************************************************************************************************************
19/10/2013 12:02:02.203 - Scheduled Current_Stats logging is switched ON via the ini file
19/10/2013 12:02:02.203 - Current_Stats_Datum = 00
19/10/2013 12:02:02.203 - Current_Stats_Interval = 12
19/10/2013 12:02:02.234 - (Time in Hours - Datum) Modulus Interval i.e. (12 - 0) % 12 = 0
19/10/2013 12:02:02.234 - (Time in Minutes) = 02
19/10/2013 12:02:02.234 - Modulus & minutes *BOTH* have to be zero, so scheduled snapshot logging is NOT due yet
*********************************************************************************************************************
19/10/2013 12:02:02.281 - Scheduled Daily_Graphing is switched ON via the ini file
19/10/2013 12:02:02.281 - Daily_Graphing_hour = 23
19/10/2013 12:02:02.281 - Daily_Graphing_minutes = 58
19/10/2013 12:02:02.281 - Current Time is Hours 12, Minutes 02
19/10/2013 12:02:02.312 - scheduled Daily_Graphing is NOT due yet
*********************************************************************************************************************
19/10/2013 12:02:02.312 - End of HG612_stats.exe program, EXIT error code = 0
19/10/2013 12:02:02.343 - End of HG612_stats.exe program, closing ERROR.LOG
19/10/2013 12:00:05.953 - Start of Current Stats Harvesting
19/10/2013 12:00:06.062 - From IsRunningVB.exe, HG612_stats.exe was running 1 instances.
19/10/2013 12:00:06.109 - The program full path is C:\HG612_Modem_Stats\Scripts\HG612_current_stats.exe
19/10/2013 12:00:06.109 - The program directory path is C:\HG612_Modem_Stats\Scripts
19/10/2013 12:00:06.109 - DEBUG_COMMENTS = YES
19/10/2013 12:00:06.109 - Temp File CURRENT-ISRUNNING-120006-062 was created
19/10/2013 12:00:06.109 - Before checking for RESYNC or SCHEDULED events, Delay_snapshot_data_harvest_seconds = 0
19/10/2013 12:00:06.109 - A SCHEDULED run was detected via HG612_stats.exe. Initial Pause setting from ini file = NO
19/10/2013 12:00:06.109 - Pause setting for this instance only has been forced to be NO
19/10/2013 12:00:06.109 - After checking for RESYNC or SCHEDULED events, Delay_snapshot_data_harvest_seconds = 0
19/10/2013 12:00:06.109 - malloc() O.K.
19/10/2013 12:00:06.109 - Initializing Winsock
19/10/2013 12:00:06.109 - WSAStartup() SUCCESSFUL!!!
19/10/2013 12:00:06.109 - Starting getaddrinfo()
19/10/2013 12:00:06.109 - getaddrinfo() O.K.
19/10/2013 12:00:06.109 - Starting socket()
19/10/2013 12:00:06.125 - socket() O.K.
19/10/2013 12:00:06.125 - Starting connect()
19/10/2013 12:00:06.125 - connect() O.K.
19/10/2013 12:00:07.078 - About to reply(xdslcmd info --stats)
19/10/2013 12:00:07.078 - reply(xdslcmd info --stats) O.K.
19/10/2013 12:00:07.281 - get_data() for --stats O.K.
19/10/2013 12:00:07.281 - Modem in use = HG622
19/10/2013 12:00:07.281 - About to determine the xDSL mode
19/10/2013 12:00:07.281 - About to parse_stats()
19/10/2013 12:00:07.281 - parse_stats completed
19/10/2013 12:00:07.281 - VDSL2 mode detected so about to reply(xdslcmd info --pbParams)
19/10/2013 12:00:07.281 - reply(xdslcmd info --pbParams) O.K.
19/10/2013 12:00:07.578 - get_data() for --pbParams O.K.
19/10/2013 12:00:07.578 - About to parse_pbParams_data()
19/10/2013 12:00:07.578 - parse_pbParams_data() completed
19/10/2013 12:00:07.578 - reply(xdslcmd info --Bits) O.K.
19/10/2013 12:00:07.875 - get_data() for --Bits O.K.
19/10/2013 12:00:07.890 - reply(xdslcmd info --linediag) O.K.
19/10/2013 12:00:09.593 - get_data() for --linediag O.K.
19/10/2013 12:00:09.593 - reply(xdslcmd info --SNR) O.K.
19/10/2013 12:00:10.093 - get_data() for --SNR O.K.
19/10/2013 12:00:10.093 - reply(xdslcmd info --QLN) O.K.
19/10/2013 12:00:10.593 - get_data() for --QLN O.K.
19/10/2013 12:00:10.593 - reply(xdslcmd info --Hlog) O.K.
19/10/2013 12:00:11.093 - get_data() for --Hlog O.K.
19/10/2013 12:00:11.093 - reply(xdslcmd info --show) O.K.
19/10/2013 12:00:11.296 - get_data() for --show O.K.
19/10/2013 12:00:11.296 - About to exit Busybox
19/10/2013 12:00:11.296 - Busybox exited
19/10/2013 12:00:11.500 - About to exit ATP
19/10/2013 12:00:11.500 - ATP exited
19/10/2013 12:00:11.500 - About to close (sockfd)
19/10/2013 12:00:11.500 - About to WSACleanup()
19/10/2013 12:00:11.500 - About to free(txbuf)
19/10/2013 12:00:11.500 - About to free(rxbuf)
19/10/2013 12:00:11.500 - CURRENT-ISRUNNING-120006-062 DELETED
19/10/2013 12:00:11.500 - Auto_graph_Snapshot_data = YES, now graphing snapshot stats
19/10/2013 12:00:11.500 - Successfully changed directory to C:\HG612_Modem_Stats\Current_Stats\Current_Stats_20131019-1200-SCHEDULED
19/10/2013 12:00:11.500 - Pause_after_obtaining_snapshot_data = NO
19/10/2013 12:00:11.500 - GRAPHING_COMMAND = ""C:\HG612_Modem_Stats\Scripts\GRAPH6.exe" "C:\HG612_Modem_Stats\Current_Stats\Current_Stats_20131019-1200-SCHEDULED\Plink_20131019-1200.log""
19/10/2013 12:01:28.531 - Snapshot graphs should now have been plotted
19/10/2013 12:01:28.531 - End of HG612_current_stats.exe program, closing ERROR.LOG
19/10/2013 12:00:13.234 - Start of GRAPH6.exe
19/10/2013 12:00:13.234 - The program full path is C:\HG612_Modem_Stats\Scripts\GRAPH6.exe
19/10/2013 12:00:13.234 - The program directory path is C:\HG612_Modem_Stats\Scripts
19/10/2013 12:00:13.234 - DEBUG_COMMENTS = YES
19/10/2013 12:00:13.234 - Using C:\HG612_Modem_Stats\Current_Stats\Current_Stats_20131019-1200-SCHEDULED\Plink_20131019-1200.log
19/10/2013 12:00:13.234 - About to change folder to the one with the log file stored in it
19/10/2013 12:00:13.234 - Successfully changed directory to C:\HG612_Modem_Stats\Current_Stats\Current_Stats_20131019-1200-SCHEDULED
19/10/2013 12:01:28.515 - The Plink log being used came from a RESYNC or SCHEDULED event, so any pauses were disabled
19/10/2013 12:01:28.515 - End of GRAPH6.exe program, closing ERROR.LOG