[PATCH] tests: Trace elapsed time when $WINETEST_TIME is set.
Francois Gouget
fgouget at codeweavers.com
Thu Dec 5 06:50:32 CST 2019
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 at 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 );
--
2.20.1
More information about the wine-devel
mailing list