Search code examples
pythontimetiming

Weird Timing Issue using time.time()


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?


Solution

  • 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!).