starker Laufzeit-Sprung durch eine weitere binäre-Operation

[malin]

ob ich eine oder 61 binäre Operation ist egal, geht beides in 30 ns
sobald aber die 62. Operation dazukommt wird die Rechnung 100 mal langsamer
woran liegt das?

Code: Alles auswählen

%timeit 1*1
%timeit 1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1
%timeit 1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1

Ausgabe:
10000000 loops, best of 3: 29.1 ns per loop
10000000 loops, best of 3: 29 ns per loop
100000 loops, best of 3: 2.15 µs per loop

[BlackJack]

@malin: Wird tatsächlich die *Rechnung* 100 mal langsamer? Du misst da nämlich nicht nur die Rechnung. Und 100 mal klingt viel, ist es aber in diesen Grössenordnungen nicht.

[Sirius3]

@malin: das ist bei mir reproduzierbar aber seltsam, denn Python übersetzt beide Ausdrücke in den selben Code:

Code: Alles auswählen

In [2]: dis.dis(compile('1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1','','eval'))
  1           0 LOAD_CONST              62 (1)
              3 RETURN_VALUE        

In [3]: dis.dis(compile('1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1','','eval'))
  1           0 LOAD_CONST              63 (1)
              3 RETURN_VALUE        

Da wird also in Wirklichkeit in beiden Fällen nichts gerechnet.

[malin]

@BlackJack
Bin mir nicht sicher ob ich deine Einwände richtig verstehe.
Was wird denn alles mit gemessen?

Die Ausführung der Zeile braucht 74 mal länger und das ist auch kein Einzelfall,
Das passiert bei jeder Anhäufung von binären Operationen
bis 61 Operationen ist alles gut, die 62. benötigt etwa 100 mal so lang:

Code: Alles auswählen

%timeit 9.5/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9/2.1-4.3+7.4**9.9%7.9/2.1+1.9*7.4**7.9/2.1-4.3+7.4**9.9%7.9-1.9*7.4%7.9/2.1-4.3+1.9
%timeit 9.5/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9/2.1-4.3+7.4**9.9%7.9/2.1+1.9*7.4**7.9/2.1-4.3+7.4**9.9%7.9-1.9*7.4%7.9/2.1-4.3+1.9+0.0
Ausgabe:
The slowest run took 40.45 times longer than the fastest. This could mean that an intermediate result is being cached.
10000000 loops, best of 3: 28.5 ns per loop
100000 loops, best of 3: 3.55 µs per loop

hier sogar 124 mal so lang obwohl nur noch +0 "gerechnet" wurde.

@Sirius3
Ok, schon mal interessant, das es nicht nur bei mir so ist.

Code: Alles auswählen

dis.dis(compile('9.5/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9/2.1-4.3+7.4**9.9%7.9/2.1+1.9*7.4**7.9/2.1-4.3+7.4**9.9%7.9-1.9*7.4%7.9/2.1-4.3+1.9','','eval'))
dis.dis(compile('9.5/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9%7.9/2.1-4.3+1.9*7.4**9.9/2.1-4.3+7.4**9.9%7.9/2.1+1.9*7.4**7.9/2.1-4.3+7.4**9.9%7.9-1.9*7.4%7.9/2.1-4.3+1.9+0.0','','eval'))
Ausgabe:
  1           0 LOAD_CONST              67 (371353602.09584594)
              3 RETURN_VALUE
  1           0 LOAD_CONST              69 (371353602.09584594)
              3 RETURN_VALUE

Wenn nach dem Kompilieren des Codes das selbe dort steht,
heißt das, dass %timeit die Zeit des Kompilieren mit misst?
Ok ich werfe gerade wohl mit geballten Unwissen um mich ^^'

Danke euch beiden, dass ihr das Forum so aktiv mit Rat und Tat unterstützt

[BlackJack]

@malin: Genau, was Du eigentlich misst ist das Parsen des Quelltextes, das Optimieren, und das erzeugen des Bytecodes. Und da der erzeugte Code der dann letztendlich ausgeführt wird gleich ist, kann der Unterschied ja nur beim Parsen und Optimieren liegen. Das wird bei Deinem Beispiel 10.000.000 mal beziehungsweise 100.000 mal gemacht, was aber unrealistisch ist, denn normalerweise wird der Quelltext ja nur einmal kompiliert.

Ich kann das Ergebnis auch nachvollziehen. Wenn man aber nur das kompilierte misst, ist da kein signifikanter Unterschied mehr:

Code: Alles auswählen

In [38]: a, b = (compile('*'.join(['1'] * i), '<>', 'eval') for i in [62, 63])

In [39]: %timeit a
The slowest run took 16.07 times longer than the fastest. This could mean that an intermediate result is being cached.
10000000 loops, best of 3: 84 ns per loop

In [40]: %timeit b
The slowest run took 19.66 times longer than the fastest. This could mean that an intermediate result is being cached.
10000000 loops, best of 3: 97.2 ns per loop

In [41]: dis.dis(a)
  1           0 LOAD_CONST              61 (1)
              3 RETURN_VALUE        

In [42]: dis.dis(b)
  1           0 LOAD_CONST              62 (1)
              3 RETURN_VALUE

Letztlich sind das aber wie gesagt ”Grössen” deren Messung nicht wirklich Sinn macht. Was man an den Warnungen ja schon ganz gut sieht, das die Schwankungen im Verhältnis zur Grössenordnung schon viel zu hoch ist als das man da sinnvolle Aussagen treffen kann.

[malin]

hm,

Aber die Frage warum er trotz den kleinen Unterschied nun länger braucht bleibt bestehen
Auch wirft das 2 weitere Fragen auf,
denn auch bei mir erzeugt
%timeit a und
%timeit b
gleiche Zeiten, aber längere als %timeit 1*1*...*1 (mit 61 "mal-zeichen)
dabei müsste es als schon kompilierter Code wohl schneller sein als noch
nicht kompilierter Code.
Außerdem dauert:
%timeit (compile('*'.join(['1'] * i), '<>', 'eval') for i in [62, 63])
fast eine millisekunde, also viel länger als wenn man den code ausführt
ohne extra zu kompilieren.
Das wirkt für mich, als würde %timeit das kompilieren zumindest zum Teil rausfiltern

[BlackJack]

@malin: Darf ich noch mal anmerken das in diesen kleinen Bereichen auch 100 mal langsamer nicht wirklich viel ist? Und das ganz grundsätzlich Microbenchmarks nur sehr begrenzt sinnvoll oder aussagekräftig sind?

Parsen und Optimieren sind ausserdem ziemlich komplexe Vorgänge. Da wird Quelltext in Token zerlegt und ein abstrakter Syntaxbaum (AST) erstellt, und darauf werden dann Operationen durchgeführt wie das „constant folding“ und es werden diverse Datenstrukuren angelegt, zerstört, eventuell kopiert.

Irgendwas bei der zusätzlichen Operation sorgt halt dafür das der Compiler zusätzliche Arbeit verrichten muss. Beispielsweise weil eine Grösse für eine Datenstruktur beim Parsen oder beim bauen des AST oder traversieren des selben überschritten wurde und die vergrössert werden muss. Vielleicht eine ”zufällige” Grenze die überschritten wurde, oder vielleicht auch ein „educated guess“ der Entwickler das 60 Operationen in *einem* Ausdruck eine Obergrenze ist, die sowieso niemand erreicht. Und selbst wenn, haben wir hier ja keine Verlangsamung die irgendwie reale Auswirkungen hätte.

Warum müssen Codeobjekte schneller aufgerufen werden können als Kompilieren und Ausführen in einem Schritt? Und noch mal: Wir bewegen uns hier in einem Bereich bei dem auch eine konsistent schnellere Messung keine Aussagekraft haben muss, weil es einfach zu kleine Unterschiede sein können um wirklich signifikant zu sein.

Dir ist klar das

Code: Alles auswählen

%timeit (compile('*'.join(['1'] * i), '<>', 'eval') for i in [62, 63])

nur den Code kompiliert und dann ein Generatorobjekt erstellt, aber keine Iteration durchführt und `compile()` nicht aufgerufen wird? Ich weiss nicht was Du mit diesem Messergebnis überhaupt aussagen möchtest, denn das kann man mit nichts bisherigem hier sinnvoll vergleichen.

[snafu]

Aufgrund der Warnhinweise vermute ich stark, dass bis zu einer gewissen Anzahl von Operanden die Ergebnisse aus einem Cache wiederverwendet werden. timeit misst dann also für die allermeisten Durchläufe nicht die tatsächliche Berechnung, sondern nur das Abfragen aus dem Cache. Darauf deutet ja auch die Ausgabe von dis() hin. Wie das genau funtioniert, habe ich auf die Schnelle aber leider nicht finden können.

[BlackJack]

@snafu: Da gibt's keinen Cache, das in dem Hinweis ist ja nur eine Vermutung, weil das *ein* Grund für so ein Zeitverhalten sein könnte. Die Warnung deutet aber auf jeden Fall darauf hin, dass die Schwankungen zu gross sind um mit dem Ergebnis etwas sinnvolles anfangen zu können.

[snafu]

Da gibt's keinen Cache, das in dem Hinweis ist ja nur eine Vermutung, weil das *ein* Grund für so ein Zeitverhalten sein könnte.

Bist du mit den Interna des Compilers und der VM soweit vertraut, dass du das auschließen kannst oder was macht dich da so sicher?

[BlackJack]

@snafu: Was soll denn da gecached sein? Da müsste ja der Compiler irgenwelche kompilierten Teilausdrücke cachen in der Hoffnung das irgendwo noch mal gleicher oder ähnlicher Quelltext kompiliert wird. Das würde ich ausschliessen, weil dann speziell auf schlecht geschriebenen Code optimiert wird, denn solche Wiederholungen schreibt man als Programmierer ja nicht. Die Rechnung selbst ist dann gar keine Rechnung wie die disassemblierten Codes zeigen, weil das vom Compiler schon zu einem Konstanten Wert optimiert wird.

[snafu]

Es liegt wohl an der Art wie IPython das Messverfahren für das %timeit-Kommando implementiert wurde. Nutzt man alterntiv z.B. das perf-Modul (kann mittels pip installiert werden), dann kommt es zu keinen signifikanten Abweichungen im Ergebnis:
[codebox=dos file=Unbenannt.bat]C:\Users\Sebastian>py -3 -m perf timeit '1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1'
.....................
Mean +- std dev: 34.5 ns +- 0.5 ns

C:\Users\Sebastian>py -3 -m perf timeit '1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1*1'
.....................
Mean +- std dev: 34.8 ns +- 1.0 ns[/code]
Die Problematik wird übrigens hier angesprochen. Die Entwickler von IPython haben sich der Sache bereits angenommen, um die Darstellung der Messergebnisse zu verbessern.

[BlackJack]

Das ändert aber IMHO alles nichts daran, dass das messen der Ausführung von *zwei* einfachen Bytecode-Befehlen schlicht keinen Sinn macht. Das Problem ist ja, dsas dagegen *alles* andere im Vergleich ”riesig” ist, also jede Änderung im Code der darum gestrickt wird um zu messen, massive Auswirkungen auf das Messergebnis haben kann, so das dieses nicht aussagekräftig oder belastbar ist.

[snafu]

Klar sind Microbenchmarks mit Vorsicht zu genießen. Trotzdem ist der große Anstieg an dieser einen Stelle bemerkenswert. Hat sich ja jetzt weitesgehend aufgeklärt, woran es wirklich liegt, finde ich.

[malin]

Ja, ich denke mehr kann man zu diesem Thema nicht sagen.

Ich habe es aus 2 Gründen angesprochen.
1. fand ich diese willkürliche Grenze von 61 auf 62 Operationen einfach seltsam
2. hat es mich interessiert, ob durch den selben Grund, ein echter Code relevant
verlangsamt werden kann.
Dies scheint zumindest nicht der Fall zu sein.
Danke euch dreien