MySQL Bugs: #47663: mtr --parallel has weird output

Bug #47663	mtr --parallel has weird output
Submitted:	27 Sep 2009 23:15	Modified:	17 Jun 2010 19:36
Reporter:	Vladislav Vaintroub	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Tools: MTR / mysql-test-run	Severity:	S3 (Non-critical)
Version:	mysql-5.1-mtr	OS:	Windows
Assigned to:	Bjørn Munch	CPU Architecture:	Any

Description:
When I start 
mysql-test-run --paralel=4 
( I've a 4 core machine, it seems to work fine for a minute.
After that, it continues to function but brings pretty weird output (looks like end-of-line characters are missing or might be something else).

I'll attach the screenshot.

How to repeat:
mysql-test-run --parallel=4

mtr output

Attachment: mtr_parallel.png (image/x-png, text), 49.49 KiB.

That's weird, it's more than linefeeds missing.

Does it only happen with --parallel?

What's the last output before the weirdness starts?  I was just about to try hitting the scrollbar in the screen dump but that wouldn't work. :-)

Does it actually run the tests, and how does it all end?

When this happened, mtr started pretty nice with normal output. Then one of mysqld.exe died (I guess it was when shutting down, since all tests completed successfully at the end, but windows error reporting popped up informing me of died mysqld). 
Then it started to show output like that.

Now I tested with mysql-next-mr but stopped with:

main.udf                                 w3 [ pass ]   3152
binlog.binlog_stm_unsafe_warning 'stmt'  w3 [ fail ]
        Test ended at 2009-10-05 12:59:31

CURRENT_TEST: binlog.binlog_stm_unsafe_warning
Unable to open : No such file or directory
mysqltest: At line 102: command "perl" failed with error 2

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/88340

2851 Bjorn Munch	2009-10-27
      Bug #47663 mtr --parallel has weird output
      Some output is written, some is not
      Finally concluded it's a Perl bug: after running with parallel threads
        for a while, print suddenly ignores all but the first argument.
      Workaround: concatenate all the arguments into one, except in output that
        only comes before we start running tests

Please also change the functions "mtr_print_line()" and "mtr_print_thick_line()" to concatenate all their arguments (the repeated dash or equals, and the newline character) into one string.

No need for further review (from me) after that change.

Comment to the last comment: those functions don't call print with several arguments, they call print repeatedly which is very different. There is no need to concatenate them.

Sorry about my inexact wording - you are right, it is multiple calls now
(was multiple arguments before the change).

But is there any reason to keep them that way?
Combining the two calls (per function) into one will be essential if there ever is a risk that multiple processes / threads send their output to the same file, so it should just improve thread safety.

In my quick local test, it worked just fine:
   perl -e 'my $m; $m="-"; print $m x 3 . "\n";'

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/89304

2851 Bjorn Munch	2009-11-04
      Bug #47663 mtr --parallel has weird output
      Some output is written, some is not
      Finally concluded it's a Perl bug: after running with parallel threads
        for a while, print suddenly ignores all but the first argument.
      Workaround: concatenate all the arguments into one, except in output that
        only comes before we start running tests

Pushed to 5.1-mtr, trunk-mtr, next-mr-mtr and 6.0-codebase-mtr

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100220092844-jh07ayojyxn8uh9p) (version source revid:bjorn.munch@sun.com-20091104145701-e53aocvl875cpz99) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into 5.5.3-m2 (revid:alik@sun.com-20100220092622-wvhh1vfy5tjq4mhu) (version source revid:bjorn.munch@sun.com-20091104135716-k4u4vo35wzvkwpaa) (merge vers: 5.5.0-beta) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100220092730-paoo5t9gcajs5dq8) (version source revid:bjorn.munch@sun.com-20091104140003-934yjqw1npbjsktg) (pib:16)

Test suite changes. No changelog entry needed.

Setting report to Need Merge pending push to 5.1.x.

Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:azundris@mysql.com-20100222175719-viuh0f3gdsrkgv0r) (merge vers: 5.1.45) (pib:16)

No changelog entry needed.

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609140708-52rvuyq4q500sxkq) (merge vers: 5.1.45-ndb-6.2.19) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)