https://bugs.winehq.org/show_bug.cgi?id=48094
Bug ID: 48094 Summary: Simplify debugging test timeouts Product: Wine Version: unspecified Hardware: x86 OS: Linux Status: NEW Severity: normal Priority: P2 Component: testcases Assignee: wine-bugs@winehq.org Reporter: fgouget@codeweavers.com Distribution: ---
When a Wine test times out one has to manually add traces to figure out where it gets stuck, or what the slow parts are. This is all the more difficult when the timeout is random and happens on a TestBot VM.
I propose to leverage the ok() calls to simplify getting timing information on the tests.
* Recognize the $WINETEST_TIME environment variable and, if it is set, add the elapsed time since the test started to the trace() and ok() messages.
* Ideally this elapsed time would have sub-second precision for those cases where it's more an issue of a long loop being slow. How many decimals to print is a matter of taste: one may be enough, three would feel quite standard if maybe a bit overkill.
* Also when $WINETEST_TIME is set, an ok() call would be printed even if successful when more than 1 second has elapsed since adding a message to the report (trace/ok/skip). This should allow identifying which part of the test causes trouble without altering its timing with thousands of traces.
* And when combined with $WINETEST_REPORT_SUCCESS of course every ok() call would print the elapsed time.
Once the Wine side is implemented a few other components should be updated: * The TestBot should allow setting $WINETEST_TIME when submitting a job.
* The TestBot should recognize the failure/todo/skip lines even with the extra timing information.
* The TestBot could be modified to automatically rerun and set $WINETEST_TIME if a test times out.
* The above may be particularly interesting for the full WineTest runs.
* We may also want to have test.winehq.org recognize the new failure/todo/skip line formats.
https://bugs.winehq.org/show_bug.cgi?id=48094
--- Comment #1 from François Gouget fgouget@codeweavers.com --- Created attachment 66113 --> https://bugs.winehq.org/attachment.cgi?id=66113 First attempt
This patch adds support for $WINETEST_TIME.
It also uses the $WINETEST_START_TIME to pass the start time to subprocesses so they all use the same elapsed time value. Unfortunately this causes msvcrt:environ to fail which means this version is not suitable for inclusion in Wine: https://www.winehq.org/pipermail/wine-devel/2019-December/156960.html
https://bugs.winehq.org/show_bug.cgi?id=48094
François Gouget fgouget@codeweavers.com changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |RESOLVED Resolution|--- |FIXED
--- Comment #2 from François Gouget fgouget@codeweavers.com --- This patch is in and the TestBot now has support for it.
commit 9f60ce22fb3e8291dda6f064655f6b3c877be1bf Author: Francois Gouget fgouget@codeweavers.com Date: Fri Jul 17 13:34:32 2020 +0200
tests: Trace elapsed time when $WINETEST_TIME is set.
This simplifies narrowing down where a test gets stuck or is slow if it times out but prints few messages. Note that the elapsed time is relative to the current process start time. So subprocesses will have a different elapsed time.
Wine-Bug: https://bugs.winehq.org/show_bug.cgi?id=48094 Signed-off-by: Francois Gouget fgouget@codeweavers.com Signed-off-by: Alexandre Julliard julliard@winehq.org
https://bugs.winehq.org/show_bug.cgi?id=48094
Alexandre Julliard julliard@winehq.org changed:
What |Removed |Added ---------------------------------------------------------------------------- Status|RESOLVED |CLOSED
--- Comment #3 from Alexandre Julliard julliard@winehq.org --- Closing bugs fixed in 6.10.