Slowdown over time

[chantling]

I've got a problem with one of my scripts slowing down over a period of several hours - since it's fairly time-dependant, it crashes and burns (from a functional standpoint) eventually. I was tearing my hair out, thinking at first that it was due to pixelgetcolor() leaking memory or something, although the script's memory usage appears to be holding steady over time. Then I thought maybe it was the sleep() commands, then I was trying to figure out if I was getting handles and not releasing them...

Then I actually looked at my logfile (imagine that). I've got a log window (list control) that gets updated constantly, and every x lines I flush the log cache to a file. At the end of each cycle of my script, I write a few status lines. Nothing gets done at that time other than the log update, and unless my log cache is already full, it doesn't even get written to file at that point, so it should be very fast, certainly less than a second. And it is, on the first cycle. However, now that I've been looking, I see that the time to write the lines steadily increases over time - less than a second on the first cycle, about a second per line around cycle 7 or 8, 5 seconds per line on cycle 30 or so... Here's an example excerpt from one of my logfiles (just listing the fast bit here):

2009/03/01 - 10:36:42 - ==========================

2009/03/01 - 10:36:42 - Cycles Complete: 1

2009/03/01 - 10:36:42 - Last Cycle Time: 08:19

2009/03/01 - 10:36:42 - Avg. Cycle Time: 08:19

2009/03/01 - 10:36:42 - Max Cycle Time: 08:19

2009/03/01 - 10:36:42 - Min Cycle Time: 08:19

2009/03/01 - 10:36:42 - Total Time: 08:19

2009/03/01 - 10:36:42 - ==========================

...

...

2009/03/01 - 16:01:12 - ==========================

2009/03/01 - 16:01:17 - Cycles Complete: 32

2009/03/01 - 16:01:22 - Last Cycle Time: 21:58

2009/03/01 - 16:01:26 - Avg. Cycle Time: 10:24

2009/03/01 - 16:01:31 - Max Cycle Time: 21:58

2009/03/01 - 16:01:36 - Min Cycle Time: 08:19

2009/03/01 - 16:01:41 - Total Time: 05:32:50

2009/03/01 - 16:01:46 - ==========================

Here's the log function:

;----------------------
; DoLogStatus( $LogString )
; returns: 
; purpose: Writes status to log file temp variable,
;           calls FlushLog if needed
;----------------------
Func DoLogStatus( $LogString )
    Local $LogIndex = $LogTemp[0] + 1, $TempList
    Local $LogArray = SplitStringArray( $LogString, "|" )
    For $i = 1 to ( Ubound( $LogArray ) - 1 ) Step 1
        $Time = StringFormat("%02d:%02d:%02d", @HOUR, @MIN, @SEC)
        $Date = StringFormat("%02d/%02d/%02d", @Year, @Mon, @MDay)
        $TempList = $Date & " - " & $Time & " - " & $LogArray[$i]
        $LogTemp[$LogIndex] = $TempList & @CRLF
    ;_GUICtrlListBox_BeginUpdate( $Log1 )
        GuiCtrlSetData( $Log1, $TempList, $TempList )
    ;_GUICtrlListBox_AddString( $Log1, $TempList )
        _GUICtrlListBox_UpdateHScroll($Log1)
        _GUICtrlListBox_UpdateHScroll($Log1)
    ;_GUICtrlListBox_EndUpdate($Log1)
        $LogTemp[0] = $LogIndex
        $LogIndex = $LogIndex + 1
    Next
    If $LogIndex >= 20 Then
        FlushLog("Log")
    EndIf
    return
EndFunc

The Logfile function:

;----------------------
; DoLogStatus( $LogString )
; returns: 
; purpose: Writes status to log file temp variable,
;           calls FlushLog if needed
;----------------------
Func DoLogStatus( $LogString )
    Local $LogIndex = $LogTemp[0] + 1, $TempList
    Local $LogArray = SplitStringArray( $LogString, "|" )
    For $i = 1 to ( Ubound( $LogArray ) - 1 ) Step 1
        $Time = StringFormat("%02d:%02d:%02d", @HOUR, @MIN, @SEC)
        $Date = StringFormat("%02d/%02d/%02d", @Year, @Mon, @MDay)
        $TempList = $Date & " - " & $Time & " - " & $LogArray[$i]
        $LogTemp[$LogIndex] = $TempList & @CRLF
        GuiCtrlSetData( $Log1, $TempList, $TempList )
        _GUICtrlListBox_UpdateHScroll($Log1)
        _GUICtrlListBox_UpdateHScroll($Log1)
        $LogTemp[0] = $LogIndex
        $LogIndex = $LogIndex + 1
    Next
    If $LogIndex >= 20 Then
        FlushLog("Log")
    EndIf
    return
EndFunc

The portion of code that calls it (although the log func is called constantly throughout my script, leading to the huge slowdown overall):

Local $LogStringTemp = "==========================" & "|"
        $LogStringTemp = $LogStringTemp & "Cycles Complete: " & $Cycles & "|"
        If $CycleTime <> 0 Then
            Local $TimeTemp= TimerDiff($CycleTime)
            Local $TotalTemp = TimerDiff($TotalTime)
            Local $AvgTemp = $TotalTemp / $Cycles
            $CycleTimeS = _TimeToString( $TimeTemp )
            $LogStringTemp = $LogStringTemp & "Last Cycle Time: " & $CycleTimeS & "|"
            $CycleTimeA = _TimeToString( $AvgTemp )
            $LogStringTemp = $LogStringTemp & "Avg. Cycle Time: " & $CycleTimeA & "|"
            Local $T1 = TimerDiff($CycleTime)
            If $T1 > $CycleTimeMax Or $CycleTimeMax == 0 Then
                $CycleTimeMax = $T1
            EndIf
            If $CycleTimeMin > $T1 Or $CycleTimeMin == 0 Then
                $CycleTimeMin = $T1
            EndIf
            $LogStringTemp = $LogStringTemp & "Max Cycle Time: " & _TimeToString($CycleTimeMax) & "|"
            $LogStringTemp = $LogStringTemp & "Min Cycle Time: " & _TimeToString($CycleTimeMin) & "|"
            $LogStringTemp = $LogStringTemp & "Total Time: " & _TimeToString($TotalTemp) & "|"
            $CycleTime = TimerInit()
        Else
            $CycleTime = TimerInit()
            $TotalTime = TimerInit()
        EndIf
        $LogStringTemp = $LogStringTemp & "==========================" & "|"
        $CycleTime = TimerInit()
        $LogStringTemp = $LogStringTemp & "Starting next cycle"
        DoLogStatus( $LogStringTemp )

So there's a major slowdown over time, but why? My guess would be adding to the list control gets slower and slower as it gets larger, but I don't see why. I've got it set to not sort, which would be an obvious cause of slowdown as it grows. Here's the initialization:

$LogView = GUICreate("Log:", 260, 445, 752, 125, BitOR($WS_MINIMIZEBOX,$WS_SIZEBOX,$WS_THICKFRAME,$WS_SYSMENU,$WS_CAPTION,$WS_POPUP,$WS_POPUPWINDOW,$WS_GROUP,$WS_BORDER,$WS_CLIPSIBLINGS))
$Log1 = GUICtrlCreateList("", 0, 0, 260, 445, BitOR($LBS_NOSEL,$WS_HSCROLL,$WS_VSCROLL,$WS_BORDER))
GUICtrlSetResizing(-1, $GUI_DOCKLEFT+$GUI_DOCKRIGHT+$GUI_DOCKTOP+$GUI_DOCKBOTTOM+$GUI_DOCKHCENTER+$GUI_DOCKVCENTER+$GUI_DOCKWIDTH+$GUI_DOCKHEIGHT)

I'm using Autoit v3.2.12.1, Windows XP, if it matters.

[FireFox]

@chantling

the Sleep() function isnt precise for long sleep, you should use TimerInit and TimerDiff as sleep function and you can use it also for test the time before and after a sleep

Cheers, FireFox.

[chantling]

@chantling

the Sleep() function isnt precise for long sleep, you should use TimerInit and TimerDiff as sleep function and you can use it also for test the time before and after a sleep

Cheers, FireFox.

Yeah, I'm using a state-based system in the script, plenty of timers, so Sleep() is only used for < 1s pauses. It just landed in my crosshairs at first b/c I had absolutely no idea where the slowdown was coming from. I can pretty much rule out Sleep() and PixelGetColor() b/c there are none in the listing above, yet that part of the code is showing the slowdown as well.

<edit> I was just looking at the list update calls in the function and it occurred to me that _GUICtrlListBox_UpdateHScroll might be the culprit. Looking in the helpfile, I see that it updates the horiz. scroll bar based on the longest string in the list, which of course means it has to iterate through every line in the list, every time it's called. As my logfiles can approach dozens of thousands of lines long after a while, it's naturally going to start to take a while. I just commented it out and am testing to see what happens.

<edit2> Well, that appears to have been the culprit. Guess I'll just have to set the horizontal scroll at creation with _GUICtrlListBox_SetHorizontalExtent and guess how wide my log might go. Bummer. But at least the script's working.

Edited March 2, 2009 by chantling

[Richard Robertson]

If you truncate the list every once in a while, you should eliminate part of the problem.