Why does cProfile cause functions to return different values?

Question

I am building a model in Python (3.3.1) for a fairly simple but fiddly contract with long term cashflows. The complete model is fairly complex in terms of time consumed and therefore I decided to try and profile it. However, I am getting different answers with and without profiling.

I have reduced the code to the following example:

def generate_cashflows( income ):
    contingent_expense = [1000.0]
    income_cf = [income]
    outgo_cf = [ -0.001 * contingent_expense[0] ]
    bank = [ income_cf[0] + outgo_cf[0] ]

    for t in range(1, 20):
        contingent_expense.append(1000.0)
        income_cf.append( income )
        outgo_cf.append( -contingent_expense[t] * 0.001 )
        bank.append(    bank[t-1] * (1+0.05)**(1/12)
                + income_cf[t]
                + outgo_cf[t]
                )
    return bank[-1]

print(str(generate_cashflows(0)))

Output:

calum@calum:~/pricing/model$ ./scratch.py 
-20.793337746348953
calum@calum:~/pricing/model$ python -m cProfile scratch.py
-20.0
     80 function calls in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.000    0.000 scratch.py:5(<module>)
    1    0.000    0.000    0.000    0.000 scratch.py:5(generate_cashflows)
   76    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
    1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
    1    0.000    0.000    0.000    0.000 {range}


calum@calum:~/pricing/model$ 

Is there a simple explanation for why this outputs a different answer each time? I have had a read of the manual but I don't see anything obvious.

Answer 1

First, I've attempted to reproduce with python3, and running "python3 scratch.py" and "python3 -m cProfile scratch.py" both print -20.7933... on my machine.

The reason -20.0 is returned on python 2.x is because the divison operator "/" worked differently in python2.x (http://legacy.python.org/dev/peps/pep-0238/)

In python2, 1/12 == 0

In python3, 1/12 == 0.08333333....

That means that in python2 the line

 bank.append(    bank[t-1] * (1+0.05)**(1/12)

simplifies to

 bank.append(    bank[t-1] * (1+0.05)**(0)

or

 bank.append(    bank[t-1] * 1

This is probably not what you intended. The python3 interpretation is probably correct and the python2 intepretation is fairly useless. As a side note, changing (1/12) to (1.0/12) results in identical output on both python2 and python3, and will make your code return the same output with or without profiling, but that's treating the symptom and not the cause.

My best guess as to why you are getting the different outputs with and without profiling is that you are using python3 without profiling and python2 with profiling. Using the same version of python when you are running your code with and without profiling is essential to get meaningful results.

The fact that you are using ./scratch.py indicates that you probably have a line like

#!/usr/bin/python3

at the top of scratch.py (although it isn't included in the provided code). When you run

./scratch.py

/usr/bin/python3 is used to execute the file

When you run

python -m cProfile scratch.py

your default python interpreter is used to execute the file (which i'm guessing is python2)

If you run "python" from the command line (without any other arguments) you'll probably see that the default intepreter is 2.X.

So getting your code to return identical output with and without profiling should be as simple as specifying python3 when you profile:

 python3 -m cProfile scratch.py