Some tests loop on system resources like fonts and issue todos, skips or even traces on every iteration. Depending on the machine configuration this can result in a lot of lines and push WineTest reports above the 1.5 MB limit.
For instance the new Debian Testing VM has some extra fonts (though I did not manually add any extra font packages), resulting in some todo messages being repeated 772 times and dwrite:font generating 160 KB of traces. Same for gdi32:font. So of course the report exceeds the 1.5 MB.
https://testbot.winehq.org/JobDetails.pl?Key=64300
It would be possible to uninstall some font packages to reduce this but that would mean accepting that test.winehq.org forces us to artificially limit the test coverage. Plus uninstalling fonts would not help with kernel32:virtual (90 KB), shell32:ebrowser (17 KB), etc.
So when WINETEST_DEBUG=1 this patch automatically mutes the lines that generate more than 50 such messages. When it happens a message is issued so the developer knows what happened, and a count of silenced lines is given at the end. And setting WINETEST_DEBUG >= 2 disables this filtering.
The rationale here is that after the first few repetitions additional lines don't really bring any new information: sure GetFontFaceReference() is unimplemented, there's no point saying so 772 times!
In contrast other todo lines still bring new information. This is why this patch mutes individual lines rather than limiting the total number of non-essential lines in a test unit.
The drawback is that some tests like ieframe:webbrowser have 10 lines that each generate between 15 and 26 lines of output. So they all fly under the 50 repeats threshold but still generate 14 KB all together.
One option would be to lower the threshold from 50 to... 20, 15, 10?
Or we could have each test unit count the non-essential lines and silence all of them after some threshold. But then any todo, skip or trace that comes after a spammer would be lost :-(
Here are some commands to get a sense of things:
wget -O wtbdebiant_win32.report \ 'https://testbot.winehq.org/GetTaskFile.pl?Job=64300&Step=1&Task=1&am...'
# Non-essential lines repeat counts egrep '^[a-z0-9]*.c:[0-9]*: ' wtbdebiant_win32.report | \ egrep -v ': Test (failed|succeeded inside todo block):' | \ sed -e 's/^([a-z0-9]*.c:[0-9]*: Test[^:]*):.*$/\1/' -e t \ -e 's/^([a-z0-9]*.c:[0-9]*:).*$/\1 Trace/' | \ sort | uniq -c | sort -b -n -r | head -n 10
772 font.c:7947: Test marked todo 772 font.c:7943: Test marked todo 772 font.c:7934: Test marked todo 522 virtual.c:4056: Test marked todo 256 ebrowser.c:1659: Test marked todo 189 font.c:3238: Tests skipped 184 virtual.c:4015: Test marked todo 151 font.c:3940: Test marked todo 135 istream.c:274: Test marked todo 128 sock.c:1252: Test marked todo
# Per test unit non-essential line counts egrep '^[a-z0-9]*.c:[0-9]*: ' wtbdebiant_win32.report | \ egrep -v ': Test (failed|succeeded inside todo block):' | \ sed -e 's/^([a-z0-9]*.c):[0-9]*:.*$/\1/' | \ sort | uniq -c | sort -b -n -r | head -n10
2988 font.c (yep, this mixes dwrite:font, gdi32:font and gdiplus:font) 916 virtual.c 485 msg.c 437 webbrowser.c 412 metafile.c 399 info.c 372 sock.c 351 security.c 327 graphics.c 316 file.c
include/wine/test.h | 77 ++++++++++++++++++++++++++++++++++++--------- 1 file changed, 63 insertions(+), 14 deletions(-)
diff --git a/include/wine/test.h b/include/wine/test.h index a919ce81d68..9f308b4c4ab 100644 --- a/include/wine/test.h +++ b/include/wine/test.h @@ -62,6 +62,9 @@ extern int winetest_interactive; /* report successful tests (BOOL) */ extern int winetest_report_success;
+/* silence todos and skips above this threshold */ +extern int winetest_mute_threshold; + /* current platform */ extern const char *winetest_platform;
@@ -211,6 +214,9 @@ const char *winetest_platform = "windows"; /* report successful tests (BOOL) */ int winetest_report_success = 0;
+/* silence todos and skips above this threshold */ +int winetest_mute_threshold = 50; + /* passing arguments around */ static int winetest_argc; static char** winetest_argv; @@ -222,6 +228,12 @@ static LONG failures; /* number of failures */ static LONG skipped; /* number of skipped test chunks */ static LONG todo_successes; /* number of successful tests inside todo block */ static LONG todo_failures; /* number of failures inside todo block */ +static LONG muted_traces; /* number of silenced traces */ +static LONG muted_skipped; /* same as skipped but silent */ +static LONG muted_todo_successes; /* same as todo_successes but silent */ + +/* counts how many times a given line printed a message */ +static LONG line_counters[16384];
/* The following data must be kept track of on a per-thread basis */ struct tls_data @@ -284,6 +296,25 @@ int broken( int condition ) return (strcmp(winetest_platform, "windows") == 0) && condition; }
+static LONG winetest_add_line( void ) +{ + struct tls_data *data; + int index, count; + + if (winetest_debug > 1) + return 0; + + data = get_tls_data(); + index = data->current_line % ARRAY_SIZE(line_counters); + count = InterlockedIncrement(line_counters + index) - 1; + if (count == winetest_mute_threshold) + printf( "%s:%d Line has been silenced after %d occurences\n", + data->current_file, data->current_line, + winetest_mute_threshold); + + return count; +} + /* * Checks condition. * Parameters: @@ -310,13 +341,19 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args ) } else { - if (winetest_debug > 0) + if (!winetest_debug || + winetest_add_line() < winetest_mute_threshold) { - printf( "%s:%d: Test marked todo: ", - data->current_file, data->current_line ); - vprintf(msg, args); + if (winetest_debug > 0) + { + printf( "%s:%d Test marked todo: ", + data->current_file, data->current_line ); + vprintf(msg, args); + } + InterlockedIncrement(&todo_successes); } - InterlockedIncrement(&todo_successes); + else + InterlockedIncrement(&muted_todo_successes); return 1; } } @@ -353,24 +390,32 @@ void __winetest_cdecl winetest_ok( int condition, const char *msg, ... ) void __winetest_cdecl winetest_trace( const char *msg, ... ) { __winetest_va_list valist; - struct tls_data *data = get_tls_data();
- if (winetest_debug > 0) + if (!winetest_debug) + return; + if (winetest_add_line() < winetest_mute_threshold) { - printf( "%s:%d: ", data->current_file, data->current_line ); + struct tls_data *data = get_tls_data(); + printf( "%s:%d ", data->current_file, data->current_line ); __winetest_va_start(valist, msg); vprintf(msg, valist); __winetest_va_end(valist); } + else + InterlockedIncrement(&muted_traces); }
void winetest_vskip( const char *msg, __winetest_va_list args ) { - struct tls_data *data = get_tls_data(); - - printf( "%s:%d: Tests skipped: ", data->current_file, data->current_line ); - vprintf(msg, args); - skipped++; + if (winetest_add_line() < winetest_mute_threshold) + { + struct tls_data *data = get_tls_data(); + printf( "%s:%d Tests skipped: ", data->current_file, data->current_line ); + vprintf(msg, args); + InterlockedIncrement(&skipped); + } + else + InterlockedIncrement(&muted_skipped); }
void __winetest_cdecl winetest_skip( const char *msg, ... ) @@ -505,7 +550,11 @@ static int run_test( const char *name )
if (winetest_debug) { - printf( "%04x:%s: %d tests executed (%d marked as todo, %d %s), %d skipped.\n", + if (muted_todo_successes || muted_skipped || muted_traces) + printf( "%04x:%s Silenced %d todos, %d skips and %d traces.\n", + GetCurrentProcessId(), test->name, + muted_todo_successes, muted_skipped, muted_traces); + printf( "%04x:%s %d tests executed (%d marked as todo, %d %s), %d skipped.\n", GetCurrentProcessId(), test->name, successes + failures + todo_successes + todo_failures, todo_successes, failures + todo_failures,
On Mon, 3 Feb 2020, Francois Gouget wrote: [...]
The rationale here is that after the first few repetitions additional lines don't really bring any new information: sure GetFontFaceReference() is unimplemented, there's no point saying so 772 times!
In contrast other todo lines still bring new information. This is why this patch mutes individual lines rather than limiting the total number of non-essential lines in a test unit.
The drawback is that some tests like ieframe:webbrowser have 10 lines that each generate between 15 and 26 lines of output. So they all fly under the 50 repeats threshold but still generate 14 KB all together.
Note that even so this patch is sufficient to get the new debiant VM under 1.5 MB (from 1.7 MB to 1.3 MB). Same thing for the cw-gtx560 machine.
https://test.winehq.org/data/errors.html
So maybe we can use this approach for now and worry about more drastic options once it's no longer sufficient.
(as we keep adding tests all options will be insufficient eventually)
-
Francois Gouget