RFC: Flushing the test reports
Francois Gouget
fgouget at codeweavers.com
Tue Jan 24 09:17:47 CST 2017
When a test causes Windows to crash the test output is often lost, even
if it was redirected to a file : said file is often either 0-byte long
or is missing a huge chunk.
This is particularly annoying when the crash happens as part of WineTest
as then one has to manually run a bunch of tests to try and find which
one caused the issue. And it's not always which test caused the crash as
shown by the rasapi32:rasapi case (bug 42185).
So I have tested a couple of approaches to better pinpoint which test is
causing trouble, and possibly even which chunk of code in that test
causes the crash.
The first approach is simple: flush the WineTest report to disk between
each test (in Unix terms sync). It has little impact on performance and
in case of a crash the last 'dll:test start' line would clearly identify
the test responsible.
diff --git a/programs/winetest/main.c b/programs/winetest/main.c
index 50ebf4fd52a..df527734bb8 100644
--- a/programs/winetest/main.c
+++ b/programs/winetest/main.c
@@ -626,6 +626,11 @@ run_ex (char *cmd, HANDLE out_file, const char
*tempdir, DWORD ms)
PROCESS_INFORMATION pi;
DWORD wait, status;
+ /* Flush to disk so we know which test caused Windows to crash if it does */
+ if (out_file)
+ FlushFileBuffers(out_file);
+ FlushFileBuffers(GetStdHandle( STD_ERROR_HANDLE ));
+
GetStartupInfoA (&si);
si.dwFlags = STARTF_USESTDHANDLES;
si.hStdInput = GetStdHandle( STD_INPUT_HANDLE );
(the second flush is so WineTest's output too is flushed to disk in case
stdout is redirected to a file though I did not really check that this
part works)
Another approach is to add these calls in wine/test.h. This narrows the
location of the Windows crash down to an ok()/trace() interval, even
more narrow if WINETEST_REPORT_SUCCESS is set.
However this has quite an impact on performance:
* WineTest normally takes about 19 minutes.
* With the extra flushing this goes up to 29 minutes.
* With no flushing but report success I get 45 minutes.
* With both flushing and report success this shoots up to 315+ minutes.
The report success cases can be ignored but even in the normal case
the extra 10 minutes are probably not acceptable.
So I set the flushing code behind a $WINETEST_FLUSH check. So once
you've identified that, for instance, rasapi32:rasapi is causing
trouble, you can run it on its own with report success and flushing
to pinpoint where it goes wrong.
Of course on the TestBot you still won't get the report (until the
TestBot is changed appropriately), and you'll have to contend with the 2
minutes timeout but even with those options 88% of the tests completed
within the time limit on my machine.
That approach could be done with the patch below.
commit ef211f6480fe84fd7660314c27bcaa5630dd0c16
Author: Francois Gouget <fgouget at codeweavers.com>
Date: Sun Jan 22 02:57:23 2017 +0100
tests: Flush after each message if WINETEST_FLUSH is set.
Signed-off-by: Francois Gouget <fgouget at codeweavers.com>
diff --git a/include/wine/test.h b/include/wine/test.h
index aa89c55ca07..149b0a9ae14 100644
--- a/include/wine/test.h
+++ b/include/wine/test.h
@@ -52,6 +52,9 @@ extern int winetest_debug;
/* running in interactive mode? */
extern int winetest_interactive;
+/* flush after each trace */
+extern int winetest_flush;
+
/* current platform */
extern const char *winetest_platform;
@@ -199,6 +202,9 @@ int winetest_debug = 1;
/* interactive mode? */
int winetest_interactive = 0;
+/* flush to disk after every message? */
+int winetest_flush = 0;
+
/* current platform */
const char *winetest_platform = "windows";
@@ -291,6 +297,11 @@ int broken( int condition )
{
return (strcmp(winetest_platform, "windows") == 0) && condition;
}
+static void winetest_do_flush( void )
+{
+ if (winetest_flush)
+ FlushFileBuffers(GetStdHandle( STD_ERROR_HANDLE ));
+}
/*
* Checks condition.
@@ -313,6 +324,7 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args )
printf( "%s:%d: Test succeeded inside todo block: ",
data->current_file, data->current_line );
vprintf(msg, args);
+ winetest_do_flush();
InterlockedIncrement(&todo_failures);
return 0;
}
@@ -323,6 +335,7 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args )
printf( "%s:%d: Test marked todo: ",
data->current_file, data->current_line );
vprintf(msg, args);
+ winetest_do_flush();
}
InterlockedIncrement(&todo_successes);
return 1;
@@ -335,14 +348,18 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args )
printf( "%s:%d: Test failed: ",
data->current_file, data->current_line );
vprintf(msg, args);
+ winetest_do_flush();
InterlockedIncrement(&failures);
return 0;
}
else
{
if (report_success)
+ {
printf( "%s:%d: Test succeeded\n",
data->current_file, data->current_line);
+ winetest_do_flush();
+ }
InterlockedIncrement(&successes);
return 1;
}
@@ -369,6 +386,7 @@ void __winetest_cdecl winetest_trace( const char *msg, ... )
__winetest_va_start(valist, msg);
vprintf(msg, valist);
__winetest_va_end(valist);
+ winetest_do_flush();
}
}
@@ -378,6 +396,7 @@ void winetest_vskip( const char *msg, __winetest_va_list args )
printf( "%s:%d: Tests skipped: ", data->current_file, data->current_line );
vprintf(msg, args);
+ winetest_do_flush();
skipped++;
}
@@ -443,7 +462,10 @@ void winetest_wait_child_process( HANDLE process )
DWORD exit_code = 1;
if (WaitForSingleObject( process, 30000 ))
+ {
printf( "%s: child process wait failed\n", current_test->name );
+ winetest_do_flush();
+ }
else
GetExitCodeProcess( process, &exit_code );
@@ -452,12 +474,14 @@ void winetest_wait_child_process( HANDLE process )
if (exit_code > 255)
{
printf( "%s: exception 0x%08x in child process\n", current_test->name, exit_code );
+ winetest_do_flush();
InterlockedIncrement( &failures );
}
else
{
printf( "%s: %u failures in child process\n",
current_test->name, exit_code );
+ winetest_do_flush();
while (exit_code-- > 0)
InterlockedIncrement(&failures);
}
@@ -599,6 +623,7 @@ static int run_test( const char *name )
todo_successes, failures + todo_failures,
(failures + todo_failures != 1) ? "failures" : "failure",
skipped );
+ winetest_do_flush();
}
status = (failures + todo_failures < 255) ? failures + todo_failures : 255;
return status;
@@ -624,6 +649,7 @@ static LONG CALLBACK exc_filter( EXCEPTION_POINTERS *ptrs )
printf( "%s: unhandled exception %08x at %p\n", current_test->name,
ptrs->ExceptionRecord->ExceptionCode, ptrs->ExceptionRecord->ExceptionAddress );
fflush( stdout );
+ winetest_do_flush();
return EXCEPTION_EXECUTE_HANDLER;
}
@@ -660,6 +686,7 @@ int main( int argc, char **argv )
if (GetEnvironmentVariableA( "WINETEST_IS_CHILD", p, sizeof(p) )) winetest_is_child = atoi(p);
/* Identify any future process as a child of this one */
SetEnvironmentVariableA( "WINETEST_IS_CHILD", "1" );
+ if (GetEnvironmentVariableA( "WINETEST_FLUSH", p, sizeof(p) )) winetest_flush = atoi(p);
if (!strcmp( winetest_platform, "windows" )) SetUnhandledExceptionFilter( exc_filter );
if (!winetest_interactive) SetErrorMode( SEM_FAILCRITICALERRORS | SEM_NOGPFAULTERRORBOX );
Both approaches could be combined.
Comments?
Suggestions?
--
Francois Gouget <fgouget at codeweavers.com>
More information about the wine-devel
mailing list