Ladezeiten von Modulen ermitteln

[freimatz]

Ich bin gerade dabei die Ladegeschwindigkeit von Programmen (konkret hier unit tests) zu beschleunigen. Nach dem Toolwindow "Events" werden da hunderte von Modulen (Packages, DLLs) geladen. Gibt es da eine Möglichkeit festzustellen wie lange ein Modul benötigt? Im Toolwindow selber habe ich keine Option gesehen dass man da ein Zeitstempel mit ausgeben lassen könnte. Andere Ideen?

[juergen]

Ich hoffe dich richtig verstanden zu haben (das zeitliche Programmstartverhalten eines Delphi Projektes zu analysieren)

Es gibt verschiedene Delphi-Pofilingtools. Empfehlen kann ich nexus quality suite Da gibt es auch immer wieder mal Aktionen…

[freimatz]

Jein.
Erstmal danke für den Hinweis auf die Suite. Ich frage da nach.
Mir geht hier nun eher um das Ladeverhalten von ganzen Packages und nicht um allgemein.
Wenn ich wo einen Breakpoint setzten könnte dann könnte ich dort auch selber ein Messung einfügen. Wenn ich aber in einer unit nach initialization was einfüge hält der Debugger dort nicht an, obwohl das Package laut Event-Log geladen wird.
Laut dieser Doku gibt es etwas, das geht aber nur für das delayed loading.

[TiGü]

Für einen ersten Schuss würde ich den Process Monitor von www.sysinternals.com nehmen und als Filter:

Process Name is DeinProgrammName.exe

Dann haste sowohl absoluten Zeitstempel als auch die Dauer des Ladevorgangs.
Die wahrscheinlich zahlreichen Reg*Key, Reg*Value kann man dann noch exkludieren und erhält wahrscheinlich einen guten Überblick.
Außerdem kann man über den Filter-Dialog oder über die Highlight-Option noch

Duration more than 0.00123 (oder sonstigen Wert) nach großen Zeitfressern suchen.

Beispiel für den Start der BDS.exe, wo ein Vorgang mehr als 0.00001 ms Duration hat (letzte Zahl in einer Zeile):

Code:

12:05:55,4283517   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\winmmbase.dll   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.5845030   0.0011584
12:05:55,4283548   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\winmmbase.dll   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.5845061   0.0012563
12:05:55,4977701   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Users\Public\Documents\Embarcadero\Studio\22.0\Bpl\JvPrintPreview280.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.6539214   0.0009348
12:05:55,5570448   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Users\Public\Documents\Embarcadero\Studio\22.0\Bpl\JvTimeFrameworkDesign280.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.7131961   0.0009376
12:05:55,5945072   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\fs28.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.7506585   0.0018888
12:05:55,5945082   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\frx28.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.7506595   0.0018197
12:05:55,6445470   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\frxDB28.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.8006983   0.0011249
12:05:55,6445573   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\fsDB28.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.8007086   0.0011690
12:05:55,6700970   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\fsTee28.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.8262483   0.0010374
12:05:55,6701007   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Windows\SysWOW64\frxTee28.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.8262520   0.0011078
12:05:55,7641417   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Program Files (x86)\FixInsight\FixInsight_11.bpl   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.9202930   0.0012905
12:05:55,7679197   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Program Files (x86)\FixInsight\FixInsight.Services.dll   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:09.9240710   0.0009579
12:05:57,5400987   bds.exe   9908   IRP_MJ_CREATE   C:\Program Files (x86)\Embarcadero\Studio\22.0\bin\Borland.Studio.Interop.resources.dll   SUCCESS   Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened   00:00:11.6962500   0.0014711
12:05:57,8008141   bds.exe   9908   IRP_MJ_CREATE   C:\program files (x86)\embarcadero\studio\22.0\SystemResources\dclCloudService280.bpl.mun   PATH NOT FOUND   Desired Access: Read Data/List Directory, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a   00:00:11.9569654   0.0031073
12:05:58,1691016   bds.exe   9908   IRP_MJ_CREATE   C:\Program Files (x86)\Embarcadero\Studio\22.0\bin\Borland.Studio.Refactoring.dll   SUCCESS   Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened   00:00:12.3252529   0.0089969
12:05:58,1937933   bds.exe   9908   IRP_MJ_CREATE   C:\Users\Nachname\AppData\Roaming\DDevExtensions\CompileInterceptorW.dll   SUCCESS   Desired Access: Read Data/List Directory, Execute/Traverse, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened   00:00:12.3499446   0.0138205
12:05:58,2076338   bds.exe   9908   FASTIO_ACQUIRE_FOR_SECTION_SYNCHRONIZATION   C:\Users\Nachname\AppData\Roaming\DDevExtensions\CompileInterceptorW.dll   FILE LOCKED WITH ONLY READERS   SyncType: SyncTypeCreateSection, PageProtection: PAGE_EXECUTE_READWRITE   00:00:12.3637851   0.0018315
12:05:58,3865149   bds.exe   9908   IRP_MJ_CREATE   \\EinNetzwerkPfad\Nachname\Eigene Dateien\CnWizards\PreDefSymbols.xml   SUCCESS   Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, AllocationSize: n/a, OpenResult: Opened   00:00:12.5426662   0.0065452
12:05:58,3931059   bds.exe   9908   IRP_MJ_READ   \\EinNetzwerkPfad\Nachname\Eigene Dateien\CnWizards\PreDefSymbols.xml   SUCCESS   Offset: 0, Length: 63.802, Priority: Normal   00:00:12.5492572   0.0017884
12:05:58,3931543   bds.exe   9908   IRP_MJ_READ   \\EinNetzwerkPfad\Nachname\Eigene Dateien\CnWizards\PreDefSymbols.xml   SUCCESS   Offset: 0, Length: 63.802, I/O Flags: Non-cached, Paging I/O, Priority: Normal   00:00:12.5493056   0.0017178
12:05:58,5095431   bds.exe   9908   IRP_MJ_CREATE   \\EinNetzwerkPfad\Nachname\Eigene Dateien\CnWizards\XmlComment.xml   SUCCESS   Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, AllocationSize: n/a, OpenResult: Opened   00:00:12.6656944   0.0031091
12:05:58,5126929   bds.exe   9908   IRP_MJ_READ   \\EinNetzwerkPfad\Nachname\Eigene Dateien\CnWizards\XmlComment.xml   SUCCESS   Offset: 0, Length: 8.503, Priority: Normal   00:00:12.6688442   0.0012263
12:05:58,5127246   bds.exe   9908   IRP_MJ_READ   \\EinNetzwerkPfad\Nachname\Eigene Dateien\CnWizards\XmlComment.xml   SUCCESS   Offset: 0, Length: 8.503, I/O Flags: Non-cached, Paging I/O, Priority: Normal   00:00:12.6688759   0.0011800
12:05:58,9292682   bds.exe   9908   IRP_MJ_CREATE   C:\Program Files (x86)\Embarcadero\Studio\22.0\bin\Borland.Studio.ToolsAPI.dll   SUCCESS   Desired Access: Generic Read, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Delete, AllocationSize: n/a, OpenResult: Opened   00:00:13.0854195   0.0258449

[himitsu]

Mit "Modulen" ist hier wohl eher "Forms" gemeint.

[TiGü]

Zitat:

Zitat von himitsu (Beitrag 1517294)

Mit "Modulen" ist hier wohl eher "Forms" gemeint.

Zitat:

Zitat von freimatz (Beitrag 1517229)

...hunderte von Modulen (Packages, DLLs) geladen.

:roll:

[juergen]

Nexus Quality Suite kann nicht nur Methoden protokollieren.
Auszug von der Webseite zu dem Teilmodul "Coverage Analyst" dieser Suite :

Zitat:

Das CoverageAnalyst-Tool hilft Ihnen, die Teile Ihres Codes, die nicht vollständig ausgeführt werden, visuell zu identifizieren. Mit Quality Suite CoverageAnalyst können Sie bessere und effektivere Testfälle erstellen.

Die wichtigste Verwendung eines Abdeckungsanalysators besteht darin, sicherzustellen, dass alle Teile eines Moduls (Anwendung, DLL, COM-Objekt usw.) während des Tests ausgeführt wurden. Viel zu viele Programme werden mit Fehlern veröffentlicht, die der Erkennung während der Qualitätssicherungsphase entgehen, einfach weil der anstößige Code nie ausgeführt wird. Quality Suite CoverageAnalyst hilft sicherzustellen, dass alle Teile des Programms ausgeführt wurden.

Es gibt auch eine Testversion.
Vllt. hilft dir das auch weiter.

[Stevie]

Zitat:

Zitat von juergen (Beitrag 1517299)

Coverage Analyst

Coverage Analyst ist leider komplett am Thema vorbei, da das für CodeCoverage ist: "welche Codezeilen wurden wie oft ausgeführt"

Ich würde auch spontan zum ProcMon Einsatz raten, da es um das Laden von Bibliotheken geht.
Da du vom Toolwindow und den Events darin sprachst nehme ich an, dass du deine Anwendung im Debugger laufen lässt - jegliche Performance in diesem Szenario ist komplett zu ignorieren. Der Debugger hängt an zahlreichen Events, die das ganze massive verlangsamen können. Beim ProcMon Einsatz also am besten ohne Debugger starten.

[freimatz]

Zitat:

Zitat von TiGü (Beitrag 1517292)

Für einen ersten Schuss würde ich den Process Monitor von www.sysinternals.com nehmen ...

:wall: ah na klar. Warum bin ich da nicht selber drauf gekommen. Danke.

@Coverage ist gerade jetzt nicht das Thema. Aber trotzdem Danke. Eine funktionierende Coverage kann ich auch brauchen.

@Stevie: gerade dieses Szenario interessiert mich aber: TDD. Ich mache eine Änderung am Test- oder Produktivcode und will grün oder rot sehen. Wenn das dann jedesmal 30 Sekunden dauert macht TDD keinen Spass.
(Exceptions treten beim Laden nicht auf)

[himitsu]

OK, hab'sch irgednwie übersehn.

Wenn es statisch gelinkte DLLs sind, dann wird es schwer,
denn die werden ja geladen, bevor ein Code von deiner EXE ausgeführt wird.

Bei LoadLibrary kann man von vorher zu nachher die Zeit messen.
Manuell oder man hookt den Aufruf.


Extern messen, z.B. mit dem ProcessExplorer ober über's WindowsSystem-Log (live oder gespeichert) ginge auch.


Als Debugger würde man über's Laden informiert, aber sich als Debugger an sich selbst zu hängen ist keine gute Idee.

Im Programm gibt es zwei NotificationsAPI von Windows, wo man über's Laden von DLL/BPL informiert wird,
aber Messen geht da nicht direkt. Sie geben aber zurück was "gerade eben" geladen wurde.
(leider gibt es kein Event für "ich werde jetzt anfangen zu Laden")

Nja, man könnte zumindestens die Zeit zum letzten Event messen und hätte dann in etwa die Zeit für die soeben geloggte DLL.


Bei uns hab ich es nur als Fortschrittsanzeige genommen, ähnlich wie bei Delphi im Splashscreen.
Mit der "alten" API LdrRegisterDllNotification sieht man zumindestens was zuletzt geladen wurde. (die Neue wird dringend empfohlen, aber die Alte ist wesentlich einfacher)

Schöner wäre es zwar, wenn man sieht was gerade lädt und wo es sozusagen derzeit hängt, aber besser als nichts, wenn das Laden mal wieder ewig dauert.