Velocity Reviews

Velocity Reviews (http://www.velocityreviews.com/forums/index.php)
-   Python (http://www.velocityreviews.com/forums/f43-python.html)
-   -   multithreading, performance, again... (http://www.velocityreviews.com/forums/t710248-multithreading-performance-again.html)

mk 12-30-2009 03:44 PM

multithreading, performance, again...
 
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_stat s(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


Oktaka Com 01-18-2010 02:40 PM

Re: multithreading, performance, again...
 
On 30 Aral─▒k 2009, 17:44, mk <mrk...@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_stat s(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.


All times are GMT. The time now is 01:37 PM.

Powered by vBulletin®. Copyright ©2000 - 2014, vBulletin Solutions, Inc.
SEO by vBSEO ©2010, Crawlability, Inc.