View Issue Details

IDProjectCategoryView StatusLast Update
0000214Adventure PHP FrameworkCode-Verbesserung // Code improvementpublic2016-03-22 14:58
ReporterdingsdaAssigned ToChristianAchatz 
PrioritynormalSeverityfeatureReproducibilityN/A
Status resolvedResolutionfixed 
Product Version2.1 
Target Version3.2Fixed in Version3.2 
Summary0000214: Verbesserung des BenchmarkTimers
Descriptionwas ich mir so als verbesserung vorgestellt hab sind folgende sachen:

1. der parameter bei start() und stop() soll optional werden.
    * hab das schon fast fertig und funktioniert bisher soweit schon ganz gut. in 95% der anwendungsfälle wird der Timer ja innerhalb einer Methode gestartet und beendet. daher holt sich der timer bei mir die information einfach aus debug_backtrace. auch das starten eines kindprozesses ist problemlos in der selben methode möglich. nur wenn start und ende nicht in der selben Methode liegen, muss eine eindeutige ID angegeben werden. oder wenn man zusätlich noch nen namen nutzen will, der genauer beschreiben, was gemessen wird.
2. möglichkeit für andere gruppierung der prozesse im report (hier schonmal angesprochen: http://forum.adventure-php-framework.org/viewtopic.php?f=10&t=990)
Sinnvoll wären hier glaube ich follgende Gruppierungen
    * gruppierung nach Methodennamen (abhängig oder auch unnabhäng vom Klassennamen)
    * oder gruppierung nach dem parameter der in start() übergeben wurde.
    * zusätzlich sollte man noch angeben können, ob innerhalb des elternprozesses gruppiert wird oder über alle prozesse
3. benchmarkTimer nur für bestimmte prozesse aktivieren
    * das find ich wichtig, wenn man z.b. die ablaufzeit einer methode messen will, welche widerum x methoden aufruft, die selbst auch den BenchmarkTimer nutzen. da jeder start und stop des timers schon performance kostet kann man nicht wirklich die zeit messen, die die äußere methode braucht, weil man immer die zeit + x-mal zeit von start/stop. hier behelfe ich mir aktuell immer mit microtime() oder in dem ich den timer nach dem dem start abschalte und vor dem stop wieder anschalte. aber das ist eigentlich nervig, gerade, wenn ich z.b. in einem branch etwas änder und mit der früheren version der methode vergleichen möchte. dann muss ich in beiden branches die messund ändern. so nur in der index
    * möglich wäre hier auch wieder die angabe der methodennamen oder des parameters in start
Tagsbenchmark
Codereferenz: ([Datei]:[Zeile])
Namespacecore

Activities

ChristianAchatz

2014-06-29 14:23

administrator   ~0000420

Hi dingsda,

zu 1):
debug_backtrace() halte ich für eine problematische Lösung, da debug_backtrace() nicht besonders schnell ist und damit auf die Performance Auswirkung hat. Der BenchmarkTimer läuft bei jedem Request und in sehr vielen kleinen Prozess-Schritten, da ist Performance unglaublich wichtig.

Was ich mir vorstellen könnte wäre eine etwas andere API:

<snip>
$t = &Singleton::getInstance('APF\core\benchmark\BenchmarkTimer');

$timer = &$t->start('foo');

...

$timer->stop();
</snip>

Damit kannst du dir das zweimalige Übergeben der ID sparen.

zu 2):
Hierzu hatte ich mir in der Vergangenheit auch mal Gedanken gemacht. Die Implementierung dazu (sprich den Report zu generieren) ist nicht ganz trivial. Daher habe ich das zu Gunsten der Verfügbarkeit der xdebug-Tracking-Komponente gelassen. Dort kannst du (natürlich auch mit etwas Overhead) sehr genau sehen, welche Methoden wie lange benötigt haben. Die Heatmaps dort inkl. drill-down-Feature sind einfach zu gut, als dass ich das nachbauen wollen würde. Insofern ist der BenchmarkTimer bisher eine einfache aber immer verfügbare Komponente gewesen, die man auch im Live-Betrieb laufen lassen konnte ohne zu großen Overhead zu generieren aber gleichzeitig eine Detail-Information zu den Rendering-Zeiten zu haben.

zu 3):
Hinsichtlich des Overheads möchte ich dafür plädieren, die Implementierung auch weiterhin so einfach wie möglich zu halten. Sicher ist die Messung mit dem BenchmarkTimer nicht immer 100% akkurat, das ist sie mit einem xdebug-Tracking-Feature aber auch nicht. Insofern geht es meiner langjährigen Erfahrung nach auch nicht darum, 100% korrekte Werte zu haben, sondern eine gut ermittelte Größenordnung. Braucht ein Prozess 5s oder 50ms, weiß ich seht gut ob ich handeln muss oder nicht. Sind es statt 50ms nur 48 oder 52ms, ist das zwar absolut betrachtet eine Abwichung von 0000033:0000004%, relativ zu 5s betrachtet jedoch (ingenieursmäßig) absolut vernachlässigbar.

Was für mich ebenfalls gegen eine Bestrebung möglichst genaue absolute Zahlen zu erhalten spricht ist die Tatsache, dass jeder Request anderen Gegebenheiten unterliegt und daher ohnehin nie eine absolut korrekte Messung möglich ist. Mal läuft gerade der Virenscanner, mal der Garbage-Collector, mal ist die Netzwerkkarte gerade mit einem großen Paket beschäftigt und deines wird leicht verzögert. Das sind alles Dinge, die den Determinismus deiner Messung beeinflussen.

dingsda

2014-06-29 18:24

reporter   ~0000421

zu 1) im vergleich zu dem get_class($this) was aktuell fast überall aufgerufen wird, wo der benchmarktimer dann genutzt wird ist debug_backtrace nicht wirklich langsamer. der unterschied ist minimal, wenn er überhaupt vorhanden sein sollte. das zumindest zeigt mir grad ein kurzer test.
im gegensatz zu get_class($this) würde debug_backtrace aber nur aufgerufen werden, wenn der benchmarktimer überhaupt aktiviert ist.
so oder so ist der benchmarktimer aber auch nicht wirklich ein tool, dass man im produktivbetrieb anlassen würde. es macht immerhin doch 25% der performance aus. und wenn man ihn anlässt, dann macht es einem wohl nicht so viel aus, ob die performance nun 25% oder 26% schlechter ist.

dein vorschlag mit der anderen api klingt auch nicht schlecht. hatte ich auch irgendwo im forum schonmal gelesen.

zu 2) ich hab mich noch nicht richtig damit befasst, wie schwierig es werden könnte, das umzusetzen auf den ersten blick schien es zumindest machbar.
Ich hatte mir mal die möglichkeiten von xdebug angeschaut gehabt, aber entweder hab ich da nicht die richtigen tools für gefunden oder es ist wirklich nicht ganz das was ich gerne hätte. zumal der overheap mit xdebug nicht grad gering ist, da dort dann wieder wirklich jeder funktionsaufruf getrackt wird.

zu 3) ich glaube nicht wirklich, dass es ein overheap ist, was ich mir vorstelle.
am anfang der index einfach ein
$t->setMode(TRACK_SOME);
$t->addTrackingProcesses(array('bla','foo'));
oder ähnliches (namen sind nicht so mein ding :D ) und im benchmarktimer dann die prüfung mit isset(...) falls er überhaupt enabled und im mode TRACK_SOME läuft.

mir geht es bei punkt 3 auch nicht nur, um die zusätzliche zeit, die das benchmarking selbst braucht, sondern auch um die übersicht beim report. also ähnlich wie feature 2. angenommen ich entwickel eine neue klasse/methode, die an viele stellen aufgerufen wo schon der benchmarktimer läuft wird und ihrerseits noch andere methoden aufruft, die selbst auch noch mal den benchmarktimer aufrufen. es sind apf-methoden oder schon getestete methoden, daher weiß ich, dass die alle so laufen wie sie sollen. nun ruf ich dort den benchmarktimer auf und darf dann überall im report suchen, wo meine methode/klasse ist. würde ich mit einer option am anfang der index einstellen können, dass mich gerade nur eine einzige methode oder klasse interessiert sieht der report schon ganz anders aus.

ChristianAchatz

2014-06-29 21:59

administrator   ~0000422

Danke für deine weiteren Analysen.

Bin jetzt 2 Tag unterwegs, danach schaue ich mir das Thema nochmal an Hand der Implementierung und deinen Vorschlägen in Ruhe an. Kann mir grade noch nicht 100%-ig vorstellen, wie Implementierung, Anwendung und Report mit deinen weiteren Vorschlägen aussehen sollen.

Danke für dein Engagement! :)

dingsda

2014-07-01 21:31

reporter   ~0000426

Du kannst auch einfach abwarten, bis ich was funktionierendes fertigstelle und vorzeige. wenns ne performance-bremse ist bauen wir es nicht ins APF ein. wenn ich sehe, dass es überhaupt nicht machbar ist wirds auch gelassen.

ChristianAchatz

2014-07-02 19:37

administrator   ~0000430

OK, bin gespannt auf dein Ergebnis! :)

ChristianAchatz

2015-03-07 13:41

administrator   ~0000549

Moved to 3.1 to be able to release 3.0 soon.

ChristianAchatz

2015-09-05 17:14

administrator   ~0000604

@dingsda: magst du dir das Thema nochmal ansehen?

ChristianAchatz

2015-09-05 17:14

administrator   ~0000605

Moved to 3.2 to shape scope for 3.1.

ChristianAchatz

2016-03-14 00:28

administrator   ~0000688

Created alternative implementation w/o hierarchy model. Performance optimisation ~ 50% faster for 10000 subsequent calls of start() and stop().

xdebug analysis shows 3.2s vs. 0.6s call duration within real-life application (APF web site). In total, 6.8s vs. 2.1s overall time is a significant improvement.

Code can be seen under https://github.com/AdventurePHP/code/commit/a2a49163a577c78b26b8e35cb6b30781850bc465. Will be integrated into master after refactoring and creation of migration scripts.

ChristianAchatz

2016-03-16 23:20

administrator   ~0000689

Implementation done and merged to master. Documentation to be updated.

ChristianAchatz

2016-03-22 14:58

administrator   ~0000690

Documentation updated thus closing.

Issue History

Date Modified Username Field Change
2014-06-26 21:24 dingsda New Issue
2014-06-26 21:24 dingsda Status new => assigned
2014-06-26 21:24 dingsda Assigned To => dingsda
2014-06-26 21:28 dingsda Namespace none => core
2014-06-26 21:28 dingsda Description Updated View Revisions
2014-06-26 21:28 dingsda Tag Attached: benchmark
2014-06-26 21:34 dingsda Description Updated View Revisions
2014-06-29 14:23 ChristianAchatz Note Added: 0000420
2014-06-29 18:24 dingsda Note Added: 0000421
2014-06-29 21:59 ChristianAchatz Note Added: 0000422
2014-07-01 21:31 dingsda Note Added: 0000426
2014-07-02 19:37 ChristianAchatz Note Added: 0000430
2015-03-07 13:41 ChristianAchatz Note Added: 0000549
2015-03-07 13:41 ChristianAchatz Target Version 3.0 => 3.1
2015-09-05 17:14 ChristianAchatz Note Added: 0000604
2015-09-05 17:14 ChristianAchatz Note Added: 0000605
2015-09-05 17:14 ChristianAchatz Target Version 3.1 => 3.2
2016-03-14 00:28 ChristianAchatz Note Added: 0000688
2016-03-14 00:28 ChristianAchatz Assigned To dingsda => ChristianAchatz
2016-03-16 23:20 ChristianAchatz Note Added: 0000689
2016-03-22 14:58 ChristianAchatz Note Added: 0000690
2016-03-22 14:58 ChristianAchatz Status assigned => resolved
2016-03-22 14:58 ChristianAchatz Fixed in Version => 3.2
2016-03-22 14:58 ChristianAchatz Resolution open => fixed