Captured output slows down tests a lot

[sk-]

First of all I wanted to say that I recently started using green, and it's great, I'm really happy with it.

However, I noticed that when a test prints to stdout, the tests becomes super slow.

Here are some timings:

Without any prints: Ran 731 tests in 0.644s using 4 processes
Adding a print('test'): Ran 731 tests in 3.856s using 4 processes
Adding a print('test') and running with green -q: Ran 731 tests in 4.057s using 4 processes

which is almost 6 times slower than when there's no output.

Any idea what the problem may be? Or how to provide some extra details.

[CleanCut]

@sk- More details, please!

• What's the output of green -V?
• What is your operating system, including version?
• Have you timed this same code with python's built-in test runner?
• Is this code open source? Can we see it?

[sk-]

$ green -V
Green 3.2.0, Coverage 5.2.1, Python 3.7.7

Operating System: macOS Catalina 10.15.4

The following file reproduces the problem:

import unittest

import parameterized

class GreenTest(unittest.TestCase):
    @parameterized.parameterized.expand([[i] for i in range(1000)])
    def test_speed(self, a):
        print('testing...')
        self.assertGreaterEqual(a, 0)

Green

Without print: Ran 1000 tests in 0.836s using 4 processes
With print: Ran 1000 tests in 9.088s using 4 processes

Python runner

Without print: Ran 1000 tests in 0.047s
With print: Ran 1000 tests in 0.108s

[CleanCut]

Perfect! That's very useful info.

[quincysoul]

I'm curious if this project might do Tee-Object or tee like operations: output to stdout allowed and capture (if wanted). pytest definitely doesn't support it.

[sk-]

Also important to note is the fact that the runner, even without captured output seems to be about 17x slower compared to python's unittest runner. Could it be that there's a noticeable overhead introduced by using multiple processes?

With more complex test suites I still see a slowdown of about 4x. But maybe my tests are still to fast to get a performance advantage by using multiprocesses.

If I use green with the option -s 1, I get slightly slower test runs.

[CleanCut]

I'm curious if this project might do Tee-Object or tee like operations: output to stdout allowed and capture (if wanted). pytest definitely doesn't support it.

No, green does not support that currently.

[CleanCut]

@sk- By default, entire test modules are given to a single sub-process to test. The only exception is if you specify specific classes or methods to test on the command-line. So the performance gains from green come from having enough modules to spread among several subprocesses.

Green itself uses unittest under the hood. That approach is a blessing and a curse.

The advantage is that green doesn't invent any new test framework stuff and just uses unittest for a lot of the actual work.

The disadvantage is everything green does is on top of unittest, so there's a bunch of overhead. There's the fixed overhead of launching some number of subprocesses. There's the mostly-fixed overhead of loading all the code to be tested (it's almost always loaded exactly twice - once by the main process and once by the process that actually runs the tests). Then there's the highly-variable overhead of whatever we add on top of the regular functionality--like intercepting output. The whole point of Green was to make output nice, so we do a lot of extra work on anything we output in our output handling.

Although it would be nice to be more optimized, it's not a common problem that folks have with green, so I don't consider this a bug. My advice would be "don't print so much stuff!" Having said that, I would be more than happy to accept any pull requests people make to optimize the performance of green! To that end, I've marked this issues as enhancement and help wanted.