multithreading, performance, again...

[Oktaka Com]

On 30 Aralık 2009, 17:44, mk <mrk... at gmail.com> wrote:
> 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

See http://code.google.com/p/yappi/ if you want to profile
multithreaded python app.