multithreading, performance, again...

[mk]

Hello everyone,

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