Tracy client slow startup due to Symbol resolution pre-caching

[KiviTK]

The Trarcy profilee starts up very slowly in my case, around 2-3 minutes, however after this the applications continues to run normally.
A quick glance with a profiler (VerySleepy in this case) shows that almost all this time is taken up by the FindFirstFileW WinAPI function.

I have attached the typical call stack for this function in the application.

Removing Tracy from the build fixes the issue and the application starts up instantly as expected. If breakpoints are added, it is clear that this hang is caused at static initialization time since the breakpoint in main will not get hit until the application starts normally.

[wolfpld]

Pausing the application in a debugger would seem to be a more sensible approach for finding out what is happening.

[KiviTK]

Yes, however like I said this occurs during static initialization time, before the main function starts executing, and I do not know the code for Tracy well enough to know where to debug it, a breakpoint in main would only be hit after the initial few minutes of startup.
If you can tell me where I should start to debug Tracy I'll see if I can find what is slowing down.

[wolfpld]

You can just pause the execution in MSVC and look where the threads are stopped.

[sacereda]

Same here.
Our application is defining TRACY_DBGHELP_LOCK and is locked due to TracyCallstack.cpp is holding the lock.
I tried unlocking earlier , and then protecting again the SymLoadModuleEx call, but it was still slow.

Commenting the SymLoadModuleEx and unlocking early seems to do the trick.

diff -r b979ac45de4f tracy/public/client/TracyCallstack.cpp
--- a/tracy/public/client/TracyCallstack.cpp	Wed Nov 23 10:52:45 2022 +0100
+++ b/tracy/public/client/TracyCallstack.cpp	Wed Nov 23 12:03:10 2022 +0100
@@ -157,6 +157,10 @@
     SymInitialize( GetCurrentProcess(), nullptr, true );
     SymSetOptions( SYMOPT_LOAD_LINES );
 
+#ifdef TRACY_DBGHELP_LOCK
+    DBGHELP_UNLOCK;
+#endif
+
     DWORD needed;
     LPVOID dev[4096];
     if( EnumDeviceDrivers( dev, sizeof(dev), &needed ) != 0 )
@@ -193,7 +197,9 @@
                         path = full;
                     }
 
-                    SymLoadModuleEx( GetCurrentProcess(), nullptr, path, nullptr, (DWORD64)dev[i], 0, nullptr, 0 );
+                    // DBGHELP_LOCK
+                    // SymLoadModuleEx( GetCurrentProcess(), nullptr, path, nullptr, (DWORD64)dev[i], 0, nullptr, 0 );
+                    // DBGHELP_UNLOCK
 
                     const auto psz = strlen( path );
                     auto pptr = (char*)tracy_malloc_fast( psz+1 );
@@ -245,7 +251,7 @@
     }
 
 #ifdef TRACY_DBGHELP_LOCK
-    DBGHELP_UNLOCK;
+    // DBGHELP_UNLOCK;
 #endif
 }
 

[Lectem]

Tracy is pre-caching the list of modules (.dlls) and notifying DbgHelp about those as soon as you connect to it. This also includes drivers, which may indeed take a while on some machines. When using TRACY_DBGHELP_LOCK it can the lead to contention

In the above case, it seems to be linked to DbgHelp looking for the .exe/.pdb. This can be mitigated by using SYMOPT_DEFERRED_LOADS as done in #1009

tracy/public/common/TracyCallstack.cpp

Line 754 in 073df4e

| SYMOPT_DEFERRED_LOADS

.

TRACY_DELAYED_INIT could also be used to defer the initialization of worker threads, and should be enough in your case unless the application very often holds the TRACY_DBGHELP_LOCK ?

[Lectem]

Note that I just had the same issue, and realized that it can be exacerbated by using symsrv.dll (or any symbol server).
Due to the kernel and drivers pre-caching this can take a long time. Mitigation until #1009 gets merged is to skip loading of kernel modules using TRACY_NO_DBGHELP_INIT_LOAD (introduced in #657 ) or use SYMOPT_DEFERRED_LOADS