Weird Timing Issue using time.time()

Question

When I run this code:

t0time = time.time() 

print 2**100000 #hundred thousand

t1time = time.time() 
print (t1time - t0time)*1000,"ms"

and this code:

t0time = time.time() 

print 2**1000000 #million

t1time = time.time() 
print (t1time - t0time)*1000,"ms"

They output 70.0349807739 ms 6865.22507668 ms respectively. But when I don't print the values, replacing the print x lines with a = x, I get the same output, 0.00119209289551 ms for both, although they take obviously different times. Why is this?

Answer 1

The correct way to check how much time a simple expression take is to use timeit. This is especially convenient with IPython:

In [6]: %timeit 2**100000
100000000 loops, best of 3: 16.4 ns per loop

In [7]: %timeit 2**1000000
100000000 loops, best of 3: 16.4 ns per loop

In [8]: %timeit 2**100000000
100000000 loops, best of 3: 16.4 ns per loop
Compiler time: 0.64 s

Notice how the time taken is constant (16.4 nanoseconds. that's the time it takes to load whatever constant into the stack). However note how the last statement shows a Compiler time: 0.64s. So, as already have observed, the computation is performed by the compiler, not at runtime. In the last example the number is so big that the compilation time is significant and thus IPython displays it too.

If we try an even bigger number you see that the compiler time is the only one that changes significantly:

In [9]: %timeit 2**1000000000
100000000 loops, best of 3: 16.4 ns per loop
Compiler time: 8.62 s

We can have an other confirmation of what's happening looking directly at the bytecode that the compiler generates using the dis module:

In [10]: import dis
    ...: dis.dis(lambda: 2**100000)
    ...: 
  2           0 LOAD_CONST               3 (999002093014384507944032764330033590  ... MANY more digits ... 396223208402597025155304734389883109376) 
              3 RETURN_VALUE   

As you can see the code does not contain any BINARY_POWER operator which would compute the result. The timings we have did with timeit are simply timing the LOAD_CONST operation, which takes the same time, independently of the size of the number.

If we try to disassemble a program that uses an argument we do get the computation at run-time:

In [12]: dis.dis(lambda x: x**2)
  1           0 LOAD_FAST                0 (x) 
              3 LOAD_CONST               1 (2) 
              6 BINARY_POWER         
              7 RETURN_VALUE   

This optimization is performed by the peephole optimizer and only works with constants. Even code simply as:

In [13]: def function():
    ...:     a = 2
    ...:     return a ** 100000

Is not optimized, although it seems perfectly equivalent to using return 2 ** 100000:

In [14]: dis.dis(function)
  2           0 LOAD_CONST               1 (2) 
              3 STORE_FAST               0 (a) 

  3           6 LOAD_FAST                0 (a) 
              9 LOAD_CONST               2 (100000) 
             12 BINARY_POWER         
             13 RETURN_VALUE    

Also note that printing a number takes time proportional to its size! 2**100000 has about 30k digits, while 2**1000000 has about 300k digits! Printing the latter takes about 10 times the time take to print the former (and your timings do confirm this!).

Answer 2

When you don't print, it goes very fast. 0.00119209289551 ms is the smallest 'tick' that time.time() can catch.

So both report 0.00119209289551 ms.

To get an accurate estimate of speed. Time them over 100,000 loops and compare the total times.

Now if it seems like it takes longer, for example if you count of the time on your own, then here is what is probably happening:

Python is seeing the value 2**1000000 and saying "hey, that isn't using a variable or anything, so I can pre-calculate that before the code 'runs'." A lot of languages do that, they will convert things like 3*5 into 15, because, hey, why not? Might as well save computing power.

So the time your are waiting is time that python is spending 'pre-calculating' the values before your program runs. t0time isn't set because the script isn't running yet. I'm not a python expert, but this is how a lot of languages, both scripted and compiled, do things.