[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.

Wine-Bug: https://bugs.winehq.org/show_bug.cgi?id=48094
Signed-off-by: Francois Gouget <fgouget(a)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

[Francois Gouget]

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(a)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(a)codeweavers.com>

[Alexandre Julliard]

Francois Gouget <fgouget(a)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
julliard(a)winehq.org