Stopping and resuming coverage with settrace/gettrace results in massive slowdown

[nedbat]

Originally reported by David MacIver (Bitbucket: david_maciver_, GitHub: Unknown)

---

My use case is as follows: I wish to install my own trace function, then once I am done resume any existing tracing. The natural way of doing this is existing = sys.gettrace(); (some stuff); sys.settrace(existing).

The problem is that doing this with coverage results in massive slowdowns because it prevents the optimisation that coverage gets from using the C tracing API instead of the python tracing API: It works because coverage is exposing a callable object that can be used as settrace, and that object is implemented in C, but because the tracing now goes through the whole Python function call overhead everything suddenly becomes a lot slower.

Here is the benchmark I am using:

#!python

#!/usr/bin/env python

from __future__ import print_function

import sys
import random
import time
import math

# Without coverage: 51.831627 +/- 9.388682 us
# With coverage and this line commented out: 86.116872 +/- 4.755677 us
# With coverage and this line in: 271.424899 +/- 8.705445 us
sys.settrace(sys.gettrace())

random.seed(1)


def hash_str(s):
    h = 0
    for c in s:
        h = (h * 31 + ord(c)) & (2 ** 64 - 1)
    return h

data = [
    hex(random.getrandbits(1024)) for _ in range(500)
]

N_SAMPLES = 100


def mean(xs):
    xs = list(xs)
    return sum(xs) / len(xs)


def sd(xs):
    return math.sqrt(mean(x ** 2 for x in xs) - mean(xs) ** 2)


if __name__ == '__main__':
    timing = []
    for _ in range(N_SAMPLES):
        start = time.time()
        for d in data:
            hash_str(d)
        timing.append(1000000 * (time.time() - start) / len(data))
    print("Runtime per example:", "%f +/- %f us" % (mean(timing), sd(timing)))

With the normal C tracer, running coverage is about 40% slower than without coverage, which is acceptable, but when I do a sys.settrace(sys.gettrace()) at the beginning it's now more than 5x slower, which is painful.

If you can make this code work transparently that would obviously be great, but my suspicion is that this may prove challenging. I would be happy to call some sort of coverage specific API to make this work.

---

• Bitbucket: https://bitbucket.org/ned/coveragepy/issue/397

[nedbat]

Turns out this was simple. Commit 3ee0a304d94e (bb) adds one line that completely removes the speed difference. Let me know if it works for you.

[nedbat]

Original comment by Florian Bruhin (Bitbucket: The-Compiler, GitHub: The-Compiler)

---

Commit 3ee0a304d94e (bb) doesn't seem to exist, and I also can't find anything related in the commit list.

[nedbat]

Oops, forgot to push it. It's here now.

[nedbat]

Original comment by David MacIver (Bitbucket: david_maciver_, GitHub: Unknown)

---

Confirmed: This fixes the problem for me.

though I spent a really long time getting very confused because I couldn't reproduce my original results at all until I realised it was because I was testing from the root of the coverage repo, so coverage was coming from the local module and thus using the much slower pure python implementation all the time. Oops.