RFC How to deal with tests that spam the report
Francois Gouget
fgouget at codeweavers.com
Sun Feb 2 21:04:43 CST 2020
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&File=win32.report'
# 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,
--
2.20.1
More information about the wine-devel
mailing list