[Python-3000] test_profile failing

[Brett Cannon]

On Fri, Feb 29, 2008 at 1:15 PM, Guido van Rossum <guido at python.org> wrote:
>
> 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?

Flushing both stdout and stderr just before the logging call still
doesn't fix it for running the test through regrtest. There is an
extra call to 'exec' (not sure if it is just a method on some object
named that or the actual built-in) triggering a call to IOBase.flush()
that is only being triggered when the test is run under regrtest.
Looking in regrtest the only exec() call is when you hunt for
refleaks, not general testing so I am not sure where it is coming
from.

-Brett