Ich habe ein Perl-Skript, das ungefähr 30 Minuten zum Ausführen benötigt, also laufe ich natürlich Devel: NYTProf. Großer Profiler. Für viele meiner Subs bekomme ich Daten, die für mich keinen Sinn ergeben.
Ich laufe mit Perl 5.10.0 auf Linux unter Verwendung der NYTProf-Standardeinstellungen.
In der HTML-Ausgabe hat jeder der Subs einen zusammenfassenden Abschnitt, der angibt, wie viel Zeit in dem Subcomputer und seinen untergeordneten Elementen verbracht wird, und gibt mir dann Leitungsinformationen.
Die Zeilenstatistik addiert sich nicht zum Gesamtwert der Funktion. Was gibt?
Zum Beispiel habe ich eine Funktion, die 233s verwendet (57 + 166). Der Zeile-für-Zeile-Nummernbericht hat eine Zeile, die 20 verwendet, eine andere, die 4 verwendet und eine, die 2 verwendet. Die anderen Zeilen sind & lt; 1s und die Funktion ist nicht so lang.
Was kann ich tun, um diese Diskrepanz zu beheben?
Ich könnte zu Perl 5.12 wechseln, aber das würde einige Arbeit erfordern, um die Abhängigkeiten zu installieren. Ich bin froh, es in einem langsameren Modus zu betreiben. Gibt es eine Möglichkeit, die Abtastfrequenz zu erhöhen? Auf einer langsameren Maschine laufen?
Klicken Sie hier für ein Beispiel: meine NYTProf-Ausgabe . In diesem Fall meldet das Subsystem 225 Sekunden, aber das Hinzufügen aller Zahlen ergibt 56 Sekunden. In diesem Lauf wurde die Optimierung deaktiviert:
%Vor%Update Ich habe Perl 5.12 erneut mit dem Flag findcaller = 1 wie vorgeschlagen mit mehr oder weniger gleichen Ergebnissen ausgeführt. (Ich lief auf einem anderen Datensatz)
Update Tim B ist richtig. Ich habe einige meiner Schlüsselsubs geändert, um Caching selbst vorzunehmen, anstatt memoize zu verwenden, und die NYTProf-Ergebnisse sind wieder nützlich. Danke Tim.
Ich habe dies gerade zur NYTProf-Dokumentation hinzugefügt:
= head2 Wenn Anweisung und Unterprogramm-Timings nicht übereinstimmen
NYTProf hat zwei Profiler: eine Aussage Profiler, der bei Perl aufgerufen wird bewegt sich von einer Perl-Anweisung zu ein anderer und ein Unterprogramm Profiler das wird aufgerufen, wenn Perl Aufrufe oder kommt von einer Subroutine zurück.
Die einzelnen Statement Timings für a Subroutine summieren sich normalerweise zu etwas weniger als die exklusive Zeit für die Subroutine. Das ist, weil die Behandlung des Unterprogrammaufrufs und Rücklaufkosten sind im Preis enthalten exklusive Zeit für das Unterprogramm. Das Unterschied kann nur ein neues sein Mikrosekunden, aber das kann werden bemerkbar für Subroutinen, die sind Hunderttausende Male genannt.
Der Anweisungsprofiler verfolgt, wie viel Zeit wurde für Gemeinkosten aufgewendet Statement-Profil-Daten schreiben zu Scheibe. Der Unterprogramm-Profiler subtrahiert die Gemeinkosten, die haben akkumuliert zwischen Eingabe und Verlassen des Unterprogramms um geben Sie ein genaueres Profil. Das Statement Profiler ist in der Regel sehr schnell, weil die meisten Schreibvorgänge gepuffert werden Für Zip-Komprimierung also der Profiler Overhead pro Aussage ist tendenziell sehr klein, oft ein einziger "Tick". Das Ergebnis ist, dass die angesammelt Overhead ist ziemlich laut. Das wird signifikanter für Subroutinen, die werden häufig genannt und sind auch schnell. Dies kann ein anderer, kleiner sein, Beitrag zur Diskrepanz zwischen Aussagezeit und Exklusivität mal.
Das erklärt wahrscheinlich den Unterschied zwischen der Summe der Anweisungszeitspalte (31.7s) und der exklusiven Zeit, die für das Unterprogramm (57.2s) berichtet wird. Der Unterschied beträgt etwa 100 Mikrosekunden pro Anruf (was ein wenig hoch erscheint, aber nicht unvernünftig).
Der Statement-Profiler verfolgt, wie viel Zeit für Gemeinkosten aufgewendet wurde, z. B. das Schreiben von Statement-Profildaten auf die Festplatte. Der Subroutinen-Profiler subtrahiert den Unterschied in den Gemeinkosten zwischen dem Eintritt und dem Verlassen des Unterprogramms, um ein genaueres Profil zu erhalten.
Der Statement-Profiler ist im Allgemeinen sehr schnell, da die meisten Schreibvorgänge für die ZIP-Komprimierung gepuffert werden, so dass der Profiler-Overhead pro Anweisung sehr klein ist, oft ein einzelner "Tick". Das Ergebnis ist, dass der akkumulierte Overhead ziemlich laut ist. Dies wird für Subroutinen von Bedeutung, die häufig aufgerufen werden und auch schnell sind (in diesem Fall 250303 Aufrufe bei 899 us / Aufruf). Ich vermute also, dass dies ein weiterer, kleinerer Beitrag zur Diskrepanz zwischen Aussagezeit und exklusiven Zeiten ist.
Noch wichtiger, ich habe diesen Abschnitt auch hinzugefügt:
= head2 Wenn Headline-Unterprogramm-Timings nicht mit den aufgerufenen Subs übereinstimmen
Gesamt-Unterprogrammzeiten werden gemeldet mit einer Überschrift wie "verbrachte 10s (2 + 8) innerhalb ... ". In diesem Beispiel 10 Sekunden wurden in der. verbracht Unterprogramm (die "inklusive Zeit") und Davon wurden 8 Sekunden in Unterroutinen, die von diesem aufgerufen werden. Das lässt 2 Sekunden wie die Zeit in der Unterprogrammcode selbst (der "exklusive Zeit", manchmal auch die "Selbstzeit" genannt).
Der Bericht zeigt den Quellcode von das Unterprogramm. Leitungen, die Anrufe tätigen zu anderen Unterprogrammen werden kommentiert mit Details zur Zeit in diese Anrufe.
Manchmal ist die Summe der Zeiten für Anrufe durch die Codezeilen in der Subroutine ist kleiner als die inklusive exklusive Zeit berichtet in die Schlagzeile (10-2 = 8 Sekunden in der Beispiel oben).
Was hier passiert ist, dass Anrufe an andere Subroutinen werden aber gemacht NYTProf ist nicht in der Lage, die Rufen Sie den Standort richtig an, damit der Anrufe erscheinen nicht im Bericht in der richtige Ort.
Eine alte Version von Perl ist eine cause ( siehe unten ). Ein anderer ruft an Unterroutinen, die über "goto & amp; sub; "- am häufigsten anzutreffen in AUTOLOAD Subs und Code mit dem Memoize Modul.
Im Allgemeinen die gesamte Subroutine Timing ist genau und sollte sein vertraut mehr als die Summe der Aussage oder verschachtelte Sub-Timings.
Das Memoize-Modul ist in erster Linie die Ursache für die Diskrepanz in Ihrem Bericht. Die Aufrufe von Memoize::__ANON__[...] führen einen von Memoize generierten Teil aus, der wie sub { unshift @_, $cref; goto &_memoizer; } aussieht. Das goto &_memoizer wird von Perl als eine Art Rückkehr zum Aufrufer implementiert, gefolgt von einem Aufruf des angegebenen Subs, und auf diese Weise profiliert NYTProf es.
Die Verwirrung wird durch die Tatsache verursacht, dass, obwohl add_bit_to_map als der Aufrufer von _memoizer aufgezeichnet wird, so dass die Zeit in dem Anruf zu add_bit_to_map hinzugefügt wird, die Datei- und Zeilennummerstelle des Anrufs aufgezeichnet wird als Speicherort für goto .
Es könnte möglich sein, dies in einer zukünftigen Version zu verbessern.
Danke, dass Sie mich aufgefordert haben, dies zu untersuchen und die Dokumentation zu verbessern.
Tim Bunce.
ps. Ich empfehle, Fragen zu NYTProf in der Mailingliste zu stellen.
Versuchen Sie, Perl's Optimizer zu deaktivieren. Aus CPANs Devel :: NYTProf-Dokumenten :
optimieren = 0
Deaktivieren Sie den Perl-Optimierer.
Standardmäßig verlässt NYTProf Perls Optimierer aktiviert. Das gibt dir mehr Genaues Profil Timing insgesamt, aber kann zu ungeraden Kontoauszügen führen einzelne Sätze von Linien. Das ist weil der Peephole-Optimierer der Perl hat das neu geschrieben Aussagen, aber Sie können nicht sehen, was neu geschriebene Version sieht aus wie.
Zum Beispiel:
%Vor%so das Profil zeigt keine Anweisungsanzahl für die Zeile an 2 in Ihrem Quellcode, weil die Rückkehr wurde in das if verschmolzen Aussage zur vorhergehenden Zeile.
Die Option optimize = 0 wird deaktiviert der Optimierer, damit Sie niedriger werden Gesamtleistung aber mehr genau zugeordnete Anweisung zählt.
Wenn Sie andere Beispiele für die finden Auswirkung des Optimierers auf die NYTProf-Ausgabe (außer Leistung, offensichtlich) Bitte lass es uns wissen.