[PATCH] tests: Trace elapsed time when $WINETEST_TIME is set.

[Francois Gouget]

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(a)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 );
-- 
2.20.1