Python Bytecode Disassembler, profile, kernprof - Laufzeitanalyse

Wenn du dir nicht sicher bist, in welchem der anderen Foren du die Frage stellen sollst, dann bist du hier im Forum für allgemeine Fragen sicher richtig.
Antworten
Daikoku
User
Beiträge: 66
Registriert: Montag 20. April 2015, 21:14

Hallo,

ich hätte da ein paar Fragen, welche Möglicherweise die Hilfsbereitschaft dieses Forums etwas zu sehr in Anspruch nehmen.
Sollte dieses der Fall sein, schreibt dieses bitte offen und ehrlich.

Code: Alles auswählen

import time
import itertools
import dis
#import profile

# externe Module
# https://pypi.python.org/pypi/profilehooks
#from profilehooks import profile, coverage, timecall

#@profile
def with_itertools(x, y):
    return itertools.product(xrange(x), xrange(y))

#@profile
def with_yield(x, y):
    for i in xrange(x):
        for j in xrange(y):
            yield(i, j)

#@profile
def without_yield(x, y):
    return ((i, j) for i in xrange(x) for j in xrange(y))

#@profile
def start():
    x = 1000
    y = 1000

    tsec = time.clock()
    out = list(without_yield(x,y))
    print 'Runtime function  (x={0},y={1}) : {2:.6f} sec.'.format(x, y, time.clock() -tsec)

    tsec = time.clock()
    out = list(with_itertools(x,y))
    print 'Runtime itertools (x={0},y={1}) : {2:.6f} sec.'.format(x, y, time.clock() -tsec)

    tsec = time.clock()
    out = list(with_yield(x,y))
    print 'Runtime yield     (x={0},y={1}) : {2:.6f} sec.'.format(x, y, time.clock() -tsec)


#profile.run('start(); print')
start()

print '-' *25, 'without_yield' , '-' *25
dis.dis(without_yield.func_code.co_consts[1])
print '-' *25, 'with_yield' , '-' *25
dis.dis(with_yield)
print '-' *25, 'with_itertools' , '-' *25
dis.dis(with_itertools)

Code: Alles auswählen

Runtime function  (x=1000,y=1000) : 0.279896 sec.
Runtime itertools (x=1000,y=1000) : 0.236338 sec.
Runtime yield     (x=1000,y=1000) : 0.244184 sec.
------------------------- without_yield -------------------------
 22           0 LOAD_FAST                0 (.0)
        >>    3 FOR_ITER                36 (to 42)
              6 STORE_FAST               1 (i)
              9 LOAD_GLOBAL              0 (xrange)
             12 LOAD_DEREF               0 (y)
             15 CALL_FUNCTION            1
             18 GET_ITER
        >>   19 FOR_ITER                17 (to 39)
             22 STORE_FAST               2 (j)
             25 LOAD_FAST                1 (i)
             28 LOAD_FAST                2 (j)
             31 BUILD_TUPLE              2
             34 YIELD_VALUE
             35 POP_TOP
             36 JUMP_ABSOLUTE           19
        >>   39 JUMP_ABSOLUTE            3
        >>   42 LOAD_CONST               0 (None)
             45 RETURN_VALUE
------------------------- with_yield -------------------------
 16           0 SETUP_LOOP              54 (to 57)
              3 LOAD_GLOBAL              0 (xrange)
              6 LOAD_FAST                0 (x)
              9 CALL_FUNCTION            1
             12 GET_ITER
        >>   13 FOR_ITER                40 (to 56)
             16 STORE_FAST               2 (i)

 17          19 SETUP_LOOP              31 (to 53)
             22 LOAD_GLOBAL              0 (xrange)
             25 LOAD_FAST                1 (y)
             28 CALL_FUNCTION            1
             31 GET_ITER
        >>   32 FOR_ITER                17 (to 52)
             35 STORE_FAST               3 (j)

 18          38 LOAD_FAST                2 (i)
             41 LOAD_FAST                3 (j)
             44 BUILD_TUPLE              2
             47 YIELD_VALUE
             48 POP_TOP
             49 JUMP_ABSOLUTE           32
        >>   52 POP_BLOCK
        >>   53 JUMP_ABSOLUTE           13
        >>   56 POP_BLOCK
        >>   57 LOAD_CONST               0 (None)
             60 RETURN_VALUE
------------------------- with_itertools -------------------------
 12           0 LOAD_GLOBAL              0 (itertools)
              3 LOAD_ATTR                1 (product)
              6 LOAD_GLOBAL              2 (xrange)
              9 LOAD_FAST                0 (x)
             12 CALL_FUNCTION            1
             15 LOAD_GLOBAL              2 (xrange)
             18 LOAD_FAST                1 (y)
             21 CALL_FUNCTION            1
             24 CALL_FUNCTION            2
             27 RETURN_VALUE
1. Python Bytecode Disassembler

In der Funktion without_yield() kann ich erkennen, dass y mit LOAD_DEREF und im Generator with_yield() und in der Funktion with_itertools() y mit LOAD_FAST verarbeitet wird.
Nach meinen Recherchen ist LOAD_FAST wesentlich schneller als LOAD_DEREF in der Verarbeitung.
LOAD_FAST, LOAD_DEREF, etc. bezeichne ich im weiterem Text als code objecte.

Meine Fragen hierzu wären:
Wo steht in der Dokumentation, welche code objecte ein günstiges und welche eher ein kritisches Laufzeitverhalten haben ?
Wenn derartige Informationen nicht in der Dokumentation stehen, wo kann ich weitergehende Informationen finden ?
Welche code objecte sollten eine besondere Beachtung finden ?
Wie viele verschiedene code objecte gibt es ?
Wenn ich dieses Antworten nur im Sourcecode der GIL finden kann, wo fange ich da an zu suchen ?

Wenn ich mir die einzelnen Ergebnisse des Disassemblers anschaue, müsste unter allen Bedingungen die funktion with_itertools() die performanteste Lösung sein.
Quod esset demonstrandum.

2. Laufzeitverhalten

Code: Alles auswählen

# Ich habe die jeweilige Code-Kombination 10x durchlaufen lassen,  dann das jeweils beste und schlechteste Ergebnis gestrichen und
# aus den verbliebenen 8 Werten jeweils einen Mittelwert errechnet des jeweiligen Programm print out ermittelt:

Runtime yield     (x=5,y=5) : 0.000012 sec.
Runtime function  (x=5,y=5) : 0.000027 sec.
Runtime itertools (x=5,y=5) : 0.000025 sec.

Runtime itertools (x=5,y=5) : 0.000013 sec.
Runtime function  (x=5,y=5) : 0.000051 sec.
Runtime yield     (x=5,y=5) : 0.000083 sec.

Runtime function  (x=5,y=5) : 0.000014 sec.
Runtime itertools (x=5,y=5) : 0.000080 sec.
Runtime yield     (x=5,y=5) : 0.000102 sec.


Runtime yield     (x=1000,y=1000) : 0.200122 sec.
Runtime function  (x=1000,y=1000) : 0.245055 sec.
Runtime itertools (x=1000,y=1000) : 0.188157 sec.

Runtime itertools (x=1000,y=1000) : 0.139838 sec.
Runtime function  (x=1000,y=1000) : 0.240710 sec.
Runtime yield     (x=1000,y=1000) : 0.251581 sec.

Runtime function  (x=1000,y=1000) : 0.198934 sec.
Runtime itertools (x=1000,y=1000) : 0.186137 sec.
Runtime yield     (x=1000,y=1000) : 0.233364 sec.

Code: Alles auswählen

# Ergebnis des Moduls profile aus der Standardbibliothek
# x=1000 und y=1000

         2000017 function calls in 8.702 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        6    0.000    0.000    0.000    0.000 :0(clock)
        3    0.000    0.000    0.000    0.000 :0(format)
        1    0.021    0.021    0.021    0.021 :0(setprofile)
        1    0.057    0.057    8.682    8.682 <string>:1(<module>)
        0    0.000             0.000          profile:0(profiler)
        1    0.000    0.000    8.702    8.702 profile:0(start(); print)
  1000001    2.134    0.000    2.134    0.000 python_forum.de.py:11(with_yield)
        1    0.000    0.000    0.000    0.000 python_forum.de.py:16(without_yield)
  1000001    2.201    0.000    2.201    0.000 python_forum.de.py:17(<genexpr>)
        1    4.289    4.289    8.624    8.624 python_forum.de.py:20(start)
        1    0.000    0.000    0.000    0.000 python_forum.de.py:7(with_itertools)

Code: Alles auswählen

# Ergebnis mit  kernprof.exe -l -v <modulname.py> - https://github.com/rkern/line_profiler
Runtime function  (x=1000,y=1000) : 0.510616 sec.
Runtime itertools (x=1000,y=1000) : 0.193372 sec.
Runtime yield     (x=1000,y=1000) : 9.540016 sec.
Wrote profile results to python_forum.de.py.lprof
Timer unit: 3.41328e-07 s

Total time: 0.000105129 s
File: .\python_forum.de.py
Function: with_itertools at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                           @profile
     7                                           def with_itertools(x, y):
     8         1          308    308.0    100.0      return itertools.product(xrange(x), xrange(y))

Total time: 3.03512 s
File: .\python_forum.de.py
Function: with_yield at line 10

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    10                                           @profile
    11                                           def with_yield(x, y):
    12      1001         4450      4.4      0.1      for i in xrange(x):
    13   1001000      4480051      4.5     50.4          for j in xrange(y):
    14   1000000      4407598      4.4     49.6              yield(i, j)

Total time: 3.7546e-06 s
File: .\python_forum.de.py
Function: without_yield at line 16

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    16                                           @profile
    17                                           def without_yield(x, y):
    18         1           11     11.0    100.0      return ((i, j) for i in xrange(x) for j in xrange(y))

Total time: 10.2524 s
File: .\python_forum.de.py
Function: start at line 20

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    20                                           @profile
    21                                           def start():
    22         1            9      9.0      0.0      x = 1000
    23         1            6      6.0      0.0      y = 1000
    24
    25
    26         1           17     17.0      0.0      tsec = time.clock()
    27         1      1495912 1495912.0      5.0      out = list(without_yield(x,y))
    28         1         5592   5592.0      0.0      print 'Runtime function  (x={0},y={1}) : {2:.6f} sec.'.format(x, y, time.clock() -tsec)
    29
    30         1           31     31.0      0.0      tsec = time.clock()
    31         1       566414 566414.0      1.9      out = list(with_itertools(x,y))
    32         1        12384  12384.0      0.0      print 'Runtime itertools (x={0},y={1}) : {2:.6f} sec.'.format(x, y, time.clock() -tsec)
    33
    34         1           61     61.0      0.0      tsec = time.clock()
    35         1     27949615 27949615.0     93.1      out = list(with_yield(x,y))
    36         1         6917   6917.0      0.0      print 'Runtime yield     (x={0},y={1}) : {2:.6f} sec.'.format(x, y, time.clock() -tsec)

Code: Alles auswählen

# Ergebnisse mit aktiviertem
# from profilehooks import profile, coverage, timecall

Runtime function  (x=1000,y=1000) : 2.055206 sec.
Runtime itertools (x=1000,y=1000) : 0.195309 sec.
Runtime yield     (x=1000,y=1000) : 2.076854 sec.

*** PROFILER RESULTS ***
start (.\python_forum.de.py:24)
function called 1 times

         2000021 function calls in 4.332 seconds

   Ordered by: cumulative time, internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    2.235    2.235    4.332    4.332 python_forum.de.py:24(start)
  1000001    1.057    0.000    1.057    0.000 python_forum.de.py:22(<genexpr>)
  1000001    1.040    0.000    1.040    0.000 python_forum.de.py:14(with_yield)
        3    0.000    0.000    0.000    0.000 profilehooks.py:234(new_fn)
        3    0.000    0.000    0.000    0.000 profilehooks.py:328(__call__)
        3    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
        1    0.000    0.000    0.000    0.000 python_forum.de.py:10(with_itertools)
        6    0.000    0.000    0.000    0.000 {time.clock}
        1    0.000    0.000    0.000    0.000 python_forum.de.py:20(without_yield)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        0    0.000             0.000          profile:0(profiler)

*** PROFILER RESULTS ***
without_yield (.\python_forum.de.py:20)
function called 1 times

         0 function calls in 0.000 seconds

   Ordered by: cumulative time, internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        0    0.000             0.000          profile:0(profiler)

*** PROFILER RESULTS ***
with_yield (.\python_forum.de.py:14)
function called 1 times

         0 function calls in 0.000 seconds

   Ordered by: cumulative time, internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        0    0.000             0.000          profile:0(profiler)

*** PROFILER RESULTS ***
with_itertools (.\python_forum.de.py:10)
function called 1 times

         0 function calls in 0.000 seconds

   Ordered by: cumulative time, internal time, call count

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        0    0.000             0.000          profile:0(profiler)
Egal welcher Tools oder Bibliotheken ich mich bediene, es will mir einfach nicht gelingen, aus einem quod esset demonstrandum ein quod erat demonstrandum zu machen.

Wie macht man das mit dem Profiling denn nun richtig, sodass die Ergebnisse auch wirklich belastbar sind ?
Welche Module und/oder Tools sind nützlich und von welchen sollte man lieber die Finger lassen ?
Beschäftige ich mich hier eher mit einem akademischen Thema oder ist dies in der Praxis nützlich ?

Zusammenfassend:
Ich benutze das modul dis und überwiegend kernprof. Doch ich zweifel die einzelnen Ergebnisse an.
Wenn ich die Reihenfolge der einzelnen Funktionen in meinem Code zum Beispiel von
a.) 1. list(without_yield(x,y)), 2. list(with_itertools(x,y)) und 3. list(with_yield(x,y)) nach
b.) 1. list(with_yield(x,y)), 2. list(without_yield(x,y)) und 3. list(with_itertools(x,y))
ändere, bekomme ich auch völlig andere Ergebnisse. Das kann eigentlich so nicht sein.
Nach oben
DasIch
User
Beiträge: 2718
Registriert: Montag 19. Mai 2008, 04:21
Wohnort: Berlin

Daikoku hat geschrieben:1. Python Bytecode Disassembler

In der Funktion without_yield() kann ich erkennen, dass y mit LOAD_DEREF und im Generator with_yield() und in der Funktion with_itertools() y mit LOAD_FAST verarbeitet wird.
Nach meinen Recherchen ist LOAD_FAST wesentlich schneller als LOAD_DEREF in der Verarbeitung.
LOAD_FAST, LOAD_DEREF, etc. bezeichne ich im weiterem Text als code objecte.
Tun wir dass mal nicht und nennen sie wie sie tatsächlich heissen: Opcodes. Das steht so übrigens auch in der dis Dokumentation.
Wo steht in der Dokumentation, welche code objecte ein günstiges und welche eher ein kritisches Laufzeitverhalten haben ?
Nirgends. Das kann man auch für viele Opcodes gar nicht sagen. Darüber hinaus werden z.B. bei PyPy durch den JIT zur Laufzeit teilweise ganz andere Code Pfade genommen, so dass die Opcodes für wesentliche Teile eines Programms vollkommen irrelevant sind.
Wenn derartige Informationen nicht in der Dokumentation stehen, wo kann ich weitergehende Informationen finden ?
Wenn man weiß was ein Opcode tut, ist eigentlich offensichtlich wie teuer er ist. Ansonsten im Source Code des Interpreters in der von dir verwendeten Version.
Welche code objecte sollten eine besondere Beachtung finden ?
Keine.
Wie viele verschiedene code objecte gibt es ?
Hängt vom Interpreter und möglicherweise auch von der Interpreter Version ab.
Wenn ich dieses Antworten nur im Sourcecode der GIL finden kann, wo fange ich da an zu suchen ?
Im Fall von CPython suchst du nach opcode.h für die Definitionen der Opcodes, ceval.c für was genau die machen.
Wie macht man das mit dem Profiling denn nun richtig, sodass die Ergebnisse auch wirklich belastbar sind ?
Profiler nutzt man um herauszufinden welche Funktionen/Methoden langsam sind, im Vergleich zu allen anderen Funktionen/Methoden. Richtig benutzt man sie also um etwas völlig anderes zu tun als was du machst und dies nur bei wesentlich komplexerem Code.
Welche Module und/oder Tools sind nützlich und von welchen sollte man lieber die Finger lassen ?
Profiler sind nützlich, die sind ja auch in der stdlib. Ansonsten gibt es noch vmprof, ein statistischer Profiler der etwas ungenauer ist, dafür sehr viel weniger Overhead hat. Disassembler sind vollkommen uninteressant außer um irgendwelchen Leuten zu zeigen, wieso trivaler Ausdruck a unwesentlich schneller als trivialer Ausdruck b ist.
Beschäftige ich mich hier eher mit einem akademischen Thema oder ist dies in der Praxis nützlich ?
Natürlich ist es in der Praxis nützlich, es ist eher aus akademisch Sicht uninteressant.
Zusammenfassend:
Ich benutze das modul dis und überwiegend kernprof. Doch ich zweifel die einzelnen Ergebnisse an.
Wenn ich die Reihenfolge der einzelnen Funktionen in meinem Code zum Beispiel von
a.) 1. list(without_yield(x,y)), 2. list(with_itertools(x,y)) und 3. list(with_yield(x,y)) nach
b.) 1. list(with_yield(x,y)), 2. list(without_yield(x,y)) und 3. list(with_itertools(x,y))
ändere, bekomme ich auch völlig andere Ergebnisse. Das kann eigentlich so nicht sein.
Deine Ergebnisse machen schon keinen Sinn weil du da nicht versuchen solltest irgendwelche Durchschnittswerte zu finden. Das ist keine gute Idee. Davon mal abgesehen stellt sich die Frage ob die tatsächlich völlig unterschiedlich sind. Bedenke dass bei x=y=5 wir eine Größenordnung von Mikrosekunden haben. Wie präzise ist time.clock() überhaupt? Selbst bei x=y=1000 wo die Unterschiede größer sind, sind bei allen Reihenfolgen die Ergebnisse relativ zu einander doch recht ähnlich. Man sieht also durchaus noch dass itertools am schnellsten ist und yield/function in etwa gleichauf ist mit yield etwas schneller.
Nach oben
Antworten

Zurück zu „Allgemeine Fragen“