Does cProfile include IO wait time?

Discussion in 'Python' started by Matthew Wilson, Jul 5, 2009.

  1. I have a command-line script that loads about 100 yaml files. It takes
    2 or 3 seconds. I profiled my code and I'm using pstats to find what is
    the bottleneck.

    Here's the top 10 functions, sorted by internal time:

    In [5]: _3.sort_stats('time').print_stats(10)
    Sat Jul 4 13:25:40 2009 pitz_prof

    756872 function calls (739759 primitive calls) in 8.621 CPU seconds

    Ordered by: internal time
    List reduced from 1700 to 10 due to restriction <10>

    ncalls tottime percall cumtime percall filename:lineno(function)
    15153 0.446 0.000 0.503 0.000 build/bdist.linux-i686/egg/yaml/reader.py:134(forward)
    30530 0.424 0.000 0.842 0.000 build/bdist.linux-i686/egg/yaml/scanner.py:142(need_more_tokens)
    98037 0.423 0.000 0.423 0.000 build/bdist.linux-i686/egg/yaml/reader.py:122(peek)
    1955 0.415 0.000 1.265 0.001 build/bdist.linux-i686/egg/yaml/scanner.py:1275(scan_plain)
    69935 0.381 0.000 0.381 0.000 {isinstance}
    18901 0.329 0.000 3.908 0.000 build/bdist.linux-i686/egg/yaml/scanner.py:113(check_token)
    5414 0.277 0.000 0.794 0.000 /home/matt/projects/pitz/pitz/__init__.py:34(f)
    30935 0.258 0.000 0.364 0.000 build/bdist.linux-i686/egg/yaml/scanner.py:276(stale_possible_simple_keys)
    18945 0.192 0.000 0.314 0.000 /usr/local/lib/python2.6/uuid.py:180(__cmp__)
    2368 0.172 0.000 1.345 0.001 build/bdist.linux-i686/egg/yaml/parser.py:268(parse_node)

    I expected to see a bunch of my IO file-reading code in there, but I don't. So
    this makes me think that the profiler uses CPU time, not
    clock-on-the-wall time.

    I'm not an expert on python profiling, and the docs seem sparse. Can I
    rule out IO as the bottleneck here? How do I see the IO consequences?

    TIA

    Matt
     
    Matthew Wilson, Jul 5, 2009
    #1
    1. Advertising

  2. En Sat, 04 Jul 2009 21:03:38 -0300, Matthew Wilson <>
    escribió:

    > I expected to see a bunch of my IO file-reading code in there, but I
    > don't. So
    > this makes me think that the profiler uses CPU time, not
    > clock-on-the-wall time.
    > I'm not an expert on python profiling, and the docs seem sparse. Can I
    > rule out IO as the bottleneck here? How do I see the IO consequences?


    I don't know either - but it's easy to check.
    Write a program that just reads a lot from /dev/zero, and look at its
    profile. You should be able to tell whether I/O time is included or not.

    --
    Gabriel Genellina
     
    Gabriel Genellina, Jul 6, 2009
    #2
    1. Advertising

  3. Matthew Wilson

    Robert Kern Guest

    On 2009-07-04 19:03, Matthew Wilson wrote:
    > I have a command-line script that loads about 100 yaml files. It takes
    > 2 or 3 seconds. I profiled my code and I'm using pstats to find what is
    > the bottleneck.
    >
    > Here's the top 10 functions, sorted by internal time:
    >
    > In [5]: _3.sort_stats('time').print_stats(10)
    > Sat Jul 4 13:25:40 2009 pitz_prof
    >
    > 756872 function calls (739759 primitive calls) in 8.621 CPU seconds
    >
    > Ordered by: internal time
    > List reduced from 1700 to 10 due to restriction<10>
    >
    > ncalls tottime percall cumtime percall filename:lineno(function)
    > 15153 0.446 0.000 0.503 0.000 build/bdist.linux-i686/egg/yaml/reader.py:134(forward)
    > 30530 0.424 0.000 0.842 0.000 build/bdist.linux-i686/egg/yaml/scanner.py:142(need_more_tokens)
    > 98037 0.423 0.000 0.423 0.000 build/bdist.linux-i686/egg/yaml/reader.py:122(peek)
    > 1955 0.415 0.000 1.265 0.001 build/bdist.linux-i686/egg/yaml/scanner.py:1275(scan_plain)
    > 69935 0.381 0.000 0.381 0.000 {isinstance}
    > 18901 0.329 0.000 3.908 0.000 build/bdist.linux-i686/egg/yaml/scanner.py:113(check_token)
    > 5414 0.277 0.000 0.794 0.000 /home/matt/projects/pitz/pitz/__init__.py:34(f)
    > 30935 0.258 0.000 0.364 0.000 build/bdist.linux-i686/egg/yaml/scanner.py:276(stale_possible_simple_keys)
    > 18945 0.192 0.000 0.314 0.000 /usr/local/lib/python2.6/uuid.py:180(__cmp__)
    > 2368 0.172 0.000 1.345 0.001 build/bdist.linux-i686/egg/yaml/parser.py:268(parse_node)
    >
    > I expected to see a bunch of my IO file-reading code in there, but I don't. So
    > this makes me think that the profiler uses CPU time, not
    > clock-on-the-wall time.


    It should be basically wall-clock time on Linux. The timer function underneath
    is gettimeofday(2). Look in Modules/_lsprof.c of the Python sources for the
    function hpTimer().

    --
    Robert Kern

    "I have come to believe that the whole world is an enigma, a harmless enigma
    that is made terrible by our own mad attempt to interpret it as though it had
    an underlying truth."
    -- Umberto Eco
     
    Robert Kern, Jul 8, 2009
    #3
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. David Pratt

    cProfile for python 2.4

    David Pratt, Mar 28, 2008, in forum: Python
    Replies:
    1
    Views:
    1,625
  2. Rahul

    cProfile.py not found.

    Rahul, Apr 4, 2009, in forum: Python
    Replies:
    10
    Views:
    698
  3. mk
    Replies:
    1
    Views:
    340
    Jonathan Hartley
    Dec 30, 2009
  4. Dysgraphic Programmer

    cProfile taking up too much memory?

    Dysgraphic Programmer, Mar 14, 2011, in forum: Python
    Replies:
    0
    Views:
    234
    Dysgraphic Programmer
    Mar 14, 2011
  5. Gelonida N

    cProfile and name spaces.

    Gelonida N, Sep 23, 2011, in forum: Python
    Replies:
    0
    Views:
    231
    Gelonida N
    Sep 23, 2011
Loading...

Share This Page