This simplifies narrowing down where a test gets stuck or is slow if it times out but prints few messages.
Wine-Bug: https://bugs.winehq.org/show_bug.cgi?id=48094 Signed-off-by: Francois Gouget fgouget@codeweavers.com ---
If this approach is acceptable I'll add support for it on the TestBot and on the test.winehq.org site: allowing to set $WINETEST_TIME and recognizing the modified failure lines.
include/wine/test.h | 72 ++++++++++++++++++++++++++++++++++----------- 1 file changed, 55 insertions(+), 17 deletions(-)
diff --git a/include/wine/test.h b/include/wine/test.h index aeb9a55dee2..dea94fa60f0 100644 --- a/include/wine/test.h +++ b/include/wine/test.h @@ -58,6 +58,9 @@ /* debug level */ extern int winetest_debug;
+/* trace timing information */ +extern int winetest_time; + /* running in interactive mode? */ extern int winetest_interactive;
@@ -216,6 +219,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;
@@ -304,11 +311,27 @@ void winetest_set_location( const char* file, int line ) data->current_line=line; }
+const char *winetest_elapsed(void) +{ + DWORD now; + char *res; + + if (!winetest_time) + return ""; + + now = GetTickCount(); + winetest_last_time = now; + res = get_temp_buffer( 11 ); /* enough for a day */ + sprintf( res, "%.3f", (now - winetest_start_time) / 1000.0); + release_temp_buffer( res, strlen(res) + 1 ); + return res; +} + 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 ) @@ -334,8 +357,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; @@ -344,8 +367,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); @@ -356,17 +379,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; } @@ -389,7 +415,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); @@ -400,7 +426,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++; } @@ -630,8 +656,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", @@ -656,8 +682,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 ); @@ -695,6 +721,18 @@ 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); + if (GetEnvironmentVariableA( "WINETEST_START_TIME", p, sizeof(p) )) + winetest_start_time = atoi(p); + else + { + char time_str[11]; + winetest_start_time = GetTickCount(); + /* Export the test start time for child processes */ + sprintf( time_str, "%u", winetest_start_time ); + SetEnvironmentVariableA( "WINETEST_START_TIME", time_str ); + } + winetest_last_time = winetest_start_time;
if (!strcmp( winetest_platform, "windows" )) SetUnhandledExceptionFilter( exc_filter ); if (!winetest_interactive) SetErrorMode( SEM_FAILCRITICALERRORS | SEM_NOGPFAULTERRORBOX );
On Thu, 5 Dec 2019, Francois Gouget wrote:
This simplifies narrowing down where a test gets stuck or is slow if it times out but prints few messages.
Wine-Bug: https://bugs.winehq.org/show_bug.cgi?id=48094 Signed-off-by: Francois Gouget fgouget@codeweavers.com
If this approach is acceptable I'll add support for it on the TestBot and on the test.winehq.org site: allowing to set $WINETEST_TIME and recognizing the modified failure lines.
What's the status on this patch? Should I use a different approach?
Francois Gouget fgouget@codeweavers.com writes:
@@ -695,6 +721,18 @@ 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);
- if (GetEnvironmentVariableA( "WINETEST_START_TIME", p, sizeof(p) ))
winetest_start_time = atoi(p);- else
- {
char time_str[11];winetest_start_time = GetTickCount();/* Export the test start time for child processes */sprintf( time_str, "%u", winetest_start_time );SetEnvironmentVariableA( "WINETEST_START_TIME", time_str );- }
I don't think the test runtime should be modifying the environment. This even breaks a test:
../../../tools/runtest -q -P wine -T ../../.. -M msvcrt.dll -p msvcrt_test.exe environ && touch environ.ok environ.c:230: Test failed: Expected environment block pointer element to be non-NULL wine: Unhandled page fault on read access to 00000000 at address 7EAFFB4D (thread 0044), starting debugger...
-
Alexandre Julliard -
Francois Gouget