Node Performance Profile
From Solipsis
| Table of contents |
[edit]
Python profiler
The standard profiler is described here (http://docs.python.org/lib/profile.html). For single-threaded programs, an optimized profiler named hotshot (http://www.python.org/doc/current/lib/module-hotshot.html) is also available.
[edit]
Sample results
These results were not obtained during the same sequences, thus absolute total times cannot be compared.
[edit]
with the Twisted node
>>> stats.sort_stats("time").print_stats(20)
1207977 function calls (1057431 primitive calls) in 16.961 CPU seconds
Ordered by: internal time
List reduced from 221 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
13119 0.915 0.000 2.401 0.000 /usr/lib/python2.4/logging/__init__.py:604(handle)
19418 0.780 0.000 1.754 0.000 /home/antoine/solipsis/main/solipsis/twistednode/protocol.py:235(ParseMessage)
2960 0.721 0.000 12.668 0.004 /usr/lib/python2.4/site-packages/twisted/internet/default.py:475(doSelect)
139342 0.679 0.000 0.679 0.000 /home/antoine/solipsis/main/solipsis/util/bidict.py:29(get_reverse)
150496/1 0.627 0.000 16.961 16.961 <string>:1(?)
77088 0.605 0.000 0.605 0.000 /home/antoine/solipsis/main/solipsis/twistednode/topology.py:35(<lambda>)
11818 0.539 0.000 1.902 0.000 /home/antoine/solipsis/main/solipsis/twistednode/protocol.py:215(BuildMessage)
115976 0.530 0.000 0.530 0.000 /usr/lib/python2.4/site-packages/twisted/internet/base.py:132(__lt__)
13119 0.493 0.000 0.699 0.000 /usr/lib/python2.4/logging/__init__.py:1005(findCaller)
13119 0.452 0.000 5.086 0.000 /usr/lib/python2.4/logging/__init__.py:1026(_log)
13119 0.417 0.000 0.839 0.000 /usr/lib/python2.4/logging/__init__.py:369(format)
13119 0.392 0.000 2.792 0.000 /usr/lib/python2.4/logging/__init__.py:1066(callHandlers)
6782 0.379 0.000 0.786 0.000 /usr/lib/python2.4/site-packages/twisted/internet/base.py:365(callLater)
7600 0.324 0.000 11.081 0.001 /home/antoine/solipsis/main/solipsis/twistednode/nodeconnector.py:23(datagramReceived)
19278 0.289 0.000 0.542 0.000 /home/antoine/solipsis/main/solipsis/twistednode/topology.py:80(Distance)
13119 0.285 0.000 0.285 0.000 /usr/lib/python2.4/logging/__init__.py:1092(getEffectiveLevel)
13119 0.281 0.000 0.709 0.000 /usr/lib/python2.4/logging/__init__.py:187(__init__)
15929 0.278 0.000 0.278 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:21(getCoords)
800 0.274 0.000 1.909 0.002 /home/antoine/solipsis/main/solipsis/twistednode/statemachine.py:784(_UpdatePeer)
6942 0.269 0.000 4.112 0.001 /home/antoine/solipsis/main/solipsis/twistednode/nodeconnector.py:37(SendMessage)
[edit]
with the old node
>>> p.sort_stats('time').print_stats(20)
Tue Nov 30 11:51:52 2004 node.prof
1770649 function calls (1770631 primitive calls) in 25.580 CPU seconds
Ordered by: internal time
List reduced from 265 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
56109 5.190 0.000 8.170 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:81(relativePosition)
397316 1.830 0.000 1.830 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:21(getPosX)
418994 1.790 0.000 1.790 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:24(getPosY)
6478 1.540 0.000 3.420 0.001 /home/antoine/solipsis/main/solipsis/node/protocol.py:130(fromData)
17846 1.310 0.000 7.210 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:131(inHalfPlane)
17788 0.710 0.000 3.570 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:72(distance)
86084 0.710 0.000 0.960 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:8(__init__)
55592 0.590 0.000 0.590 0.000 /usr/lib/python2.3/sre.py:216(_compile)
55592 0.460 0.000 1.050 0.000 /usr/lib/python2.3/sre.py:177(compile)
6478 0.410 0.000 5.280 0.001 /home/antoine/solipsis/main/solipsis/node/protocol.py:114(toData)
16187 0.400 0.000 0.550 0.000 /usr/lib/python2.3/threading.py:93(acquire)
16187 0.360 0.000 0.550 0.000 /usr/lib/python2.3/threading.py:111(release)
3239 0.350 0.000 8.860 0.003 /home/antoine/solipsis/main/solipsis/node/udpconnector.py:97(_send_no_wait)
7667 0.330 0.000 2.690 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:140(ccwOrder)
373 0.290 0.001 3.220 0.009 /home/antoine/solipsis/main/solipsis/node/peer.py:351(necessaryPeers)
4938 0.280 0.000 0.450 0.000 /usr/lib/python2.3/logging/__init__.py:183(__init__)
6478 0.280 0.000 6.660 0.001 /home/antoine/solipsis/main/solipsis/node/peerevent.py:57(getData)
1 0.260 0.260 25.570 25.570 /home/antoine/solipsis/main/solipsis/node/node.py:167(mainLoop)
5240 0.250 0.000 6.380 0.001 /home/antoine/solipsis/main/solipsis/util/container.py:58(dichotomy)
6192 0.250 0.000 0.250 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:45(setValueFromString)
<pstats.Stats instance at 0x40761fcc>
>>> p.sort_stats('cumulative').print_stats(15)
Tue Nov 30 11:51:52 2004 node.prof
1770649 function calls (1770631 primitive calls) in 25.580 CPU seconds
Ordered by: cumulative time
List reduced from 265 to 15 due to restriction <15>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.010 0.010 25.580 25.580 <string>:1(?)
1 0.000 0.000 25.580 25.580 profile:0(solipsis.node.main.profile_run())
1 0.260 0.260 25.570 25.570 /home/antoine/solipsis/main/solipsis/node/node.py:167(mainLoop)
1 0.000 0.000 25.570 25.570 /home/antoine/solipsis/main/solipsis/node/main.py:105(<lambda>)
165 0.000 0.000 11.770 0.071 /home/antoine/solipsis/main/solipsis/node/state.py:389(MOVE)
3923 0.080 0.000 9.720 0.002 /home/antoine/solipsis/main/solipsis/node/node.py:130(dispatch)
3239 0.060 0.000 8.920 0.003 /home/antoine/solipsis/main/solipsis/node/udpconnector.py:87(send)
3239 0.350 0.000 8.860 0.003 /home/antoine/solipsis/main/solipsis/node/udpconnector.py:97(_send_no_wait)
56109 5.190 0.000 8.170 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:81(relativePosition)
2620 0.100 0.000 7.290 0.003 /home/antoine/solipsis/main/solipsis/node/peer.py:172(addPeer)
17846 1.310 0.000 7.210 0.000 /home/antoine/solipsis/main/solipsis/util/geometry.py:131(inHalfPlane)
508 0.070 0.000 6.740 0.013 /home/antoine/solipsis/main/solipsis/node/state.py:67(HELLO)
6478 0.280 0.000 6.660 0.001 /home/antoine/solipsis/main/solipsis/node/peerevent.py:57(getData)
5240 0.090 0.000 6.470 0.001 /home/antoine/solipsis/main/solipsis/util/container.py:51(insert)
5240 0.250 0.000 6.380 0.001 /home/antoine/solipsis/main/solipsis/util/container.py:58(dichotomy)
<pstats.Stats instance at 0x40761fcc>
[edit]
Memory performance and memory leaks
Some hints to track memory leaks in Python apps (http://www.nightmare.com/medusa/memory-leaks.html).
A Python size estimator (http://manatee.mojam.com/~skip/python/sizer.py).
Note: Psyco is useful but it eats up some memory too. It is thus better to tweak its profiler parameters: see the documentation for Profile-based compilation (http://psyco.sourceforge.net/psycoguide/node14.html).
