title: Python getting meaningful results from cProfile
body: <p>I have a Python script in a file which takes just over 30 seconds to run.  I am trying to profile it as I would like to cut down this time dramatically.  </p>
  
  <p>I am trying to profile the script using <code>cProfile</code>, but essentially all it seems to be telling me is that yes, the main script took a long time to run, but doesn't give the kind of breakdown I was expecting.  At the terminal, I type something like:</p>
  
  <pre><code>cat my_script_input.txt | python -m cProfile -s time my_script.py
  </code></pre>
  
  <p>The results I get are:</p>
  
  <pre><code>&lt;my_script_output&gt;
               683121 function calls (682169 primitive calls) in 32.133 seconds
  
     Ordered by: internal time
  
     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
          1   31.980   31.980   32.133   32.133 my_script.py:18(&lt;module&gt;)
     121089    0.050    0.000    0.050    0.000 {method 'split' of 'str' objects}
     121090    0.038    0.000    0.049    0.000 fileinput.py:243(next)
          2    0.027    0.014    0.036    0.018 {method 'sort' of 'list' objects}
     121089    0.009    0.000    0.009    0.000 {method 'strip' of 'str' objects}
     201534    0.009    0.000    0.009    0.000 {method 'append' of 'list' objects}
     100858    0.009    0.000    0.009    0.000 my_script.py:51(&lt;lambda&gt;)
        952    0.008    0.000    0.008    0.000 {method 'readlines' of 'file' objects}
   1904/952    0.003    0.000    0.011    0.000 fileinput.py:292(readline)
      14412    0.001    0.000    0.001    0.000 {method 'add' of 'set' objects}
        182    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
          1    0.000    0.000    0.000    0.000 fileinput.py:80(&lt;module&gt;)
          1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
          1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
          1    0.000    0.000    0.000    0.000 {isinstance}
          1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
          1    0.000    0.000    0.000    0.000 fileinput.py:184(FileInput)
          1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
          1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
  </code></pre>
  
  <p>This doesn't seem to be telling me anything useful.  The vast majority of the time is simply listed as:</p>
  
  <pre><code>   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
          1   31.980   31.980   32.133   32.133 my_script.py:18(&lt;module&gt;)
  </code></pre>
  
  <p>In <code>my_script.py</code>, Line 18 is nothing more than the closing <code>"""</code> of the file's header block comment, so it's not that there is a whole load of work concentrated in Line 18.  The script as a whole is mostly made up of line-based processing with mostly some string splitting, sorting and set work, so I was expecting to find the majority of time going to one or more of these activities.  As it stands, seeing all the time grouped in cProfile's results as occurring on a comment line doesn't make any sense or at least does not shed any light on what is actually consuming all the time.</p>
  
  <p><strong>EDIT:</strong> I've constructed a minimum working example similar to my above case to demonstrate the same behavior:</p>
  
  <p><em>mwe.py</em></p>
  
  <pre><code>import fileinput
  
  for line in fileinput.input():
      for i in range(10):
          y = int(line.strip()) + int(line.strip())
  </code></pre>
  
  <p>And call it with:</p>
  
  <pre><code>perl -e 'for(1..1000000){print "$_\n"}' | python -m cProfile -s time mwe.py
  </code></pre>
  
  <p>To get the result:</p>
  
  <pre><code>         22002536 function calls (22001694 primitive calls) in 9.433 seconds
  
     Ordered by: internal time
  
     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
          1    8.004    8.004    9.433    9.433 mwe.py:1(&lt;module&gt;)
   20000000    1.021    0.000    1.021    0.000 {method 'strip' of 'str' objects}
    1000001    0.270    0.000    0.301    0.000 fileinput.py:243(next)
    1000000    0.107    0.000    0.107    0.000 {range}
        842    0.024    0.000    0.024    0.000 {method 'readlines' of 'file' objects}
   1684/842    0.007    0.000    0.032    0.000 fileinput.py:292(readline)
          1    0.000    0.000    0.000    0.000 fileinput.py:80(&lt;module&gt;)
          1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
          1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
          1    0.000    0.000    0.000    0.000 fileinput.py:184(FileInput)
          1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
          1    0.000    0.000    0.000    0.000 {isinstance}
          1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
          1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
  </code></pre>
  
  <p>Am I using cProfile incorrectly somehow?</p>