Debugging von Performance-Problemen

Diese Seite verwendet Cookies. Durch die Nutzung unserer Seite erklären Sie sich damit einverstanden, dass wir Cookies setzen. Weitere Informationen

  • Debugging von Performance-Problemen

    Ich bastle an einem ziemlich komplexen Projekt (geschrieben in Obj-C für MacOS X), das (fremde) Daten per XML einliest, in eine interne Datenstruktur (Hierarchie aus Objekten) umwandelt und dann anzeigt (und bearbeiten läßt - also ein CAD-System).
    Alles funktioniert soweit problemlos, bis auf die Geschwindigkeit. Das Einlesen eines größeren NSXMLDocuments dauert ca 0,5 Sekunden. Die Umwandlung ca. 10 Sekunden. Die Anzeige in einem CustomView dauert <0.3 Sekunden.
    Ein kommerzielles Programm zeigt die gleichen Daten in unter 1 Sekunde an.
    Die Frage ist nun, wie man das am besten debuggt.
    Bei Standard-C hätte ich cc -p und prof probiert, aber geht das für Obj-C?
    Ich habe bisher nicht mit Instruments gearbeitet und erste Versuche mit dem "Time Profiler" zeigen auch viel an, aber die Info hilft mir (noch) nicht herauszufinden, welche Methode besonders oft aufgerufen wurde. Also wo sich eine Optimierung lohnt.
    Wie geht Ihr bei solchen Themen vor?

  • torquato schrieb:

    Wie muß man sich dieses 'Umwandeln' vorstellen? Aus den xml-Daten werden Obj-C-Klasseninstanzen erzeugt und in NSArray's und NSDictionary's gespeichert?
    Im Prinzip ja. Die ObjC-Instanzen können wieder andere NSArray oder NSDictionary als Elemente haben, die manchmal aber nicht immer mit dem XML korrespondieren (ich habe das XML-Format halt nicht selber definieren können). Außerdem werden z.B. Koordinaten (units) umgerechnet und Stringkonstanten in enum-Werte usw. Alles so dass die Weiterverarbeitung (insbesondere das Drawing) effizienter wird.

    macmoonshine schrieb:

    Ich benutze den Time Profiler. Ich lasse ihn laufen und filtere die System-Libraries raus. Zum finden der Zeitfresser klappe ich im Baum immer die Knoten mit der größten Prozentzahl auf. In der Regel funktioniert das ganz gut.
    Ok, in diese Richtung gingen meine Experimente auch (universalmind.com/blog/what-ev…e-doing-with-instruments/). Dann stimmt die Richtung schon mal. Danke!

    Ich habe das jetzt vorhin mit der größten Prozentzahl (98%) mal aufgeklappt und komme dann (wenn ich auch da immer die größte %-Zahl nehme) zu einem Element mit 30%. Dort steht dann ein Element mit "Unknown Address". Dabei habe ich aber keine externen Libraries oder sowas. Alles pures Obj-C. Außerdem kommen manche Klassen (bei anderen %-Werten) mehrfach vor. D.h. der innersten Schleife komme ich noch nicht näher.

    Ich denke ich muß mir da erst mal klar machen, wie das Instruments überhaupt funktioniert. Das macht doch alle 1ms einen Stackauszug und versucht damit herauszufinden welche Methoden länger als 1ms aktiv bleiben? Dann könnte es sein dass das Performaceproblem durch extrem häufigen Aufruf von etwas passiert das einzeln weniger als 1ms braucht. An dem "extrem häufig" kann ich vermutlich nicht viel ändern weil es durch die Zahl der XML-Knoten vorgegeben sein dürfte...

  • Nach meiner Erfahrung sind die Zeitfresser NSXMLDocument und NSXMLParser.
    Hatte mal mit XML-Dateien im Bereich von 1MB bis 850 MB zu tun. Da hat die Umwandlung teilweise Minuten gedauert.
    Hab das dann auf SAX Parser umgestellt und erträgliche Zeiten erreicht.
    Apple hat einBeispiel dazu. developer.apple.com/library/co…e/Introduction/Intro.html

    Chris
    Man macht einfach solange irgendwelche Dinge, bis man tot ist.
    Und dann bekommen die anderen Kuchen.

  • Wir hatten es schon einmal, dass wir eine Software OOP totoptimiert hatten und dadurch Millionen von ganz kleinen Objekten initialisiert haben. Das war dann tatsächlich extrem langsam. Nachdem wir die Objekte wieder vergrößert und dementsprechend viel weniger instanzierungen im Code hatten, wurde es viel schneller.

    Gruß

    Claus
    2 Stunden Try & Error erspart 10 Minuten Handbuchlesen.

    Pre-Kaffee-Posts sind mit Vorsicht zu geniessen :)

  • Der xml-Parser scheint ja nicht das Problem zu sein, wenn er bei einer großen Datei bei 0.5 sec liegt.

    Mit Instruments kenne ich mich nicht aus.

    Ich würde vermuten, daß ein Großteil bei Speicherallozierung draufgeht. Ich würde erwarten, daß viel Zeit auf calls nach malloc und realloc verbraten wird. Viele einzelne NSObject-Instanzen sind teuer. Beim Befüllen von NSMutableArray muß der zugrundeliegende Buffer auch immer wieder vergrößert werden…

    Banale Objekte kann man natürlich auch als C-structs realisieren und damit gut was einsparen. Den Speicherplatz dafür kann man dann auch in einem Rutsch als C-Array anlegen…

    Das ist jetzt Rumgestochere meinerseits. Messen ist das A&O. Da kann ich aber wohl nicht wirklich weiter helfen.
    Das iPhone sagt: "Zum Antworten streichen". Wie? Echt Jetzt? Muß ich erst die Wohnung streichen!?

  • macmoonshine schrieb:

    Chris schrieb:

    Nach meiner Erfahrung sind die Zeitfresser NSXMLDocument und NSXMLParser.
    Hatte mal mit XML-Dateien im Bereich von 1MB bis 850 MB zu tun. Da hat die Umwandlung teilweise Minuten gedauert.
    Hab das dann auf SAX Parser umgestellt und erträgliche Zeiten erreicht.
    Äh, NSXMLParser ist ein SAX-Parser. ;)
    Stimmt, ich meinte das SAX-API der libxml2.
    Man macht einfach solange irgendwelche Dinge, bis man tot ist.
    Und dann bekommen die anderen Kuchen.

  • Chris schrieb:

    Nach meiner Erfahrung sind die Zeitfresser NSXMLDocument und NSXMLParser.
    Hatte mal mit XML-Dateien im Bereich von 1MB bis 850 MB zu tun. Da hat die Umwandlung teilweise Minuten gedauert.
    Hab das dann auf SAX Parser umgestellt und erträgliche Zeiten erreicht.

    Thallius schrieb:

    Wir hatten es schon einmal, dass wir eine Software OOP totoptimiert hatten und dadurch Millionen von ganz kleinen Objekten initialisiert haben. Das war dann tatsächlich extrem langsam. Nachdem wir die Objekte wieder vergrößert und dementsprechend viel weniger instanzierungen im Code hatten, wurde es viel schneller.

    torquato schrieb:

    Ich würde vermuten, daß ein Großteil bei Speicherallozierung draufgeht. Ich würde erwarten, daß viel Zeit auf calls nach malloc und realloc verbraten wird. Viele einzelne NSObject-Instanzen sind teuer. Beim Befüllen von NSMutableArray muß der zugrundeliegende Buffer auch immer wieder vergrößert werden…
    Leute, die Möglichkeiten sind vielfältig. Nur weil es bei euch mal so war, heißt dass ja nicht, dass es bei hns auch so ist. Ich hatte schon Fälle, wo ein einfacher C++-String-Vergleich einen Großteil der Zeit verbraten hat. Deswegen würde ich dem OP aber nicht raten, genau danach zu suchen.



    Thallius schrieb:

    2 Stunden Try & Error erspart 10 Minuten Handbuchlesen.
    Das trifft doch auch hier wieder genau zu. Instruments lernt man in einem Tag zu nutzen. Nach Speicherlecks kann man ohne Profiler hingegen wochenlang suchen.
    „Meine Komplikation hatte eine Komplikation.“

  • macmoonshine schrieb:

    Chris schrieb:

    Nach meiner Erfahrung sind die Zeitfresser NSXMLDocument und NSXMLParser.
    Hatte mal mit XML-Dateien im Bereich von 1MB bis 850 MB zu tun. Da hat die Umwandlung teilweise Minuten gedauert.
    Hab das dann auf SAX Parser umgestellt und erträgliche Zeiten erreicht.

    Thallius schrieb:

    Wir hatten es schon einmal, dass wir eine Software OOP totoptimiert hatten und dadurch Millionen von ganz kleinen Objekten initialisiert haben. Das war dann tatsächlich extrem langsam. Nachdem wir die Objekte wieder vergrößert und dementsprechend viel weniger instanzierungen im Code hatten, wurde es viel schneller.

    torquato schrieb:

    Ich würde vermuten, daß ein Großteil bei Speicherallozierung draufgeht. Ich würde erwarten, daß viel Zeit auf calls nach malloc und realloc verbraten wird. Viele einzelne NSObject-Instanzen sind teuer. Beim Befüllen von NSMutableArray muß der zugrundeliegende Buffer auch immer wieder vergrößert werden…
    Leute, die Möglichkeiten sind vielfältig. Nur weil es bei euch mal so war, heißt dass ja nicht, dass es bei hns auch so ist. Ich hatte schon Fälle, wo ein einfacher C++-String-Vergleich einen Großteil der Zeit verbraten hat. Deswegen würde ich dem OP aber nicht raten, genau danach zu suchen.


    Thallius schrieb:

    2 Stunden Try & Error erspart 10 Minuten Handbuchlesen.
    Das trifft doch auch hier wieder genau zu. Instruments lernt man in einem Tag zu nutzen. Nach Speicherlecks kann man ohne Profiler hingegen wochenlang suchen.

    Hat doch keiner BEhauptet das er nicht den Analyzer nehmen soll. Wir haben doch nur Tippps gegeben wonach er suchen kann.
    2 Stunden Try & Error erspart 10 Minuten Handbuchlesen.

    Pre-Kaffee-Posts sind mit Vorsicht zu geniessen :)

  • Thallius schrieb:

    Wir hatten es schon einmal, dass wir eine Software OOP totoptimiert hatten und dadurch Millionen von ganz kleinen Objekten initialisiert haben. Das war dann tatsächlich extrem langsam. Nachdem wir die Objekte wieder vergrößert und dementsprechend viel weniger instanzierungen im Code hatten, wurde es viel schneller.
    Welche Objekte ich brauche, ist durch den Anwendungsfall (und das XML-Format) vorgegeben. Wires, Circles, SMD-Pads, Bohrungen, Texte usw... Da kann ich keine weglassen oder zusammenfassen.

    Das XML-Parsing ist anscheinend auch nicht der große Zeitfresser. Und das kommerzielle Vorbild macht das ja exakt genauso, aber schneller (ist wahrscheinlich in Qt und C++ geschrieben).

    macmoonshine schrieb:

    hns schrieb:

    Ich habe das jetzt vorhin mit der größten Prozentzahl (98%) mal aufgeklappt und komme dann (wenn ich auch da immer die größte %-Zahl nehme) zu einem Element mit 30%.
    Kannst du aus dem umgebenden Code nicht darauf schließen, um welchen Code es sich handelt?
    Leider nicht. Die niedrigste Ebene die ich sehe enthält nur eine Schleife um die nächstniedrigere Ebene in Objekte zu packen und in NSArrays zu stecken. Es gibt allerdings auf unterester Ebene Mechanismen zum Caching und um bei Änderungen an CAD-Objekten einen setNeedsDisplay auszulösen. Dazu gehen sie den Objektbaum rekursiv nach oben. Falls die schon beim Laden getriggert werden und das viel Zeit brauchen sollte, dann könnte das ein Faktor sein. Muß aber nicht. Es reicht schon eine unnötige Suchschleife zwischen der obersten sichtbaren und der untersten Ebene, wenn man das besser per NSDictionary lösen könnte.
    Im Moment bin ich jetzt bei NSLog() und Zeitstempel anschauen ("was, das dauert 6ms von A nach B?"). Evtl. kann ich auch mit gettimeofday() arbeiten um µs sichtbar zu machen.
    Mir geht es ja auch hauptsächlich darum herauszufinden, wie man das Debugging in so einem Spezialfall am besten angeht. Instrument scheint mir da jetzt dann nicht genau genug hinzuschauen...

  • hns schrieb:

    Instrument scheint mir da jetzt dann nicht genau genug hinzuschauen...
    Eigentlich schon. Mit dem oben genannten String-Vergleich (und Map-Zugriff) hätte ich beispielsweise vor dem Profiling nicht gerechnet. Da habe ich erst durch Instruments gesehen, dass diese Code extrem häufig ausgeführt wird.

    Wenn er dir für bestimmten Code keine Symbole anzeigt, dann kann das eigentlich nur an den Objekt-Dateien liegen. Übersetzt du vielleicht Teile deines Codes anders (z. B. als eigenständiges Library-Projekt)?Instruments kann übrigens auch Symbole nach importieren, falls du die entsprechenden dSYM-Dateien hast.
    „Meine Komplikation hatte eine Komplikation.“

  • Also, ich bin mit klassischem Debugging etwas weitergekommen...

    Einfach

    Quellcode

    1. #define TIME_START() { NSDate *d1=[NSDate date], *d2;
    2. #define TIME_END(STR) ; d2=[NSDate date]; NSLog(@"%@: time=%lf", STR, [d2 timeIntervalSinceDate:d1]); }
    definiert und das vor und nach der kritischen Schleife eingebaut.

    Wenn man dann direkt danach einen Breakpoint setzt, kann man den Zeitbedarf für die gesamte Schleife im Xcode-Debugger-Log sehen.

    Zunächst hatte ich noch an einer Stelle einen NSLog() in der Schleife, so dass dessen Bearbeitungszeit signifikant dazukam. Ohne diesen NSLog() sowie einer anderen Optimierung lädt das Dokument in insgesamt 5 Sekunden.

    Bei meinem Problem stellt sich nun heraus dass der typische Aufbau eines bestimmten umgewandelten (Container-)Elements ca. 1-2 ms braucht, was etwas viel ist aber noch nicht schlimm erscheint. Nur wird diese Art Objekt für 219 Bauelemente aus einer Bibliothek erzeugt. Wären aber auch erst 219 ms.

    Aber ab und zu dauert es 15 ms und mehrmals über 60 ms und einmal über 100 ms um ein Element zu wandeln. Daher muß ich eher von einem Mittelwert von 5 ms ausgehen. Das wären schon merkbare 1,1 Sekunden für alle Elemente der Bibliothek. Dazu kommen aber noch weitere Schleifen um die in diesem Dokument vorhandenen 50 Seiten umzwandeln...

    So langsam wird erklärbar wo die hohe Umwandlungszeit herkommt.

    Das gibt mir jetzt mehrere Hinweise:
    a) anderer Ansatz: lazy loading (d.h. nicht alle 219 auf Vorrat übersetzen sondern nur bei erstmaligem Bedarf). Das löst das Problem zwar nicht wirklich, versteckt es aber vor dem Benutzer beim ersten Start
    b) herausfinden, warum das in diesem einen Fall über 100 ms dauert. Im Prinzip ist es klar: da wird ein komlexes Bauteil mit ca. 760 Unterelementen geladen. Wenn da jedes Unterelement "nur" 150 µs braucht kommen 114 ms raus.
    D.h. das Problem ist die hohe Datenmenge und dass die Übersetzung je Unterelement zu lange dauert.

    Ok, jetzt entwickelt sich das mehr in ein Fehlersuche-Blog als eine klassische Frage + Antwort :)

    Insofern bin ich auf dem richtigen Weg gelandet, ein Stück weiter gekommen und bedanke mich für alle Beiträge!

  • Naja, das führt aber zu nix.

    jetzt weißt du zwar dass das ganze soviel zeit kostet, aber nicht genau was denn nun darin die zeit verbraucht.
    der profiler zeigt dir das auf die zeile genau an.
    Es kann zb die erstellung eines strings sein, irgendwelche klassenerstellungen, irgendwelche langsamen funktionsaufrufe etc.

    Auf einem Durschnittsrechner parse ich hier etwa 100 MB große xml dateien und wandle sie in ein objektmodell um - und das in nichtmal 1 sekunde. Kommt natürlich auch immer aufs XML und dessen content an, aber 5 sekunden klingen für mich nach "da läuft was nicht ganz optimal"...

  • Thallius schrieb:

    Hat doch keiner BEhauptet das er nicht den Analyzer nehmen soll. Wir haben doch nur Tippps gegeben wonach er suchen kann.
    Gerade beim Profilen sollte man möglichst vorurteilslos herangehen. Also Programm an der kritischen Stelle laufen lassen, und sehen, was der Profiler als kritisch ansieht.

    Man soll ja den Schlüssel auch nicht nur da suchen, wo gerade Licht ist. ;)

    gritsch schrieb:

    Naja, das führt aber zu nix.
    Sehe ich auch so. Die 13 anderen Performance-Leaks bleiben damit weiter im Dunkeln.
    „Meine Komplikation hatte eine Komplikation.“

  • Also ich habe noch ein bischen mit Instruments gespielt, aber das hilft nicht wirklich weiter, weil es sich nicht auf eine einzelne Methode reduzieren läßt, die einen suboptimalen Algorithmus enthält. Und die Ausgabe von Instruments spiegelt im Wesentlichen den in Objekte übersetzten XML-Baum nach dem Laden wieder. Klar: der XML-Baum wird rekursiv umgewandelt und der Code steckt dann am längsten in der Schleife im obersten Element. Und am zweitlängsten in der zweitobersten usw.

    Die expliziten Zeitbedarfs-Messungen von Codeblöcken (die ich übrigens mehrfach auf verschiedenen Hierarchieebenen im Baum ansetzen kann so dass das durchaus weiter führt) war viel aufschlußreicher, aber auch nicht optimal. Ab und zu kommen nämlich Threads oder Hintergrundprozesse dazwischen, so dass die Messungen im µs-Bereich öfter mal ungenau und unplausibel werden. Damit kann man keine klaren Aussagen gewinnen.

    Dabei stellte sich aber schon heraus dass ein NSLog() im Xcode-Debugger nicht immer vernachlässigbar ist. Also habe ich alles NSLogging, das nichts mit den Timinigmessungen zu tun hat, ausgeschaltet. Aber wirklich weiter gekommen bin ich mit expliziten Zeitmessungen nicht.

    Daher habe ich den cc -p + prof-Ansatz (Zählen wie oft Methoden aufgerufen werden) von Hand gebastelt...

    Quellcode

    1. #define COUNT_ME(NAME) [_counter setObject:[NSNumber numberWithInt:[[_counter objectForKey:NAME] intValue]+1] forKey:NAME]
    2. #define COUNT_M() COUNT_ME(([NSString stringWithFormat:@"%@:%@", [self class], NSStringFromSelector(_cmd)]))
    Dazu muß man irgendwo den _counter als NSMutableDictionary definieren und in jeder relevanten und als kritisch gesehenen Methode COUNT_M(); setzen.

    Das sagt mir dann genau welche Methode wie oft insgesamt aufgerufen wurde, bis das Fenster aufgeht (da setzt man z.B. einen Breakpoint auf makeWindowControllers und macht dann einfach auf der Debugger-Kommandozeile "po _counter"). Das macht den Code zwar wieder signifikant langsamer, aber ich brauche hier ja erst mal nicht die Echtzeit zu messen weil ich wissen will welche Methoden extrem oft aufgerufen werden.

    Dann kann man überlegen ob die Zahl der Aufrufe bezogen auf die Daten verhältnismäßig ist oder nicht.

    Ein bischen Statistik. Die Testdaten sind:
    * ca. 5 MB XML
    * 86223 Zeilen XML (auf jeder Zeile steht genau 1 Tag)
    * daraus werden 63503 meiner Grafik-Objekte angelegt
    * Xcode braucht 12 Sekunden um die XML-Datei mit Syntax-Coloring zu öffnen - da sind <10 Sekunden incl. Grafik schon schneller, aber kommen nicht an das Vergleichstool heran

    Ich habe mit dieser Methode ein paar Stellen gefunden wo eine Rekursion durch den neu aufgebauten Baum (eine Art setNeedsDisplay-Mechanismus) unnötig weit lief. Hier kann man den Baum-Durchlauf beschneiden. Und alle Objekte rufen eine Methode "invalidateCaches" auf und zwar insgesamt ca. 600000 bis das Fenster erscheint... Und es werden ca. 400000 NSNotification versendet. Das ist zwar den Datenmengen halbwegs angemessen, aber vielleicht weiter optimierbar. D.h. damit habe ich die kritischen Stellen gefunden, die mir Instruments nicht angezeigt hat.

    Mit ersten Optimierungen habe ich die Zeit, bis das Fenster angezeigt wird, schon auf 3 Sekunden drücken können.

    Weitere Performance-Leaks kann man damit natürlich auch finden, sobald man danach sucht. Und das kann man machen sobald eine Funktion kritisch langsam erscheint.

  • trenne doch mal das laden und das grafische darstellen komplett.
    denn das laden kannst du dann parallel für mehrere xml files in verschienen threads durchführen.

    dann siehst du ja auch welcher der beiden teile viel zeit benötigt.

    NSLogs sollte man komplett verbannen aus zeitkritischem code denn die sind extrem langsam.

    du solltest eventuell auch auf NSNumber verzichten und anstelle dessen int, long etc verwenden (oder noch besser die typen die den passenden wertebereich im namen tragen: uint16_t zb).

    auch kannst du den parser einfach mal durchlaufen lassen ohne irgendwelche objekte zu erstellen. dann siehst du wie lang das allein dauert. dann machst du das gleiche und erstellst nur dummy-objekte ohne irgendwelchen werten etc.

    auch das string-zusammensetzen wird einiges an zeit und speicher benötigen.
    ich bevorzuge bei zeitkritischem code direkt libxml2 zu verwenden und erspar mir den apple-overhead den ich nicht wirklich brauche.

    falls die obj-c objekte die du erstellst zu langsam sind, kannst du die datenstruktur ja auch in C++ aufbauen - lässt sich ja einfach mit obj-c mixen.