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 ---
I don't see a good alternative to passing the main start time to subprocesses without using an environment variable. Using a temporary file or shared memory would be too much trouble for too little gain. So in this version each process uses its own start time as a reference for the elapsed time. Subprocesses will use a different elapsed time but that's just something to keep in mind when analysing the traces.
Reference: https://www.winehq.org/pipermail/wine-devel/2019-December/156960.html
include/wine/test.h | 55 +++++++++++++++++++++++++++++++-------------- 1 file changed, 38 insertions(+), 17 deletions(-)
diff --git a/include/wine/test.h b/include/wine/test.h index a919ce81d68..ae0a130fa62 100644 --- a/include/wine/test.h +++ b/include/wine/test.h @@ -56,6 +56,9 @@ /* debug level */ extern int winetest_debug;
+/* trace timing information */ +extern int winetest_time; + /* running in interactive mode? */ extern int winetest_interactive;
@@ -202,6 +205,10 @@ extern const struct test winetest_testlist[]; /* debug level */ int winetest_debug = 1;
+/* trace timing information */ +int winetest_time = 0; +DWORD winetest_start_time, winetest_last_time; + /* interactive mode? */ int winetest_interactive = 0;
@@ -272,11 +279,20 @@ void winetest_set_location( const char* file, int line ) data->current_line=line; }
+const char *winetest_elapsed(void) +{ + DWORD now; + + if (!winetest_time) return ""; + winetest_last_time = now = GetTickCount(); + return wine_dbg_sprintf( "%.3f", (now - winetest_start_time) / 1000.0); +} + void winetest_subtest( const char* name ) { struct tls_data *data = get_tls_data(); - printf( "%s:%d: Subtest %s\n", - data->current_file, data->current_line, name); + printf( "%s:%d:%s Subtest %s\n", + data->current_file, data->current_line, name, winetest_elapsed()); }
int broken( int condition ) @@ -302,8 +318,8 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args ) { if (condition) { - printf( "%s:%d: Test succeeded inside todo block: ", - data->current_file, data->current_line ); + printf( "%s:%d:%s Test succeeded inside todo block: ", + data->current_file, data->current_line, winetest_elapsed() ); vprintf(msg, args); InterlockedIncrement(&todo_failures); return 0; @@ -312,8 +328,8 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args ) { if (winetest_debug > 0) { - printf( "%s:%d: Test marked todo: ", - data->current_file, data->current_line ); + printf( "%s:%d:%s Test marked todo: ", + data->current_file, data->current_line, winetest_elapsed() ); vprintf(msg, args); } InterlockedIncrement(&todo_successes); @@ -324,17 +340,20 @@ int winetest_vok( int condition, const char *msg, __winetest_va_list args ) { if (!condition) { - printf( "%s:%d: Test failed: ", - data->current_file, data->current_line ); + printf( "%s:%d:%s Test failed: ", + data->current_file, data->current_line, winetest_elapsed() ); vprintf(msg, args); InterlockedIncrement(&failures); return 0; } else { - if (winetest_report_success) - printf( "%s:%d: Test succeeded\n", - data->current_file, data->current_line); + if (winetest_report_success || + (winetest_time && GetTickCount() >= winetest_last_time + 1000)) + { + printf( "%s:%d:%s Test succeeded\n", + data->current_file, data->current_line, winetest_elapsed() ); + } InterlockedIncrement(&successes); return 1; } @@ -357,7 +376,7 @@ void __winetest_cdecl winetest_trace( const char *msg, ... )
if (winetest_debug > 0) { - printf( "%s:%d: ", data->current_file, data->current_line ); + printf( "%s:%d:%s ", data->current_file, data->current_line, winetest_elapsed() ); __winetest_va_start(valist, msg); vprintf(msg, valist); __winetest_va_end(valist); @@ -368,7 +387,7 @@ 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 ); + printf( "%s:%d:%s Tests skipped: ", data->current_file, data->current_line, winetest_elapsed() ); vprintf(msg, args); skipped++; } @@ -505,8 +524,8 @@ 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", - GetCurrentProcessId(), test->name, + printf( "%04x:%s:%s %d tests executed (%d marked as todo, %d %s), %d skipped.\n", + GetCurrentProcessId(), test->name, winetest_elapsed(), successes + failures + todo_successes + todo_failures, todo_successes, failures + todo_failures, (failures + todo_failures != 1) ? "failures" : "failure", @@ -531,8 +550,8 @@ static LONG CALLBACK exc_filter( EXCEPTION_POINTERS *ptrs ) struct tls_data *data = get_tls_data();
if (data->current_file) - printf( "%s:%d: this is the last test seen before the exception\n", - data->current_file, data->current_line ); + printf( "%s:%d:%s this is the last test seen before the exception\n", + data->current_file, data->current_line, winetest_elapsed() ); printf( "%04x:%s: unhandled exception %08x at %p\n", GetCurrentProcessId(), current_test->name, ptrs->ExceptionRecord->ExceptionCode, ptrs->ExceptionRecord->ExceptionAddress ); @@ -570,6 +589,8 @@ int main( int argc, char **argv ) if (GetEnvironmentVariableA( "WINETEST_DEBUG", p, sizeof(p) )) winetest_debug = atoi(p); if (GetEnvironmentVariableA( "WINETEST_INTERACTIVE", p, sizeof(p) )) winetest_interactive = atoi(p); if (GetEnvironmentVariableA( "WINETEST_REPORT_SUCCESS", p, sizeof(p) )) winetest_report_success = atoi(p); + if (GetEnvironmentVariableA( "WINETEST_TIME", p, sizeof(p) )) winetest_time = atoi(p); + winetest_last_time = winetest_start_time = GetTickCount();
if (!strcmp( winetest_platform, "windows" )) SetUnhandledExceptionFilter( exc_filter ); if (!winetest_interactive) SetErrorMode( SEM_FAILCRITICALERRORS | SEM_NOGPFAULTERRORBOX );