Bug #55135 Collect times used in test execution phases in mtr
Submitted: 9 Jul 2010 20:03 Modified: 14 Nov 2010 2:52
Reporter: Vladislav Vaintroub Email Updates:
Status: Closed Impact on me:
None 
Category:Tools: MTR / mysql-test-run Severity:S3 (Non-critical)
Version:5.5+ OS:Any
Assigned to: Bjørn Munch CPU Architecture:Any

[9 Jul 2010 20:03] Vladislav Vaintroub
Description:
Most of the time MTR spends doing something different but not executing test cases. This "something" makes MTR slow, or at least it makes an impression that MTR is sleeping. Fine-grainer reporting on where the time has gone would help much

How to repeat:
perl mysql-test-run.pl --suite=main
<skip>
It reports at the end..
Spent 558.016 of 1348 seconds executing testcases.

So , MTR is doing nothing 60% of the run time? Looking at CPU usage, at least it seems to be so.

Suggested fix:
Implement fine-graned reporting where MTR is spending its time. 
Maybe fix some extra waits.
[9 Jul 2010 20:22] Bjørn Munch
There is nothing wrong with the numbers, the rest of the time is spent stopping and restarting the server (which has to be done fairly often), copying files, checking server log for errors etc. Since most tests take very little time to run by mysqltest, the overhead is fairly large in comparison, often dependant of the disk I/O performance.

mysqltest reports back how long time it took to run the actual test script, while MTR sums these up and also clocks the total time. It's difficult (and I'm not sure how useful) to get more fine-grained timing data.
[9 Jul 2010 23:04] Vladislav Vaintroub
Bjorn, quite it is useful. I recall the regression about slow server shutdown, due to some flag not set and how hard it was to find the reason for slowdown and how I cursed this tool because it is extremely silent, to the point it would kill processes if it waits for too long and not even tell about it. I guess now it is a similar case. It used to be "500 or 800 seconds" or similar and now it is "500 of 1300". I'm sure copying times did not increase that much, so it will either be bug in MTR itself or in server startup/shutdown, but MTR just won't tell.
[18 Oct 2010 7:39] Bjørn Munch
Changing synopsis to something more general. Patch coming up. I will make it optional.
[18 Oct 2010 7:43] Bugs System
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/120934

3098 Bjorn Munch	2010-10-18
      Bug #55135 Collect times used in test execution phases in mtr
      Adding option --report-times
      Can't collect times if test run is aborted
[19 Oct 2010 12:09] Bugs System
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/121129

3100 Bjorn Munch	2010-10-19
      Bug #55135 Collect times used in test execution phases in mtr
      Adding option --report-times
      Can't collect times if test run is aborted
[19 Oct 2010 13:11] Bjørn Munch
Pushed to -mtr branches
[29 Oct 2010 15:32] Paul DuBois
Changes to test suite. No changelog entry needed.
[13 Nov 2010 16:23] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:alexander.nozdrin@oracle.com-20101113152450-2zzcm50e7i4j35v7) (merge vers: 5.6.1-m4) (pib:21)
[13 Nov 2010 16:32] Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (pib:21)
[16 Dec 2010 22:27] Bugs System
Pushed into mysql-5.5 5.5.9 (revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (version source revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (merge vers: 5.5.9) (pib:24)