Hi list,
I was toying around a bit with writing a statistical profiler in python,
and came up with https://gist.github.com/jap/5584946
For reference, the main routine is:
with Profiler() as p:
with ProfilerContext("c1"):
s = ""
for t in range(100000):
with ProfilerContext("c2"):
s = s + "a"
s = s + "b"
print p.get_data()
When running it on my local machine, this gives the following output:
spaans@spaans-e6500:/tmp$ /usr/bin/time ~/xsrc/pypy-2.0/bin/pypy pmp.py
Counter({'c1': 638})
6.42user 0.42system 0:07.06elapsed 97%CPU (0avgtext+0avgdata
30160maxresident)k
0inputs+0outputs (0major+8383minor)pagefaults 0swaps
spaans@spaans-e6500:/tmp$ /usr/bin/time python pmp.py
Counter({'c1': 18, 'c2': 3})
0.23user 0.02system 0:00.25elapsed 98%CPU (0avgtext+0avgdata
8200maxresident)k
0inputs+0outputs (0major+2226minor)pagefaults 0swaps
So, two things seem to happen: the pypy version is almost 30 times
slower than the python version (but hey, string appending has poor
performance), and it somehow does not trigger the "c2" context..
Is the c2 context supposed to disappear?
If I change the main loop to
for t in range(100000):
with ProfilerContext("c2"):
s = s + "a"
The output is still limited to
spaans@spaans-e6500:/tmp$ /usr/bin/time ~/xsrc/pypy-2.0/bin/pypy pmp.py
Counter({'c1': 156})
1.61user 0.14system 0:01.78elapsed 98%CPU (0avgtext+0avgdata
30040maxresident)k
which seems credible, because when I change it to
for t in range(100000):
s = s + "a"
it's suddenly fast in pypy as well:
0.03user 0.01system 0:00.05elapsed 96%CPU (0avgtext+0avgdata
8024maxresident)k
Removing all the threading.local stuff gives me the following
performance data:
spaans@spaans-e6500:/tmp$ /usr/bin/time python pmp.py
Counter({'c1': 12, 'c2': 6})
0.20user 0.01system 0:00.22elapsed 98%CPU (0avgtext+0avgdata
8192maxresident)k
0inputs+0outputs (0major+2224minor)pagefaults 0swaps
spaans@spaans-e6500:/tmp$ /usr/bin/time ~/xsrc/pypy-2.0/bin/pypy pmp.py
Counter({'c1': 621})
6.18user 0.42system 0:06.76elapsed 97%CPU (0avgtext+0avgdata
30084maxresident)k
which does not seem to differ that much.
Finally, to rule out object creation issues, main was changed to:
with Profiler() as p:
with ProfilerContext("c1"):
p2 = ProfilerContext("c2")
s = ""
for t in range(100000):
with p2:
s = s + "a"
s = s + "b"
print p.get_data()
but that still behaves similar to the previous runs:
spaans@spaans-e6500:/tmp$ /usr/bin/time ~/xsrc/pypy-2.0/bin/pypy pmp.py
Counter({'c1': 624})
6.25user 0.38system 0:06.69elapsed 99%CPU (0avgtext+0avgdata
29792maxresident)k
spaans@spaans-e6500:/tmp$ /usr/bin/time python pmp.py
Counter({'c2': 6, 'c1': 6})
0.14user 0.02system 0:00.16elapsed 98%CPU (0avgtext+0avgdata
8188maxresident)k
(all of this on my trusty old Dell E6500 running Ubuntu 13.04 on amd64)
Could someone help me get "c2" registered, or is this expected behaviour? :)
Cheers,
Jasper
--
/\____/\ ir. Jasper Spaans // Lead Developer DetACT
\ (_)/ Fox-IT - For a more secure society!
\ X T: +31-15-2847999
\ / \ M: +31-6-41588725
\/ KvK Haaglanden 27301624
_______________________________________________
pypy-dev mailing list
pypy-dev@python.org
http://mail.python.org/mailman/listinfo/pypy-dev
