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.