Enable autoFlush for JUnit printstream so we get output as the tests run

Review Request #4102 — Created July 20, 2016 and submitted

cheister
pants
flush-test-buffer
3698
pants-reviews
jsirois, kwlzn, zundel

Enable autoFlush for JUnit printstream so we get output as the tests run

Without autoFlush the buffer is never flushed and we get no output during the test run.

Travis CI: https://travis-ci.org/pantsbuild/pants/builds/146186132

And installing the new junit-runner.jar and running java tests in the Pants repo.

In regards to the speedup in https://rbcommons.com/s/twitter/r/4101/

The tests are not as fast with the autoFlush enabled but hopefully they are fast enough?

$ ./pants test.junit tests/java/org/pantsbuild/tools/junit/impl/::
...
11:40:57 00:15       [run]
                     Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=256m; support was removed in 8.0
                     Java HotSpot(TM) 64-Bit Server VM warning: ignoring option UseSplitVerifier; support was removed in 8.0
                     Auto-detected 8 processors, using -parallel-threads=8
                     ........................................................................................................................................................................................................................................................................................................................................................................................
                     Time: 148.382

                     OK (376 tests)
ST
  1. autoFlush - A boolean; if true, the output buffer will be flushed whenever a byte array is written, one of the println methods is invoked, or a newline character or byte ('\n') is written

    Flushing for every byte array is pretty aggressive. And a 3x increase in runtime (even between John's machine and your own) is... significant.

    Does this call for periodic manual flushing, or a timed flush?

    1. The only thing that would keep the test run looking responsive is to is flush after every test. Which is pretty close to what you get with autoFlush.

      You could flush at the very end of the test run but then you will only see output once all of the tests have run.

      The 3x increase isn't really the right comparison since the current code does not write anything to stdout and stderr. The better comparison is how this change compares to the original unbuffered code which takes around 1200 seconds. So we will still get a large speed up.

      13:48:20 00:01       [run]
                           Java HotSpot(TM) 64-Bit Server VM warning: ignoring option MaxPermSize=256m; support was removed in 8.0
                           Java HotSpot(TM) 64-Bit Server VM warning: ignoring option UseSplitVerifier; support was removed in 8.0
                           Auto-detected 8 processors, using -parallel-threads=8
                           ................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
                           Time: 1,201.17
      
                           OK (376 tests)
      
    2. I patched this in and get 180s timeout consistently just like before on my machine vs ~50s. The interesting CI in this case is not travis but Jenkins - can you link that / get it to go green?
      I think we need flush of every . for user-experience, but buffering of individual test method stdout/stderr with only flush at the end of the individual methods. Presumably that would provide ~same performance of my prior patch and the experience would be decent, even for the output modes that send stdios to the console. If not, those modes might need special treatment. The speed tradeoff though in those cases is at least asked for by the user specifying the mode.

    3. Noting that I'm happy to see my patch reverted since its driver was getting Jenkins green and Jenkins appears to be currently ~unuseable anyway due to spot price issues.  It sounds like as things stand, my patch will make the next publish of the junit tool jar unuseable which is not good.
    4. If you bump the timeout in tests/java/org/pantsbuild/tools/junit/impl/BUILD to something higher than 180, how long does this patch take to run on your machine?

      It seems like we'll still get a significant performance increase with this change and can comeback later and optimize the buffer flushes if needed.

    5. Jenkins is the only target, so you should try that strategy - if needed - to get the Jenkins CI for this RB green.  That the only standard that matters zeroth order.
      But, again, if Jenkins is unuseable I'm happy for you to instead just revert my patch for now.
    6. On my machine I did 2 runs with 1000s timeout and got 314 seconds and 316 seconds.
      This is all using my original baseline of `./pants test.junit tests/java/org/pantsbuild/tools/junit/impl/::`
    7. Do you mind if we ship this fix and comeback and revisit the fixes for Jenkins in a follow-up?

    8. SGTM. I did just confirm its in fact a fix on my machine by running my benchmark prior to my broken fix, which takes ~510s on average.
  2. 
      
ZU
  1. 
      
  2. So are you saying we get no output until all the tests or finished or are you concerned with flushing the buffer in the middle of a test?
    Maybe a more performant solution would be to start a thread that flushes these streams every few seconds?

    1. Without this change you get no output from the tests at all unless they write more than 8092 bytes (the default size of the output buffer).

    2. I've use the background thread on a timer flushing logic before to good effect. It balances our want to occasionally see output with the ability not to call flush too often and degrade performance.

  3. 
      
CH
JS
  1. Ship It!
  2. 
      
ZU
  1. Ship It!
  2. 
      
CH
Review request changed

Status: Closed (submitted)

Change Summary:

submitted as commit: 0ed2684eb8e5aafc1eabac21f52475203c883913

Loading...