MsgBox verlangsamt den Skriptablauf unter Win 10

  • Mal schauen welche "Schalter" es in AutoIt noch gibt die wir alle nicht kannten.

  • Was ist denn mit folgender Theorie?

    Es ist nicht unbeabsichtigt, sondern von Microsoft gewollt! Da AutoIt eine recht leicht zu lernende Scriptsprache ist, die auch schon häufiger für Schadsoftware missbraucht wurde, haben die den WindowsDefender dahingehende modifiziert, dass erkannt wird, wenn eine autoit.exe gestattet wurde und diese dann zur Laufzeit analysiert und dabei ausgebremst wird?! Seit win10 werden beinahe alle exen von mir in quarantäne geschickt weil irgend etwas bösartiges gefunden wird! (Was aber jahrelang zuvor nicht registriert/beachtet wurde von irgendwelchen AV-Routinen)

  • Ja Windows denkt bei jeder in AutoIt geschriebenen Exe, dass es ein Virus ist (ist bei mir genauso), allerdings glaube ich nicht, dass Windows absichtlich irgendwelche Skripte ausbremst. Im Prinzip läuft das Skript ja über die standard AutoIt3.exe und nicht als eigenständiges Programm. Da die AutoIt3.exe nicht vom Defender als Virus eingestuft wird, sollte sie zur Laufzeit auch nicht besonderst stark von ihm beeinflusst werden.

    Edit: Falls jemand Vergleichswerte mit GDI+ will:

    Scheint als würde nur der AutoIt-Teil langsamer werden. Ich komme da auf ca. 70% mit MsgBox + EventMode. Für ein Skript in dem GDI+ den Großteil der Zeit läuft ist also leider kein Faktor 7 drin wenn man die GUI auslagert...

  • Nur um alle mal auf dem Laufenden zu halten :

    Im EN-Forum hat sich einer der Entwickler (jpm) gemeldet, und folgenden 'work-around' vorgeschlagen (also die MsgBox-Funktion zu wrappen und in einen "eigenen Prozess" auszulagern) :rolleyes::

    AutoIt
    Func _MsgBox($iFlag, $sTitle, $sText, $iTimeOut = 0)
        RunWait(@AutoItExe & ' /AutoIt3ExecuteLine "MsgBox(' & $iFlag & ', ''' & $sTitle & ''', ''' & $sText & ''', ' & $iTimeOut & ')"')
    EndFunc   ;==>_MsgBox

    Das von mir sehr geschätzte Mitglied jchd hat darauf passend und prompt geantwortet :

    https://www.autoitscript.com/forum/topic/20…comment=1451577

    (schnelle Übersetzung :)

    "Eine solche Umgehung ist ziemlich sinnlos: Sobald ein Fenster angezeigt wird, geschieht die Verlangsamung. Es ist unmöglich, jede GUI-Operation einem bestimmten Prozess zuzuordnen. Das bedeutet einfach, dass AutoIt 6 Mal (für mich) bis zu 10 Mal (für einige andere Benutzer) schneller werden kann, als es tatsächlich ist, nachdem es irgendeine Art von Fenster unter W10 "gezeigt" hat. Das heißt, alle AutoIt GUI-Programme (alte oder aktuelle), die unter W10 gestartet wurden.

    Das ist ein Grund genug, Jon schnell aus seiner abgeschlossenen Höhle herauszuholen (vorausgesetzt, er ist noch am Leben).":rofl:

    Gruß Musashi

    86598-musashi-c64-png

    "Am Anfang wurde das Universum erschaffen. Das machte viele Leute sehr wütend und wurde allenthalben als Schritt in die falsche Richtung angesehen."

    • Offizieller Beitrag

    Ich habe mal einen Test mit nim gemacht.

    Ergebnis:

    Code
    Kürzeste Zeit vor MsgBox      0.09299999999999997
    Kürzeste Zeit nach MsgBox     0.08800000000000008
    Längste Zeit vor MsgBox       0.09400000000000031
    Längste Zeit nach MsgBox      0.1029999999999998
    Mittlere Zeit vor MsgBox      0.09490000000000003
    Mittlere Zeit nach MsgBox     0.09459999999999999

    System: Win10 Pro x64, Build 18362

    Hier hat es keinerlei Einfluß auf die Geschwindigkeit. Wie bereits vermutet, könnte das eine gezielte Attacke von $MS gegen AutoIt sein. (Anordnung durch das Trumpeltier? :rofl:)

  • Spaßvogel :P . Ausgerechnet mein Hauptkandidat dem ich das zutrauen würde stellt diese Frage.

    Hehe, ich hatte einmal vor Jahren an einem Wochenende damit angefangen, einfachste Scripte auf Maschinenebene mittels Debugger zu "analysieren". Da sieht man auch schon nach einigen Minuten kein Land mehr...

    Für mich am schlimmsten war, dass ich, infolge keinerlei Kenntnis des Quellcodes, auch keinerlei Rückschlüsse auf Programmabläufe schließen konnte. Ich hatte Anfang der 90er im vorherigen Jahrhundert selbst (einfache Basic-) Interpreter und auch lauffähige X86-Assembler geschrieben, daher war mir klar, auf was ich mich einlasse^^

    Irgendein Cleverle könnte jetzt ja sagen:" Hey, der "Fehler" im Code kommt doch von der MsgBox-Funktion, du musst doch nur den Einsprung in die (user32.dll-) MessageBoxW-Funktion finden, um dort "in der Nähe" entsprechend zu suchen!"

    Gute Idee, aber der Compiler kracht den Code zu mit unendlich vielen "Absicherungen", und packt dazu noch unendlich viele Funktionen in den Code, die das zu interpretierende Script irgendwann ggf. mal gebrauchen könnte(!). Der Compiler würfelt das dann auch noch fleissig durcheinander (aka optimiert) und fertig ist das Code-Chaos.

    Letztendlich besteht eine AutoIt-EXE ja aus mehreren hundert Kilobytes Code, auch wenn nur ein einfachstes Script zu interpretieren ist!

    Ein "reines", bspw. in C erstelltes Programm, welches letztendlich aus einer Handvoll Kilobytes Maschinencode besteht, ist in einigen Stunden komplett "zerpflückt".

    Hat jemand vielleicht ein System zur Hand auf dem er kurz verschiedene AutoIt-Versionen installieren kann? War das schon mit älteren (3.3.10.2, 3.3.8.1, 3.3.6.0 und co. so?)

    Eben getestet, Win Server 2012 mit AutoIt 3.3.8.1 völlig unauffällig, die Schleife ist vor und nach der Msgbox gleich schnell. Morgen kann ich das Verhalten auch noch auf Win7 und XP testen.

    Übrigens zeigt das kompilierte 3.3.8.1-Script unter Win10 auch das Verhalten, dass die erste Schleife ca. 8-10x schneller läuft wie die zweite nach der MsgBox.

    Ergo: WIN10 ist das Problem.

  • Ein einfaches

    Code
    AutoItSetOption('GUIOnEventMode', 1)

    verlangsamt auch das Skript

    Code
    AutoItSetOption('GUIOnEventMode', 1)
    $start = TimerInit()
    $x = 0
    For $i = 1 To 5000000
        $x += 1
    Next
    ConsoleWrite('@@ Debug(' & @ScriptLineNumber & ') : TimerDiff($start) = ' & TimerDiff($start) & @CRLF) ;### Debug Console

    Unter FreeBasic gibt es keine Probleme!

    Output:

    Code
    >>>>> Check 1  <<<<<<
    Elapsed Time 1: 1634.368500014247 ms
    Elapsed Time 2: 1568.77529999646 ms
    Elapsed Time 3: 1718.41980000012 ms
    >>>>> Check 2 after Messagebox call <<<<<<
    Elapsed Time 1: 1621.735800009915 ms
    Elapsed Time 2: 1752.797799986425 ms
    Elapsed Time 3: 1734.618899997685 ms
    Done

    Auch am Arsch geht ein Weg vorbei...

    ¯\_(ツ)_/¯

  • Ich habe das Script mal auf verschieden System laufen lassen, allerdings in VMs:

    Als Hostsystem ist Windows 10 LTSC 1809 installiert!

    Windows 10 LTSC (Hostsystem):

    > ------------------------------------------
    > >>>>> Check 1 vor ... <<<<<
    ! Elapsed time 1 : 569.979 ms
    ! Elapsed time 2 : 569.112 ms
    ! Elapsed time 3 : 569.562 ms
    > >>>>> Check 2 nach _ArrayDisplay <<<<<
    ! Elapsed time 1 : 3455.226 ms
    ! Elapsed time 2 : 3444.094 ms
    ! Elapsed time 3 : 3436.570 ms
    > >>>>> Check 3 nach GUIOnEventMode=1 <<<<<
    ! Elapsed time 1 : 4398.779 ms
    ! Elapsed time 2 : 4368.314 ms
    ! Elapsed time 3 : 4383.285 ms
    > ------------------------------------------

    WindowsXP (32Bit):

    > ------------------------------------------
    > >>>>> Check 1 vor ... <<<<<
    ! Elapsed time 1 : 673.275 ms
    ! Elapsed time 2 : 699.424 ms
    ! Elapsed time 3 : 627.805 ms
    > >>>>> Check 2 nach _ArrayDisplay <<<<<
    ! Elapsed time 1 : 523.474 ms
    ! Elapsed time 2 : 521.010 ms
    ! Elapsed time 3 : 520.581 ms
    > >>>>> Check 3 nach GUIOnEventMode=1 <<<<<
    ! Elapsed time 1 : 1159.178 ms
    ! Elapsed time 2 : 1181.750 ms
    ! Elapsed time 3 : 1166.352 ms
    > ------------------------------------------

    Windows 7 Ultimate (x64):

    > ------------------------------------------
    > >>>>> Check 1 vor ... <<<<<
    ! Elapsed time 1 : 522.313 ms
    ! Elapsed time 2 : 524.421 ms
    ! Elapsed time 3 : 525.721 ms
    > >>>>> Check 2 nach _ArrayDisplay <<<<<
    ! Elapsed time 1 : 523.526 ms
    ! Elapsed time 2 : 521.809 ms
    ! Elapsed time 3 : 522.121 ms
    > >>>>> Check 3 nach GUIOnEventMode=1 <<<<<
    ! Elapsed time 1 : 1200.217 ms
    ! Elapsed time 2 : 1200.965 ms
    ! Elapsed time 3 : 1196.835 ms
    > ------------------------------------------

    Das Testprogramm ist als x86 compliliert (wegen Windows XP)....

    Für mich sieht das aus als würde der GUIOnEventMode=1 immer etwas bremsen, aber nicht so start wie unter Windows 10

    lg

    Racer

  • Kurze Info zum aktuellen Stand im englischen Forum (für die, die dort nicht mitlesen können/wollen) :

    Zitat von argumentum (übersetzt)

    bis zur Version 1803 tritt das Verhalten nicht auf - ab Version 1809 aufwärts geht es los

    Version 1803 (April 2018 Update)

    Version 1809 (October 2018 Update)

    Kommentar von jchd :

    Zitat von jchd (übersetzt)

    Wenn ich Wikipedias Win10-Geschichte richtig verstehe bedeutet das, dass der Fehler mit der Veröffentlichung der v1809 (Oktober 2018) eingeführt wurde, 6 Monate nach v1803, also vor 17 Monaten (wobei wir aktuell nur die v1909 bekommen können).

    Nebenbei bemerkt : die letzte "funktionierende" Version ist die 1803 mit dem Supportende am 12. Mai 2020.

    Statement des Developer's jpm :

    Zitat von jpm

    Daher denke ich, dass Jon seine alten Freunde von Microsoft kontaktieren muss ...

    (für die, die es nicht wissen : Jon ist der ursprüngliche Entwickler von AutoIt)

    Mein Zwischenfazit :

    Sofern keiner von uns eine praktikable Lösung findet, was ohne den AutoIt-Core-Sourcecode eher unwahrscheinlich ist, sollten wir die weitere Entwicklung im EN-Forum abwarten.

    Gruß Musashi

    86598-musashi-c64-png

    "Am Anfang wurde das Universum erschaffen. Das machte viele Leute sehr wütend und wurde allenthalben als Schritt in die falsche Richtung angesehen."

  • Mein Zwischenfazit :

    Sofern keiner von uns eine praktikable Lösung findet, was ohne den AutoIt-Core-Sourcecode eher unwahrscheinlich ist, sollten wir die weitere Entwicklung im EN-Forum abwarten.

    Dem kann ich nur zustimmen, denn imho liegt die Ursache in Win10 und dessen derzeitiger Umstellung der Ideolodie: Weg von Win32 Programmen hinzu Win10-Apps.

    mfg (auto)Bert

  • Hi,

    interessanterweise passiert das bei mir nicht, wenn verhindert wird, dass die GUI den Fokus bekommt.
    Wenn ich z.B. ein Toolwindow als Child vom DesktopWindow erstelle kann ich dieses sogar benützen.
    Hatt jetzt nicht wirklich viel praktischen Nützen, fand ich aber recht spannend.

    Habe hier mal das Script aus dem Startpost entsprechend abgeändert:

    Beispiel

    GUI erscheint immer im Hindergrund!

  • Haha, interessanter Ansatz Zeitriss :)

    Allgemein möchte ich eigentlich sagen, dass es keinen Grund gibt den Aluhut aufzusetzen. Mit Sicherheit hat Microsoft AutoIt nicht als Feind entdeckt, Im letzten Jahr habe ich Sachen erlebt, wie das keine Fremdprogramme mehr auf den Jet Treiber zugreifen konnten oder sogar dass keine MS Access-Anwendung mehr ein Update auf eine Datenbank ausführen konnte. Jeweils hat es über einen Monat nach dem Endrüstungssturm gedauert, bis das Problem behoben wurde. Das sind ganz andere Reichweiten..
    Das Problem ist einfach, dass nicht mehr getestet wird. Dazu gibt es viele Artikel. Probleme fallen eben irgendwann im Feld auf oder gar nicht.

    Grüße autoiter

  • Zeitriss

    Starte ich dein Script und betätige den Button, gibt es keine Verlangsamung.

    Klickt man aber vor dem Button auf den "Rand" des Fensters, führt das wiederum nach Buttonklick zum "langsamen" zweiten Schleifendurchlauf....

    autoiter

    Mit Aluhut merkt man nicht mehr so viel und alles ist schöööööööööner :o)

  • Andy

    Ja, in diesem Fall bekommt das Fenster warscheinlich den Fokus. Dass dieses Problem irgendwas damit zu tun haben könnte war eigentlich auch schon alles was ich damit sagen wollte.

    Ich wollte nur ein Szenario produzieren bei dem der Fokus nicht auf das Fenster fällt. Anscheinend ist mir das misslungen.:/

    Etwas OT aber könntest du mir noch sagen welchen Rand du meinst?

    Ich habe grade folgende Punkte getestet, scheint bei mir aber keinen Unterschied zu machen.

    AutoIt_Version: 3.3.14.5
    OS: WIN_10

  • Also, ich habe jetzt in stundenlanger Kleinarbeit mal versucht, mittels eines API-Monitors (http://www.rohitab.com/apimonitor) herauszufinden, welcher Systemaufruf nach dem Erstellen eines Fensters länger dauert oder öfter auftritt. Ich habe dazu das folgende Testskript in kompilierter Form (x86) verwendet::

    Das ist das bereits bekannte Testscript, leicht modifiziert. Die FileWrites stehen deshalb da, weil man die im API-Monitor recht schnell finden kann (CreateFileW mit dem Dateiname als erster Parameter).

    Dabei habe ich ein paar recht interessante Erkenntnisse gewonnen. Vorneweg: Die Ursache für die Verlangsamung konnte ich leider nicht ausmachen, es waren nur "Indizien" zu finden.

    Also, steigen wir mal ein. Das Experiment findet statt auf meinem Notebook mit einem i7-7700HQ und Windows 10 Buildnummer 18362 (Windows 10 1903). Mit dem eingangs erwähnten API-Monitor kann man während der Laufzeit eines Programmes herausfinden und protokollieren, welche Funktionen in welchen (System-)Bibliotheken aufgerufen werden. Netterweise zeigt diese Software nicht nur die Parameter der aufgerufenen Funktion sowie deren Rückgabewert an... Nein, auch die Dauer des Aufrufs (also quasi die Differenz der Zeiten von CALL und RET) wird ermittelt. Das funktioniert, indem die jeweiligen Funktionen durch eine DLL Injection durch "Zwischenfunktionen" ersetzt werden. Das hat jedoch den Nachteil, dass die entsprechenden Systemaufrufe deutlich länger zum Ausführen brauchen. Leider ist es quasi unmöglich, alle Systemaufrufe auf einmal zu protokollieren. Das Log wird schlichtweg zu groß und der API-Monitor macht das nicht mit.

    Daher habe ich im ersten Durchgang ein paar Funktionen mittels der Exclude-Funktionalität des API-Monitors ausgeschlossen. Und zwar HeapAlloc, HeapFree und PeekMessageW sowie nahezu alle anderen GUI-Funktionen. Die GUI-Funktionen hatte ich vorher in Einzeltest schon als Ursache ausschließen können. Dieser Durchgang ist im Anhang als ODS-Datei (innerhalb des ZIP-Ordners) enthalten. Kurz dazu: Das erste Tabellenblatt enthält das gesamte Log vom Start der EXE bis hin zur Anzeige der MsgBox mit den Ergebnissen am Ende. Danach kommen nur noch Aufräum-Arbeiten von AutoIt. Farblich im Log markiert sind... In gelb die Aufrufe von CreateFileW und alles, was damit zusammenhängt. Und in rot der Aufruf von CreateWindowEx zwischen den beiden Berechnungsfunktionen sowie alles, was dazu gehört. Auf dem zweiten und dritten Tabellenblatt sieht man dann, was noch an API-Aufrufen bei den beiden Berechnungsdurchläufen übrigbleibt. Nicht sonderlich viel. Im ersten Durchlauf sind es rund 23 API-Aufrufe, im zweiten Durchlauf 61. Wobei beim zweiten Durchlauf der erste Teil noch zur "Zerstörung" des Fensters gehören könnte. Verglichen mit der riesigen Gesamtmenge an API-Aufrufen sind diese Zahlen allerdings so oder so nicht relevant. Das sieht man auch schön, wenn man die Aufrufzeiten mal addiert. Die 23 API-Aufrufe im ersten Durchlauf brauchten 0,0000181 Sekunden. Die 61 API-Aufrufe im zweiten Durchlauf brauchten 0,0000368 Sekunden. Wenn man mal das rausrechnet, was auch noch zur GUI gehören könnte, kommt das so ziemlich auf's selbe raus. Verglichen mit der Gesamtlaufzeit der beiden Durchläufe laut AutoIt (sieht man im Gesamtlog ganz unten) sind das ohnehin verschwindend geringe Zeiten. Dort brauchte der erste Durchlauf ca. 0,3 Sekunden, der zweite Durchlauf etwa 1 Sekunde. Das zu untersuchende Phänomen ist also definitiv vorhanden, allerdings kann ich einen Zusammenhang mit den untersuchten Systemaufrufen dadurch nahezu ausschließen. Das sollte dann auch die Theorie widerlegen, dass Microsoft da absichtlich ausbremst. :D

    Im zweiten Durchgang schließlich wollte ich dann die bisher ausgeschlossenen Funktionen untersuchen, die sonst mehrere hunderttausend Male während eines Programmdurchlaufes ausgeführt werden: HeapAlloc, HeapFree und PeekMessageW. Ich habe also - um die Datenmenge überschaubar zu halten - nur die Funktionen CreateFileW, CreateWindowEx und PeekMessageW überwacht. Da das Log ob der schieren Größe (~900 MB) kaum noch in LibreOffice Calc zu verarbeiten war, habe ich nur mit den Zeilennummern gearbeitet. Sowohl vor als auch nach der Fenstererstellung wird PeekMessageW in etwa 1.000.000 mal aufgerufen. Also auch da keine Diskrepanz. Das Interessante an dieser Stelle ist jetzt aber, dass ich in diesem Durchlauf (größenordnungsmäßig reproduzierbar) die folgenden Zeiten gemessen durch AutoIt erhalten habe: Erster Durchlauf 16,219 Sekunden, zweiter Durchlauf 17,092 Sekunden. Das Phänomen ist also deutlich deutlich abgeschwächt, wenn nicht sogar verschwunden. Das kann eigentlich nur damit zusammenhängen, dass PeekMessageW mit Monitoring deutlich länger zum Ausführen braucht.

    Nun, was gewinnen wir an Wissen daraus? Ich bin mir nicht ganz sicher, wie das Ergebnis zu deuten ist. Den ersten Durchlauf hätte ich so gedeutet, dass die "Bremse" AutoIt-Intern sein muss, da kein WinAPI-Aufruf signifikant länger dauert. Und mit AutoIt-Intern meine ich, dass weder eine WinAPI-Funktion langsamer ausgeführt wird als vorher, noch eine WinAPI-Funktion öfter aufgerufen wird als vorher.

    Aber was ich mit dem Ergebnis des zweiten Durchgangs anfangen soll, weiß ich selber noch nicht so ganz...

  • Hi chesstiger !

    Sehr interessant.

    Allein für die Mühe, die Du Dir gemacht hast, gibt es hiermit von mir ein dickes fettes "Danke" :thumbup: ;).

    Ich bin wirklich mal gespannt, wie die ganze Sache weiter-/ausgeht.

    Gruß Musashi

    86598-musashi-c64-png

    "Am Anfang wurde das Universum erschaffen. Das machte viele Leute sehr wütend und wurde allenthalben als Schritt in die falsche Richtung angesehen."

  • Nun, was gewinnen wir an Wissen daraus? Ich bin mir nicht ganz sicher, wie das Ergebnis zu deuten ist. Den ersten Durchlauf hätte ich so gedeutet, dass die "Bremse" AutoIt-Intern sein muss, da kein WinAPI-Aufruf signifikant länger dauert. Und mit AutoIt-Intern meine ich, dass weder eine WinAPI-Funktion langsamer ausgeführt wird als vorher, noch eine WinAPI-Funktion öfter aufgerufen wird als vorher.

    Aber was ich mit dem Ergebnis des zweiten Durchgangs anfangen soll, weiß ich selber noch nicht so ganz...

    Das Problem ist auch, dass ja auch bereits uralte Exe.Dateien langsamer geworden sind. Ich habe z.B. mal mein uraltes Spiel MicroTD ausgepackt, dort habe ich praktischerweise ja eine Framerate/Auslastungsanzeige drin. Das Spiel läuft heute (10 Jahre später) via AutoIt3.exe genauso "flüssig" (also Auslastungsanzeige @60FPS zeigt gleichen Auslastungswert), wie wenn ich die 10 Jahre alte Exe starte. An der Exe hat sich mit 100% Sicherheit nichts geändert. Kann mir nur vorstellen, dass AutoIt intern irgendwelche Schalter (errorchecks, oder ähnliches) hat (diese typischen "should never occur" errors die man zwar im Programm abfängt, aber weiß dass sie niemals auftreten, weshalb man das Errorhandling "so lala" implementiert) die erst seit kurzen von Windows umgelegt werden.

    PS: Deine Ausführungen sind wundervoll :thumbup:

  • Erster Durchlauf 16,219 Sekunden, zweiter Durchlauf 17,092 Sekunden. Das Phänomen ist also deutlich deutlich abgeschwächt, wenn nicht sogar verschwunden. Das kann eigentlich nur damit zusammenhängen, dass PeekMessageW mit Monitoring deutlich länger zum Ausführen braucht.

    Tja, beim nochmal lesen kommen einem schon mal Ideen... Nach ein paar Stunden hab ich den Wald vor lauter Bäumen nicht mehr gesehen. Das hat rein gar nichts mit dem beobachteten Phänomen zutun. PeekMessageW wird durch die Monitoring-Software quasi um eine konstante Zeit verlangsamt. Bei 1.000.000 Aufrufen lässt das den relativen, prozentualen Unterschied der beiden Messwerte natürlich erheblich schrumpfen. Aber der absolute Unterschied ist ja immernoch bei rund 0,85 Sekunden. Das ist in der selben Größenordnung wie die Differenz im ersten Durchgang. Von daher: Vergesst diesen Absatz. Die WinAPI-Aufrufe haben nichts mit der Verzögerung zutun, das ist rein AutoIt-Intern.

    Und danke für das Lob. Das ist wirklich ein spannendes Thema.

    Mars Die Error-Checks klingen gar nicht so unplausibel. Der nächste Schritt wäre jetzt, mit einem Tool wie IDA an die Sache ranzugehen und zu schauen, welche AutoIt-Internen Funktionen nach dem Erstellen einer GUI länger zum Ausführen brauchen.

    Edit: Es hat mir einfach keine Ruhe gelassen! Es gibt von Intel ein Tool namens VTune. Damit kann man super maschinennahe x86-Anwendungen profilen, d.h. hinsichtlich Geschwindigkeit optimieren. Der API-Monitor ist zwar cool, aber die Intel-Software liefert definitiv die besseren und verlässlicheren Daten. VTune ist dann in der Lage, genau aufzulisten, wie viel CPU-Zeit in welcher Funktion draufgegangen ist. Ohne den passenden Quellcode zur Binärdatei geht das leider nur eingeschränkt... Aber es geht. Ich habe also folgendes Programm kompiliert und mit VTune ausgeführt:

    Es ist also ein Programm, welches je nach Übergabe eines Kommandozeilenarguments vorher ein Fenster erstellt oder eben nicht. Das von AutoIt gemessene Ergebnis landet dann in einer Logdatei.

    VTune kennt mehrere Möglichkeiten, eine Anwendung zu profilen. Ich habe mich für die Detaillierteste entschieden, welche aber auch den meisten Overhead produziert: Auf Hardware-Basis, mit Stack-Verfolgung. Im Rahmen dieses Profilings hat die AutoIt-Anwendung selber folgende Zeiten ausgegeben:

    Code
    01:26:08> OHNE Fenster: 2262.843 ms
    01:26:53> MIT Fenster: 7075.408 ms

    Nicht ganz der Faktor 10, wie er sonst auf meiner Hardware auftritt, aber dennoch ist das Phänomen definitiv erkennbar.

    VTune misst zunächst mal grob die gesamte Ausführungszeit (also CPU + Idle) und dazu dann noch die gesamte CPU-Zeit:

    ProgrammAutoIt gemessen (ms)VTune Ausführungszeit (ms)VTune CPU-Zeit (ms)
    Ohne Fenster22632677803
    Mit Fenster707572063513
    Verhältnis M/O3,1272,6924,375

    Nun, hier erkennt man nicht nur, dass die Variante ohne Fenster nicht nur deutlich schneller ist, sondern auch offensichtlich wesentlich weniger Zeit im Idle "verschwendet". Aber natürlich ist auch die CPU-Zeit sehr interessant. Wir sprechen hier von einer Differenz von 2,7 Sekunden - nur für das Erstellen eines Fensters.

    Und jetzt das Interessante: Die detaillierte Ausgabe von VTune. Man kann eleganterweise sogar zwei Durchgänge direkt in VTune vergleichen. Im sog. Bottum-Up findet man dann alle relevanten Funktionen aufgelistet (inkl. Herkunfts-Modul), zusammen mit der CPU-Zeit vom Prozess ohne Fenster, mit Fenster und mit der Differenz. Die komplette Tabelle ist als CSV im Anhang, hier möchte ich nur einen kurzen Ausschnitt anfügen, nämlich die zeitlich signifikantesten Funktionen.

    Function / Call Stack ModuleCPU Time: Difference CPU Time: HW+Stack, with window CPU Time: HW+Stack, without window
    PeekMessageW user32.dll2.21418 2.30831 0.0941345
    [wow64cpu.dll] wow64cpu.dll0.228307 0.229308 0.00100129
    func@0x410b30 calltester3.exe0.133167 0.20928 0.0761127
    func@0x6b101742 wow64cpu.dll0.0390594 0.0400607 0.00100125
    func@0x6b101cb0 wow64cpu.dll0.014992 0.0279829 0.0129908
    func@0x18000fcc0 wow64cpu.dll0.0149883 0.0149883 0
    func@0x40e5c4 calltester3.exe0.00900523 0.0210254 0.0120201
    func@0x40a000 calltester3.exe0.00899911 0.0570712 0.0480721

    Wer jetzt nicht selber rechnen mag: Die summierte Differenz entspricht 2,66 Sekunden - also quasi der kompletten Differenz der CPU-Zeiten der beiden Programmvarianten. Nun, was haben wir denn hier für Funktionen? Alle "func@..." aus dem Modul calltester3.exe (so heißt mein kompiliertes AutoIt-Programm) sind vermutlich interne AutoIt-Funktionen, die z.B. eine Skriptzeile interpretieren könnten, eine UDF aufrufen könnten... Was auch immer. Alle Funktionen, die zum Modul wow64cpu.dll gehören, sind vermutlich Teil der Win32-Abstraktionsschicht. Grundsätzlich arbeiten mittlerweile alle Windows-internen Funktionen als 64-bit Software. Damit vorhandene 32-bit Software weiterhin lauffähig bleibt, kommt diese Abstraktionsschicht zum Einsatz, die die 32-bit Funktionsaufrufe in 64-bit Funktionsaufrufe übersetzt. Und zu guter Letzt hätten wir unseren Hauptübeltäter: PeekMessageW aus der user32.dll. Wer's nicht weiß: Diese Funktion ist zum Verarbeiten von Thread- und Fenster-Nachrichten innerhalb der Win32-API. Das ist quasi die Funktion, die hinter AutoIts GUIGetMsg steht. Üblicherweise wird diese PeekMessage-Funktion immer und immer wieder in einer Schleife aufgerufen, um auf Interaktionen mit dem Fenster reagieren zu können.

    Dieser Test ist auf demselben System durchgeführt worden, wie der zwei Posts davor, also mit Windows 10 1904. Das ganze werde ich morgen mal noch auf einer Windows 7 Maschine machen. Und ich wette damit, dass PeekMessageW dann nicht mehr so viel Zeit frisst.

    Ins Blaue hineingeraten würde ich Mars' Begründung hier auch übernehmen. Irgendwas am Windows-Verhalten hat sich geändert, was die AutoIt-EXE dazu bringt, PeekMessageW unverhältnismäßig oft aufzurufen.

  • Mir hat es auch keine Ruhe gelassen, aber ich habe keine Lust auf externe Tools gehabt :D

    Das liefert sowas hier:

    Ist leider nicht ganz zuverlässig, da AutoIt manchmal "anhaltende" Ruckler die nur bestimmte Funktionen Betreffen (Ich schiele auf Sqrt(5) und Timerdiff(0)), sodass hier manchmal etwas schief läuft. Das übliche "ruckeln" habe ich versucht durch Medianbildung herauszufiltern. In den (Ergebnis)Mittelwert fließt jeweils nur der mittlere Wert von drei (Einzel)Werten ein (Spikes sollten somit abgefangen werden).

    Was man aber ganz klar erkennt: Es ist komplett egal WAS AutoIt ausführt, alles wird Pi mal Daumen um konstante 600ns verzögert. Bei "schnellen" Features macht das natürlich viel aus. Ich hatte ja gehofft eine Quantisierung in der Verlangsamung zu finden (Funktion 1 wird z.B. 2x Elementarverlangsamung langsamer, Funktion 2 wird nur 1x Elementarverlangsamung langsamer, usw. Aber im Endeffekt haben alle den gleichen Wert ;()