Why does time incorrectly report such a fast time?

Question

I was playing around with big numbers, and wrote the following code:

import time

def ispow2(n):
    return not n & n - 1

start = time.clock()
ispow2(2**100000000)
end = time.clock()

print(end - start)

Surprisingly, this outputs 0.016864107385627148, and insanely short amount of time. However, it actually takes about 8 seconds, not 0.02.

Why is the time module reporting such a fast time when it clearly takes longer than that to run the code?

According to time, clock() is deprecated, so I switched it out for process_time(). I get near identical results. Same with perf_counter().

Note: this is running from IDLE. When I ran from command line, the time seemed accurately reported. Perhaps pythonw.exe has something to do with this, but what?

However, when I add another 0 to the end of 2**10..., it takes ~7 seconds on command line, but reported 0.1781140373572865.

@thefourtheye It took ~8 seconds, most of which IDLE was not responding. Trying out CMD. — Justin, May 09 '14 at 05:36
I'm seeing about 80 ms in the Python 2.7 interactive console, after wrapping your test up in a function. Interestingly, after pressing enter after the last line of the function, the console hung for a second or two... even though nothing was executing. — Jonathon Reinhart, May 09 '14 at 05:38
@JonathonReinhart exactly what I was seeing: the console hung for ~8 seconds. — Justin, May 09 '14 at 05:39
for performance measurements you could use `from timeit import default_timer as timer`: it chooses the best timer for your platform, Python version. — jfs, May 09 '14 at 11:37

Justin · Accepted Answer · 2014-05-09T06:03:34.540

python.exe and pythonw.exe are optimizing the code before running. It seems that the 2**100000000 is being pre-computed. This small edit to the code:

import time

print("program entered")

def ispow2(n):
    return not n & n - 1

start = time.perf_counter()
ispow2(2**100000000)
end = time.perf_counter()

print(end - start)

Produces the following output completely after the wait:

program entered
0.01701506924359556

So the program doesn't even run until after the majority of the wait.

Data that suggests that this is with the 2**... part (running from command line):

power of two|approximate wait time|reported time
1000000000  | 6  seconds          |0.1637752267742188
10000000000 | 62 seconds          |1.6400543291627092

On that last run, there was a clear ~1.5 second wait between the output of program entered and 1.6400543291627092.

[`PyCode_Optimize`](http://hg.python.org/cpython/file/04f714765c13/Python/peephole.c#l331) detects the bytecode pattern `LOAD_CONST`, `LOAD_CONST`, `BINOP`, and calls [`fold_binops_on_constants`](http://hg.python.org/cpython/file/04f714765c13/Python/peephole.c#l138) to evaluate the operation and replace it with a single `LOAD_CONST`. If you import the script, the module's code object is cached in the `__pycache__` directory, where you'll see that it's several megabytes, in agreement with `sys.getsizeof(2**100000000)`. — Eryk Sun, May 09 '14 at 06:19

score 3 · Answer 2 · answered May 09 '14 at 11:51

The constant is precomputed:

>>> import dis
>>> dis.dis(lambda: 2**100)
1           0 LOAD_CONST               3 (1267650600228229401496703205376)
            3 RETURN_VALUE

Compare:

$ ./python -mtimeit "2**1000"
10000000 loops, best of 3: 0.0601 usec per loop
$ ./python -mtimeit "2**10000"
10000000 loops, best of 3: 0.0584 usec per loop

vs.:

$ ./python -mtimeit -s "p=1000" "2**p"
100000 loops, best of 3: 6.89 usec per loop
$ ./python -mtimeit -s "p=10000" "2**p"
10000 loops, best of 3: 94.2 usec per loop

In the first case the time doesn't change after increasing the power 10 times. It is changed as it should in the second case there the power is a variable.

score 0 · Answer 3 · answered May 09 '14 at 05:48

The best way to time small bits of code is with timeit

If I use timeit on my computer and compare to yours, I get a similar number using Python 3.4:

import time
import timeit

def ispow2(n):
    return not n & n - 1

n=10

start = time.time()
for i in range(n):
    ispow2(2**100000000)
end = time.time()

print(end - start)

print(timeit.Timer('ispow2(2**100000000)', setup="from __main__ import ispow2").timeit(number=n))

Prints:

0.1257798671722412
0.12608672981150448

I used time.time() vs time.clock() but both seem to work.

Why does time incorrectly report such a fast time?

3 Answers3