multithreading, performance, again...
mk
I have figured out (sort of) how to do profiling of multithreaded
programs with cProfile, it goes something like this:
#!/usr/local/bin/python
import cProfile
import threading
class TestProf(threading.Thread):
def __init__(self, ip):
threading.Thread.__init__(self)
self.ip = ip
def run(self):
prof = cProfile.Profile()
retval = prof.runcall(self.runmethod)
prof.dump_stats('tprof' + self.ip)
def runmethod(self):
pass
tp = TestProf('10.0.10.10')
tp.start()
tp.join()
The problem is, now that I've done profiling in the actual program
(profiled version here: http://python.domeny.com/cssh_profiled.py) with
9 threads and added up stats (using pstats.Stats.add()), the times I get
are trivial:
>>> p.strip_dirs().sort_stats('cumulative').print_stats(10)
Wed Dec 30 16:23:59 2009 csshprof9.156.44.113
Wed Dec 30 16:23:59 2009 csshprof9.156.46.243
Wed Dec 30 16:23:59 2009 csshprof9.156.46.89
Wed Dec 30 16:24:00 2009 csshprof9.156.47.125
Wed Dec 30 16:24:00 2009 csshprof9.156.47.17
Wed Dec 30 16:24:00 2009 csshprof9.156.47.29
Wed Dec 30 16:24:01 2009 csshprof9.167.41.241
Wed Dec 30 16:24:02 2009 csshprof9.168.119.15
Wed Dec 30 16:24:02 2009 csshprof9.168.119.218
39123 function calls (38988 primitive calls) in 6.004 CPU seconds
Ordered by: cumulative time
List reduced from 224 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
9 0.000 0.000 6.004 0.667 cssh.py:696(runmethod)
100 0.004 0.000 5.467 0.055 threading.py:389(wait)
82 0.025 0.000 5.460 0.067 threading.py:228(wait)
400 5.400 0.013 5.400 0.013 {time.sleep}
9 0.000 0.000 5.263 0.585 cssh.py:452(ssh_connect)
9 0.003 0.000 5.262 0.585 client.py:226(connect)
9 0.001 0.000 2.804 0.312
transport.py:394(start_client)
9 0.005 0.001 2.254 0.250 client.py:391(_auth)
18 0.001 0.000 2.115 0.117
transport.py:1169(auth_publickey)
18 0.001 0.000 2.030 0.113
auth_handler.py:156(wait_for_response)
<pstats.Stats instance at 0xb7ebde8c>
It's not burning CPU time in the main thread (profiling with cProfile
indicated smth similar to the above), it's not burning it in the
individual worker threads - so where the heck it is burning this CPU
time? bc 'top' shows heavy CPU load during most of the time of the
program run.
help...
regards,
mk
Antoine Pitrou
> 39123 function calls (38988 primitive calls) in 6.004 CPU
> seconds
>
>
> It's not burning CPU time in the main thread (profiling with cProfile
> indicated smth similar to the above), it's not burning it in the
> individual worker threads
What do you mean, it's not burning CPU time? The profile output above
seems to suggest 6 CPU seconds were "burnt".
By the way, I don't think running several concurrent profile sessions
dumping *to the same stats file* is supported, consider using a separate
stats file for each thread or the results may very well be bogus.
Oktaka Com
See http://code.google.com/p/yappi/ if you want to profile
multithreaded python app.