Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > de.comp.lang.php > #3923 > unrolled thread

xdebug

Back to article view | Back to de.comp.lang.php

Contents

  xdebug Stefan+Usenet@Froehlich.Priv.at (Stefan Froehlich) - 2016-07-13 16:08 +0000
    Re: xdebug "Christoph M. Becker" <cmbecker69@arcor.de> - 2016-07-14 03:16 +0200
      Re: xdebug Stefan+Usenet@Froehlich.Priv.at (Stefan Froehlich) - 2016-07-14 09:13 +0000
        Re: xdebug Stefan+Usenet@Froehlich.Priv.at (Stefan Froehlich) - 2016-07-14 10:01 +0000
          Re: xdebug "Christoph M. Becker" <cmbecker69@arcor.de> - 2016-07-14 13:02 +0200
        Re: xdebug "Christoph M. Becker" <cmbecker69@arcor.de> - 2016-07-14 12:51 +0200

#3923 — xdebug

Profiling eines Programms zeigt mir, dass mein generischer Getter
nach 19.000 Aufrufen knapp 8% der gesamten Ausführungszeit benötigt.
So weit, so gut.

Beim Quelltext erhalte ich dafür die folgende Anzeige (Kommentare im
Quelltext weggelassen und mangels c/p-Möglichkeit abgetippt - man
möge mir allfällige Fehler nachsehen):

| 95.57	public static final function getProperty(String $propertyName) {
| 		if (!array_key_exists(get_called_class(), self::$baseClasses)) self::staticInit();
| 0.13	19011 call(s) to 'php::get_called_class' (php:internal)
| 0.13	19011 call(s) to 'php::array_key_exists' (php:internal)
| 
| 		return self::$propertyDefinitions[get_called_class()]->getItem($propertyName);
| 0.10	19011 call(s) to 'php::get_called_class' (php:internal)
| 0.58	19011 call(s) to 'Framework\Collection->getItem' (collection.php)
| 	}

Das alles mit PHP7.0.

Nun kann man über die Idee, sämtliche getter über ein Array von
Collections zu bedienen (aus Performance-Sicht) sicherlich geteilter
Meinung sein; die paar 1/10-Prozent sind für mich aber locker
verschmerzbar.

Das Rätsel ist für mich eher: *was* um alles in der Welt benötigt
die 95,57%, den ausser Funktionsrumpf, "if", Array-Dereferenzierung
und einem "return" bleibt ja kein Code mehr übrig. Und wie kann das
um zwei Größenordnungen mehr Zeit benötigen, als die anderen
Operationen, die (zumal getItem) mindestens ebenso komplex sind?

Oder ist xdebug einfach nicht genau genug, und bei 8% auf 19k
Aufrufe der einzelne Aufruf so kurz, dass die Ergebnisse nur noch
gewürfelt sind? Dagegen spricht, dass sich das doch relativ gut
reproduzieren lässt.

Servus,
   Stefan

-- 
http://kontaktinser.at/ - die kostenlose Kontaktboerse fuer Oesterreich
Offizieller Erstbesucher(TM) von mmeike

2016! Das Jahr des meisterhaften Durchbruchs von Stefan.
(Sloganizer)

[toc] | [next] | [standalone]

#3924

Am 13.07.2016 um 18:08 schrieb Stefan Froehlich:

> Das Rätsel ist für mich eher: *was* um alles in der Welt benötigt
> die 95,57%, den ausser Funktionsrumpf, "if", Array-Dereferenzierung
> und einem "return" bleibt ja kein Code mehr übrig. Und wie kann das
> um zwei Größenordnungen mehr Zeit benötigen, als die anderen
> Operationen, die (zumal getItem) mindestens ebenso komplex sind?

Ich tippe mal, dass sich hier einfach der Function-Call-Overhead
bemerkbar macht, siehe
<http://jpauli.github.io/2015/01/22/on-php-function-calls.html>.

> Oder ist xdebug einfach nicht genau genug, und bei 8% auf 19k
> Aufrufe der einzelne Aufruf so kurz, dass die Ergebnisse nur noch
> gewürfelt sind? Dagegen spricht, dass sich das doch relativ gut
> reproduzieren lässt.

Kann durchaus sein, dass Xdebug nicht genau genug ist. Auf jeden Fall
kann man Profilingergebnisse unter älteren *Windows*-Versionen "in die
Tonne kloppen" (siehe <https://bugs.php.net/bug.php?id=64633>).
Allerdings sind Deine geposteten Ergebnisse, glaube ich, nicht unter
Windows entstanden.

Übrigens schön, dass d.c.l.php noch nicht (ganz) tot ist. :-)

-- 
Christoph M. Becker

[toc] | [prev] | [next] | [standalone]

#3925

On Thu, 14 Jul 2016 03:16:49 Christoph M. Becker wrote:
> Am 13.07.2016 um 18:08 schrieb Stefan Froehlich:
> > *was* um alles in der Welt benötigt die 95,57%, den ausser
> > Funktionsrumpf, "if", Array-Dereferenzierung und einem "return"
> > bleibt ja kein Code mehr übrig. Und wie kann das um zwei
> > Größenordnungen mehr Zeit benötigen, als die anderen
> > Operationen, die (zumal getItem) mindestens ebenso komplex sind?
 
> Ich tippe mal, dass sich hier einfach der Function-Call-Overhead
> bemerkbar macht, siehe
> <http://jpauli.github.io/2015/01/22/on-php-function-calls.html>.

Die Seite hatte ich irgendwann vor einem Jahr schon einmal gesehen
(und auch damals nur rudimentär gelesen, weil mir das deutlich zu
sehr ins Detail geht). Damals lief mein Code noch mit PHP5, und ich
hatte durchaus die Hoffnung, dass PHP7 gerade an dieser Stelle
einiges verbessert (wenigstens stand das einmal auf der to-do
Liste).

Ok, andererseits *hat* sich die Ausführungsgeschwindigkeit seit
damals fast verdoppelt, und xdebug liefert mir nur relative Angaben.
Trotzdem - das Missverhältnis ist heftig.

Ich habe dann schon vor einem Jahr einige ganz zentrale Funktionen
entfernt und durch duplizierten Code ersetzt - mit faszinierendem
Performancegewinn (gut 20% IIRC). Unschön :-/


Unklar ist mir allerdings weiterhin:

"public static final function getProperty(String $propertyName)"
verbraucht laut xdebug in 19k Aufrufen rund 8% Rechenzeit, davon
7,67% für sich selbst.

Die darin jeweils 1x aufgerufene Methode "Collection::getItem($key)"
verbraucht 0.07% Rechenzeit, davon 0,07% für sich selbst. Der Code
dafür ist:

| public function getItem($key) {
| 	return @$this->items[$key];
| }

Was kann der Aufruf dieser Methode, was die andere nicht kann, um 2
Größenordnungen weniger Ausführungszeit zu benötigen? Irgendwie habe
ich immer noch die Befürchtung, 8% Geschwindigkeit ohne Gegenwert zu
verschenken.

> Kann durchaus sein, dass Xdebug nicht genau genug ist. Auf jeden
> Fall kann man Profilingergebnisse unter älteren
> *Windows*-Versionen "in die Tonne kloppen" (siehe
> <https://bugs.php.net/bug.php?id=64633>). Allerdings sind Deine
> geposteten Ergebnisse, glaube ich, nicht unter Windows entstanden.

Nein, ich arbeite ausschließlich unter Linux, und immerhin sind die
Ergebnisse ja auch halbwegs konsistent.
 
> Übrigens schön, dass d.c.l.php noch nicht (ganz) tot ist. :-)

Ich tue, was ich kann - als einziger hier mit Problemen
aufzuschlagen, ist auf Dauer allerdings auch ein wenig irritierend.

Servus,
   Stefan

-- 
http://kontaktinser.at/ - die kostenlose Kontaktboerse fuer Oesterreich
Offizieller Erstbesucher(TM) von mmeike

Gute Drüsen benötigt diese Zeit: Stefan!
(Sloganizer)

[toc] | [prev] | [next] | [standalone]

#3926

On Thu, 14 Jul 2016 11:13:46 Stefan Froehlich wrote:
> "public static final function getProperty(String $propertyName)"
> verbraucht laut xdebug in 19k Aufrufen rund 8% Rechenzeit, davon
> 7,67% für sich selbst.
 
> Die darin jeweils 1x aufgerufene Methode "Collection::getItem($key)"
> verbraucht 0.07% Rechenzeit, davon 0,07% für sich selbst. Der Code
> dafür ist:
> 
> | public function getItem($key) {
> |       return @$this->items[$key];
> | }

Nachdem ich mich noch ein bisschen damit herumgespielt habe, noch eine
Ergänzung hierzu. Wenn ich getItem erweitere, z.B.

| public function getItem($key) {
| 	$dummy = $this->getMaximumSize();
| 	return @$this->items[$key];
| }

...dann benötigt der Funktionsaufruf von getItem() seinerseits auf einmal
95% der Rechenzeit, während der innere Aufruf von getMaximumSize() nur mit
0,43% verbucht wird (btw. fehlt da auch immer noch einiges auf 100%).

Die Verhältnisse in getProperty() ändern sich ebenfalls gravierend: 20%
Overhead, jeweils 0,01% für die php-Befehle und 80% für den Aufruf von
getItem().

Durch den dummy-Aufruf ist jetzt getItem() angeblich 4x so teuer wie
getProperty(). Das passt alles noch nicht ganz zusammen.

Servus,
   Stefan

-- 
http://kontaktinser.at/ - die kostenlose Kontaktboerse fuer Oesterreich
Offizieller Erstbesucher(TM) von mmeike

Happy mit Stefan, standhaft und gehängt!
(Sloganizer)

[toc] | [prev] | [next] | [standalone]

#3928

Am 14.07.2016 um 12:01 schrieb Stefan Froehlich:

> On Thu, 14 Jul 2016 11:13:46 Stefan Froehlich wrote:
>
>> "public static final function getProperty(String $propertyName)"
>> verbraucht laut xdebug in 19k Aufrufen rund 8% Rechenzeit, davon
>> 7,67% für sich selbst.
>  
>> Die darin jeweils 1x aufgerufene Methode "Collection::getItem($key)"
>> verbraucht 0.07% Rechenzeit, davon 0,07% für sich selbst.
>
> Wenn ich getItem erweitere, […]
>
> ...dann benötigt der Funktionsaufruf von getItem() seinerseits auf einmal
> 95% der Rechenzeit, während der innere Aufruf von getMaximumSize() nur mit
> 0,43% verbucht wird (btw. fehlt da auch immer noch einiges auf 100%).

Das klingt, als würde das einzeilige getItem() als Inline-Funktion
gehandhabt, aber das dürfte noch nicht implementiert sein (siehe
<https://wiki.php.net/php-7.1-ideas>); oder macht OPcache das bereits?
Vielleicht bringt auch der @-Operator den Profiler durcheinander?
Vielleicht ist das aber auch ein Bug oder eine Beschränkung von Xdebug?

Um das Problem einzugrenzen, ist es vermutlich hilfreich ein möglichst
minimales Script zu schreiben, das sich prinzipiell so verhält wie das
ganze Programm, und die erzeugten Opcodes mit dem Vulcan Logic Dumper
(<https://derickrethans.nl/projects.html#vld>) zu begutachten.

-- 
Christoph M. Becker

[toc] | [prev] | [next] | [standalone]

#3927

Am 14.07.2016 um 11:13 schrieb Stefan Froehlich:

> On Thu, 14 Jul 2016 03:16:49 Christoph M. Becker wrote:
>  
>> Ich tippe mal, dass sich hier einfach der Function-Call-Overhead
>> bemerkbar macht, siehe
>> <http://jpauli.github.io/2015/01/22/on-php-function-calls.html>.
> 
> Die Seite hatte ich irgendwann vor einem Jahr schon einmal gesehen
> (und auch damals nur rudimentär gelesen, weil mir das deutlich zu
> sehr ins Detail geht). Damals lief mein Code noch mit PHP5, und ich
> hatte durchaus die Hoffnung, dass PHP7 gerade an dieser Stelle
> einiges verbessert (wenigstens stand das einmal auf der to-do
> Liste).

Ich fürchte, da kann man zunächst gar nicht mal so viel optimieren;
Funktionsaufrufe kosten eben einfach Zeit, und bei einer dynamischen
Programmiersprache wird das noch vermehrt. Soweit ich es überblicke,
wurden bei PHP 7 hauptsächlich Aufrufe von einigen internen Funktionen
optimiert, indem zend_parse_parameters() (optional) durch deutlich
effizientere Macros ersetzt wird (siehe
<https://wiki.php.net/rfc/fast_zpp>).

Viel mehr herausholen kann man wohl nur durch Übersetzung in nativen
Maschinencode (Stichwort JIT) und/oder Auswertung von Typinformationen.
Und natürlich durch Inlining von Funktionen. Ein paar Optimierungen sind
wohl schon für PHP 7.1 umgesetzt, andere kommen wohl erst später (siehe
<https://wiki.php.net/php-7.1-ideas>).

-- 
Christoph M. Becker

[toc] | [prev] | [standalone]

Back to top | Article view | de.comp.lang.php

csiph-web