Performance Messung und Script Analyse

  • Ich bastel gerade an einer Möglichkeit einfach und bequem meine Scripte zu analysieren und die Performance einzelner Funktionen zu messen.

    Ziele:

    1. Ermittlung der langsamsten Funktionen
    2. Ermittlung der am meist aufgerufenen Funktionen
    3. Ermittlung der insgesamt zeitintensivsten Programmteile
    4. Eventuell grafische und zeitliche Darstellung des Scriptablaufs (Sequenzdiagramm)

    Die aktuelle Version erstellt ein "Trace" Script aus dem Quellscript, startet dieses und gibt die Ergebnisse der Messungen aus. Derzeit fehlt also noch eine Auswertung (sollte kein Problem sein) und grafisch ansprechende Darstellung (schon eher ein Problem).
    Außerdem fehlt es mir an entsprechend umfangreichen Testscripten um die Funktionalität der aktuellen Fassung zu testen.

    Und ja der Quellcode schaut derzeit noch etwas chaotisch aus, gerade was das einfügen bei "return" statements angeht musste ich lange rumspielen bis es mit meinem Testscript zuverlässig funktioniert hatte. Vermutlich wäre der Einsatz von regulären Ausdrücke deutlich einfacher gewesen, steht jedenfalls auf meiner Todo das nochmals etwas zu ändern.

    Ich möchte euch daher erstmal darum bitten das Script ausgiebig mit umfangreicheren Scripten zu testen und mich auf Fehler aufmerksam zumachen (z.B. nicht ersetzte oder falsch ersetzte "return" Strings). Ich bin mir auch nicht sicher ob das Script funktioniert wenn im Original Script bereits ein "onautoitexitregister" verwendet wird und wie ich das in solch einem Fall evtl. besser lösen könnte ohne permanent in die Datei schreiben zu müssen. Theoretisch wäre auch ein überwachendes Script denkbar um erst garkeinen Umweg über eine Datei gehen zu müssen, allerdings möchte ich die Performance des Scriptes auch nicht zu sehr durch die Messungen und Datenübertragung der Messergebnisse beeinflussen.

    Ideen, Vorschläge oder gar modifizierte/erweiterte Scriptversionen sind herzlich Willkommen.

    EDIT: Netter Nebeneffekt ist im übrigen, dass man bei abstürzenden Scripten sehr gut im Logfile sieht welche Funktion zuletzt ausgeführt wurde, was die Fehlersuche bei kompilierten Scripten evtl. ein wenig vereinfachen kann.


    v0.3.1
    [autoit]


    #include <Constants.au3>
    #include <array.au3>
    #include <file.au3>

    [/autoit] [autoit][/autoit] [autoit]

    Global $sourceFile = FileOpenDialog("Script auswählen...",@ScriptDir,"Autoit (*.au3)",3)
    ;Global $sourceFile = @ScriptDir & "\test.au3"
    Global $targetFile = StringReplace($sourceFile,".au3","_trace.au3",-1)
    Global $traceLogFile = StringReplace($sourceFile,".au3","_trace.log",-1)

    [/autoit] [autoit][/autoit] [autoit]

    createTraceScript($sourceFile)
    runTraceScript($targetFile)
    showTraceResult($traceLogFile)

    [/autoit] [autoit][/autoit] [autoit][/autoit] [autoit]

    Func showTraceResult($sPath)
    Local $aData
    _FileReadToArray($sPath,$aData)
    Local $aReturn[UBound($aData)][4]=[["Name","FuncStart","FuncEnd","FuncRunTime"]]
    Local $aSplit

    [/autoit] [autoit][/autoit] [autoit]

    For $i = 1 To UBound($aData)-1
    $aSplit = StringSplit($aData[$i],";")
    For $j = 1 To UBound($aSplit)-1
    $aReturn[$i][$j-1]=$aSplit[$j]
    Next
    Next

    [/autoit] [autoit][/autoit] [autoit]

    _ArrayDisplay($aReturn)
    EndFunc

    [/autoit] [autoit][/autoit] [autoit][/autoit] [autoit][/autoit] [autoit]

    Func createTraceScript($sourceFile)
    Local $aScript
    _FileReadToArray($sourceFile,$aScript)
    Local $aFunctionNames = getFunctionNames($aScript)
    Local $aReturn[UBound($aScript)+(2*(UBound($aFunctionNames)))]=[$aScript[0]]
    Local $sDebugVarName = getDebugVarName($aScript)
    Local $sDebugFunctionName = getDebugFunctionName($aScript)
    Local $sDebugFunctionShutdownName = getDebugFunctionName($aScript,"__MyDebugTraceFunctionShutdown")
    Local $aTemp, $sTemp, $iPos
    Local $k = 1
    Local $j = 0

    [/autoit] [autoit][/autoit] [autoit]

    $aReturn[$j] = '; MyDebugTrace by MisterSpeed' & @CRLF & _
    'Global ' & $sDebugVarName & '[1][4]=[["Name","FuncStart","FuncEnd","FuncRunTime"]]' & @CRLF & _
    'OnAutoItExitRegister("' & $sDebugFunctionShutdownName & '")' & @CRLF & _
    'Func ' & $sDebugFunctionName & '($sName,$iState,$dReturn="")' & @CRLF & _
    @TAB & 'Local $time' & @CRLF & _
    @TAB & 'If $iState = 1 Then' & @CRLF & _
    @TAB & @TAB & '$time = TimerInit()' & @CRLF & _
    @TAB & @TAB & 'Redim ' & $sDebugVarName & '[ubound(' & $sDebugVarName & ')+1][4]' & @CRLF & _
    @TAB & @TAB & $sDebugVarName & '[UBound(' & $sDebugVarName & ')-1][0] = $sName' & @CRLF & _
    @TAB & @TAB & $sDebugVarName & '[UBound(' & $sDebugVarName & ')-1][1] = $time' & @CRLF & _
    @TAB & 'Else' & @CRLF & _
    @TAB & @TAB & '$time = TimerInit()' & @CRLF & _
    @TAB & @TAB & 'For $i = UBound(' & $sDebugVarName & ')-1 To 1 Step -1' & @CRLF & _
    @TAB & @TAB & @TAB & 'If ' & $sDebugVarName & '[$i][0] = $sName And ' & $sDebugVarName & '[$i][3] = "" Then ExitLoop' & @CRLF & _
    @TAB & @TAB & 'Next' & @CRLF & _
    @TAB & @TAB & $sDebugVarName & '[$i][2] = $time' & @CRLF & _
    @TAB & @TAB & $sDebugVarName & '[$i][3] = TimerDiff(' & $sDebugVarName & '[$i][1])' & @CRLF & _
    @TAB & 'Endif' & @CRLF & _
    @TAB & 'Return $dReturn' & @CRLF & _
    'EndFunc' & @CRLF & @CRLF & _
    'Func ' & $sDebugFunctionShutdownName & '()' & @CRLF & _
    @TAB & 'Local $sTemp' & @CRLF & _
    @TAB & 'For $i = 1 To UBound(' & $sDebugVarName & ')-1' & @CRLF & _
    @TAB & @TAB & '$sTemp &= ' & $sDebugVarName & '[$i][0] & ";" & ' & $sDebugVarName & '[$i][1] & ";" & ' & $sDebugVarName & '[$i][2] & ";" & ' & $sDebugVarName & '[$i][3] & @CRLF' & @CRLF & _
    @TAB & 'Next' & @CRLF & _
    @TAB & 'Local $hFile = FileOpen("' & $traceLogFile & '",2)' & @CRLF & _
    @TAB & 'FileWrite($hFile,$sTemp)' & @CRLF & _
    @TAB & 'FileClose($hFile)' & @CRLF & _
    'EndFunc' & @CRLF
    $j+=1

    [/autoit] [autoit][/autoit] [autoit]

    For $i = 1 to UBound($aScript)-1
    If $aFunctionNames[$k][1] = $i Then
    $aReturn[$j]=$aScript[$i]
    $j+=1
    $aReturn[$j]=$sDebugFunctionName & '("' & $aFunctionNames[$k][0] & '",1)'
    ConsoleWrite("New function starts!" & @CRLF & $aScript[$i] & @CRLF & $aReturn[$j] & @CRLF & "--------------" & @CRLF)
    Else
    If StringRight($aScript[$i],7) = " Return" Or StringRight($aScript[$i],7) = " return" Then
    $aReturn[$j]=StringTrimRight($aScript[$i],6) & 'Return ' & $sDebugFunctionName & '("' & $aFunctionNames[$k][0] & '",0)'
    ConsoleWrite("Return at end of line!" & @CRLF & $aScript[$i] & @CRLF & $aReturn[$j] & @CRLF & "--------------" & @CRLF)
    $j+=1
    ContinueLoop
    EndIf
    $sTemp = StringReplace($aScript[$i]," ","")
    $sTemp = StringReplace($sTemp,@TAB,"")
    $aTemp = StringSplit($sTemp,";")

    [/autoit] [autoit][/autoit] [autoit]

    If $aTemp[1] = "return" Or $aTemp[1] = "Return" Then
    $sTemp = StringReplace($aScript[$i],"return","Return")
    $aTemp = StringSplit($sTemp,"Return",1)
    If $aTemp[0] > 1 Then
    $aReturn[$j] = $aTemp[1] & 'Return ' & $sDebugFunctionName & '("' & $aFunctionNames[$k][0] & '",0)'
    Else
    $aReturn[$j] = 'Return ' & $sDebugFunctionName & '("' & $aFunctionNames[$k][0] & '",0)'
    EndIf
    $aTemp = StringSplit($aScript[$i],";")
    If $aTemp[0] > 1 Then
    For $x = 2 To $aTemp[0]
    $aReturn[$j] &= ";" & $aTemp[$x]
    Next
    EndIf
    ConsoleWrite("Single Return line!" & @CRLF & $aScript[$i] & @CRLF & $aReturn[$j] & @CRLF & "--------------" & @CRLF)
    $j+=1
    ContinueLoop
    EndIf

    [/autoit] [autoit][/autoit] [autoit][/autoit] [autoit]

    $iPos = StringInStr($aScript[$i],"return ")
    If $iPos Then ; return Zeile
    If $iPos = 1 Then
    $sTemp = StringReplace($aScript[$i],"return ","",1)
    $aTemp = StringSplit($sTemp,";")
    $sTemp = $aTemp[1]
    $aReturn[$j] = 'Return ' & $sDebugFunctionName & '("' & $aFunctionNames[$k][0] & '",0,' & $sTemp & ')'
    If $aTemp[0] > 1 Then
    $sTemp = ""
    For $x = 2 to $aTemp[0]
    $sTemp &= $aTemp[$x]
    Next
    $aReturn[$j] &= $sTemp
    EndIf
    ConsoleWrite("Return Line starting charpos 1!" & @CRLF & $aScript[$i] & @CRLF & $aReturn[$j] & @CRLF & "--------------" & @CRLF)
    Else
    If StringIsAlpha(StringMid($aScript[$i],$iPos-1,1)) Then
    $aReturn[$j]=$aScript[$i]
    ConsoleWrite("String is alpha!" & @CRLF & $aScript[$i] & @CRLF & $aReturn[$j] & @CRLF & "--------------"& @CRLF)
    Else
    $sTemp = StringReplace($aScript[$i],"return ","Return",1)
    $aTemp = StringSplit($sTemp,"Return",1)
    $aReturn[$j] = $aTemp[1]
    $sTemp = ""
    For $x=2 To $aTemp[0]
    $sTemp &= $aTemp[$x]
    Next
    ;StringReplace($aScript[$i],"Return ","",1)
    $aTemp = StringSplit($sTemp,";")
    $sTemp = $aTemp[1]
    $aReturn[$j] &= 'Return ' & $sDebugFunctionName & '("' & $aFunctionNames[$k][0] & '",0,' & $sTemp & ')'
    If $aTemp[0] > 1 Then
    $sTemp = ""
    For $x = 2 to $aTemp[0]
    $sTemp &= ';' & $aTemp[$x]
    Next
    $aReturn[$j] &= $sTemp
    EndIf
    ConsoleWrite("Return Line starting charpos x!" & @CRLF & $aScript[$i] & @CRLF & $aReturn[$j] & @CRLF & "--------------" & @CRLF)
    EndIf
    EndIf
    Else
    If $aFunctionNames[$k][2] = $i Then
    $aReturn[$j]=$sDebugFunctionName & '("' & $aFunctionNames[$k][0] & '",0)'
    ConsoleWrite("New function ends!" & @CRLF & $aReturn[$j] & @CRLF & $aScript[$i] & @CRLF & "--------------" & @CRLF)
    $j+=1
    $k+=1
    $aReturn[$j]=$aScript[$i]
    Else
    $aReturn[$j]=$aScript[$i]
    EndIf
    EndIf
    EndIf
    $j+=1
    Next

    [/autoit] [autoit][/autoit] [autoit]

    _FileWriteFromArray($targetFile,$aReturn,0)
    Return $aReturn
    EndFunc

    [/autoit] [autoit][/autoit] [autoit]

    Func runTraceScript($sPath)
    ConsoleWrite(@CRLF & @CRLF & "Running Script now!" & @CRLF & "--------------" & @CRLF)
    Local $sLine = ""
    Local $sTemp = ""
    Local $PID = Run('"' & @AutoItExe & '" /ErrorStdOut "' & $targetFile & '"',"",@SW_SHOW,$STDOUT_CHILD)
    While 1
    $sTemp = StdoutRead($PID)
    If @error Then ExitLoop
    If $sTemp <> "" Then $sLine &= $sTemp & @CRLF
    WEnd
    ConsoleWrite($sLine)
    EndFunc

    [/autoit] [autoit][/autoit] [autoit]

    Func getFunctionNames(ByRef $aData)
    Local $aTemp
    Local $sTemp
    Local $aReturn[UBound($aData)][3] = [["Name","FuncStartLine","FuncEndLine"]]
    Local $k = 1

    [/autoit] [autoit][/autoit] [autoit]

    For $i = 1 To UBound($aData)-1
    If StringInStr($aData[$i],"Func ") And Not StringInStr($aData[$i],"EndFunc") Then
    $aData[$i]=StringReplace($aData[$i],"func ","Func ",1,1)
    $aTemp = StringSplit($aData[$i],"Func ",1)
    $aTemp = StringSplit($aTemp[$aTemp[0]],"(")
    $sTemp = StringReplace($aTemp[1]," ","")
    $sTemp = StringReplace($aTemp[1],@TAB,"")
    $aReturn[$k][0] = $sTemp & "(...)"
    $aReturn[$k][1] = $i
    For $j = $i+1 To UBound($aData)-1
    If StringInStr($aData[$j],"EndFunc") Then
    $aReturn[$k][2] = $j
    $i = $j
    ExitLoop
    EndIf
    Next
    $k+=1
    EndIf
    Next
    ReDim $aReturn[$k][3]
    Return $aReturn
    EndFunc

    [/autoit] [autoit][/autoit] [autoit]

    Func getDebugVarName(ByRef $aData, $sCheck="$aMyDebugTrace")
    Local $sReturn = $sCheck

    [/autoit] [autoit][/autoit] [autoit]

    For $i = 1 To UBound($aData)-1
    If StringInStr($aData[$i],$sReturn) Then
    $sReturn = getDebugVarName($aData,$sCheck & TimerInit()) ; check again with random var name
    ExitLoop
    EndIf
    Next

    [/autoit] [autoit][/autoit] [autoit]

    Return $sReturn
    EndFunc

    [/autoit] [autoit][/autoit] [autoit]

    Func getDebugFunctionName(ByRef $aData, $sCheck="__MyDebugTraceFunction")
    Local $sReturn = $sCheck

    [/autoit] [autoit][/autoit] [autoit]

    For $i = 1 To UBound($aData)-1
    If StringInStr($aData[$i],$sReturn) Then
    $sReturn = getDebugFunctionName($aData,$sCheck & TimerInit()) ; check again with random function name
    ExitLoop
    EndIf
    Next

    [/autoit] [autoit][/autoit] [autoit]

    Return $sReturn
    EndFunc

    [/autoit]

    3 Mal editiert, zuletzt von misterspeed (24. Juli 2013 um 18:16)

  • Hi,
    nette Idee, einen Profiler zu schreiben!

    Die Kunst ist aber nicht, die Daten in ein Logfile zu schreiben, sondern hilfreich auszuwerten.
    Es müsste also eine Art Tabelle oder Diagramm geben, in dem man sofort ablesen kann, in welcher Funktion im Verhältnis zu Programmlaufzeit die
    - meiste Zeit
    - höchste Aufruffrequenz
    - höchste Prozessorlast
    - uswusf.
    festgestellt wurde. Das sind dann die sog. "Hotspots".

    Wenn das für die Funktion hinhaut, sollte man definitiv die "loops" (For/To While/Wend usw) mit einbeziehen.
    "Richtige" Profiler werten die Laufzeit jeder einzelnen Programmzeile aus. Damit ist dann auch ein direkter Verweis in den Quellcode machbar
    Anhand dieser Ergebnisse ist dann auf einen Blick erkennbar, in welcher Schleife die meiste Zeit verbracht wurde. Und dort kann man dann anfangen den Code zu optimieren....

  • Jupp, wie gesagt erstmal nur ein Grundgerüst um möglichst bequem überhaupt erstmal überall eine Zeitmessfunktion einzubauen, was doch etwas schwerer war als ursprünglich von mir angenommen. Schleifen sind jedenfalls angedacht, aber auch hier wird es evtl. nicht so einfach alle "do","for" und "while" statements zuverlässig zu finden ohne dabei versehentlich Kommentarzeilen oder Variablen zu ersetzen, das ist beim return statement schon ein rumgemurkse.

    Hast du das Ding mal auf deine Scripte losgelassen und kontrolliert ob alle Funktionen und return statements korrekt erkannt und fehlerfrei ersetzt wurden?

    Jede Programmzeile zu messen halte ich allerdings für übertrieben, außerdem würde die Laufzeit für die Messfunktion in den meisten Fällen die Ausführungszeit der eigentlichen Programmzeile deutlich übersteigen. Ich denke es genügt, wenn man einen ungefähren Anhaltspunkt bekommt in welchen Funktionen und ggf. auch Schleifen die meiste Zeit verlorengeht. Danach kann man immernoch manuelle Messpunkte in einzelnen Abschnitten setzen um das "Problem" einzugrenzen. Angedacht war aber noch eine globale Messung der Gesamtlaufzeit um z.B. errechnen zu können wie lange das Script im globalen Kontext arbeitet (z.B. GUI Schleife).

    Was die Prozessorlast anbelangt...

    Wie könnte man das am besten messen? Über das startende, also mein Script nehme ich mal an oder? Wenn ja wie misst man die Last einer bestimmten PID und wie würdest du die Lastmessungen am besten mit den Einträgen im Logfile verbinden? Timerinit Timestamps könnten zu ungenau sein um hier eine Zuordnung vorzunehmen, außerdem kann ich ja auch nicht 1000 Lastmessungen pro Sekunde machen und viele Funktionen laufen in weniger als 1ms durch.

  • Hi,

    Zitat

    Hast du das Ding mal auf deine Scripte losgelassen und kontrolliert ob alle Funktionen und return statements korrekt erkannt und fehlerfrei ersetzt wurden?

    Habe einige Scripte getestet. Bei den meisten wird zwar die *trace.au3 erstellt, aber das Script läuft nicht durch bzw bleibt mittendrin ab und zu stehen...aber da teste ich noch.

    Zitat

    Jede Programmzeile zu messen halte ich allerdings für übertrieben,

    mit dem von dir vorgestellten Konzept hast du Recht^^

    Zitat

    Was die Prozessorlast anbelangt...

    war nur ein Beispiel. In meinen Scripten "quäle" ich öfter mal das Equipment 8o . Da ist ein Sleep(20) definitiv kontraproduktiv^^. Ich will ja sehen, was die Prozessoren maximal leisten...

    Hast du dir mal "richtige" Profiler angeschaut (von AMD benutze ich bspw. Code Analyst oder CodeXL) ? Dort bekommt man sehr viele verschiedene Informationen, "eigentlich" denkt man, alles sei ok, bis man dann plötzlich merkt dass der Prozessor(core) nur zu 60%ausgelastet ist....aber das wäre für ein AutoIt-Script viel zu viel des Guten :rolleyes:

    Zitat

    Timerinit Timestamps könnten zu ungenau sein um hier eine Zuordnung vorzunehmen, außerdem kann ich ja auch nicht 1000 Lastmessungen pro Sekunde machen und viele Funktionen laufen in weniger als 1ms durch.

    Die Timestamps lösen wesentlich höher (niedriger ? ) auf als 1 ms. Was du nicht verhindern kannst, ist dass dir Windows und die anderen Programme einen Strich durch die Rechnung machen! Daher wäre es ggf. sinnvoll, die Prozesspriorität für den "Testlauf" auf maximum zu stellen, damit dir keine Querschläger durch die anderen Prozesse das Messergebnis verfälschen.
    Sobald nur etwas Last auf dem Bus ist, bricht die Performance der AutoItscripte massiv ein, typisch Interpreter..