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

--
http://mail.python.org/mailman/listinfo/python-list

Reply via email to