[Python-3000] test_profile failing

[Guido van Rossum]

On Fri, Feb 29, 2008 at 12:39 PM, Brett Cannon <brett at python.org> wrote:
> On Fri, Feb 29, 2008 at 11:57 AM, Barry Warsaw <barry at python.org> wrote:
>  > -----BEGIN PGP SIGNED MESSAGE-----
>  >  Hash: SHA1
>  >
>  >
>  > On Feb 29, 2008, at 2:44 PM, Brett Cannon wrote:
>  >
>  >  > On Fri, Feb 29, 2008 at 11:22 AM, Barry Warsaw <barry at python.org>
>  >  > wrote:
>  >  >>
>  >
>  > >> I'll see what can be done to fix this particular problem, and try to
>  >  >> be more attentive to buildbot failure notices when they happen so we
>  >  >> can nip it closer to the bud.  Ultimately, it would be nice if we had
>  >  >> a process that prevented any breaking patch from landing, but we're
>  >  >> not there yet.
>  >  >
>  >  > A quick tweak to test_profile to print out what it got for output
>  >  > shows that some changes to io.py led to a different tracing.
>  >
>  >  Thanks Brett.  Do we just need to regen the expected output then?
>
>  Ah, the joys of expected output. =)
>
>  So here is the problem, and it is probably going to mean test_profile
>  needs to be rewritten...
>
>  When you run ``./python Lib/test/test_profile.py -r`` it runs the
>  profile and rewrites the file with the golden output. That's great and
>  all, but there was a slight difference with that golden output and
>  what was being generated by ``./python Lib/test/test_profile.py``. You
>  know what that difference was? An extra write call in io.py.
>
>  Turns out that when the golden output is generated that all streams
>  have their buffers empty. But when unittest prints its whole "__test__
>  .. ok" output it has stuff in a buffer since the "ok" has not been
>  written yet (in other words sys.stdout has not been fully flushed yet
>  while the test is running). If you change the print() call in
>  test_profile.regenerate_expected_output() to ``print('Regenerating %s
>  ... ' % filename, end='')`` then sys.stdout gets a flush() call during
>  the profiling for the golden output and everyone is happy.
>
>  But guess what happens when you run ``./python Lib/test/regrtest.py
>  test_profile``? That's right, there is no extra flush call!
>  regrtest.py outputs a single line, runs the test, and then prints
>  another line when it knows the result of the test.. Actually, there is
>  one less flush call in the regrtest.py case than in the generated
>  stuff, so I suspect regrtest or someone is doing an explicit flush or
>  something.
>
>  In other words, having the golden output have any I/O in it is making
>  it impossible to test. What would probably be best is to just strip
>  out any and all lines that do not directly involve profilee.py and
>  only compare those lines. I have no clue if a simple 'contains' check
>  will suffice because I don't know if the stat numbers are consistent
>  enough.
>
>  Anyway, I am out of time. Hopefully someone can finish up this work
>  some time today.

Good analysis. Can't we insert a flush somewhere before the profiler
is started so that the starting point is always with empty output
buffers?

-- 
--Guido van Rossum (home page: http://www.python.org/~guido/)