Offline symbol resolving improvements (parallel image resolving, new fast libdw based resolving backend)

update/CMakeLists.txt

@@ -21,9 +21,12 @@ set(PROGRAM_FILES
     src/OfflineSymbolResolver.cpp
     src/OfflineSymbolResolverAddr2Line.cpp
     src/OfflineSymbolResolverDbgHelper.cpp
+    src/OfflineSymbolResolverLibdw.cpp
+    src/OfflineSymbolResolverLibBacktrace.cpp
     src/update.cpp
 )
 
 add_executable(${PROJECT_NAME} ${PROGRAM_FILES} ${COMMON_FILES} ${SERVER_FILES})
-target_link_libraries(${PROJECT_NAME} PRIVATE TracyServer TracyGetOpt)
+# sudo apt-get install libdw
+target_link_libraries(${PROJECT_NAME} PRIVATE TracyServer TracyGetOpt backtrace dl dw elf)
 set_property(DIRECTORY ${CMAKE_CURRENT_LIST_DIR} PROPERTY VS_STARTUP_PROJECT ${PROJECT_NAME})

update/src/OfflineSymbolResolver.cpp

@@ -1,5 +1,8 @@
 #include <fstream>
 #include <iostream>
+#include <vector>
+#include <future>
+#include <thread>
 #include <stdint.h>
 #include <stdio.h>
 #include <stdlib.h>
@@ -11,6 +14,22 @@
 
 #include "OfflineSymbolResolver.h"
 
+// main entrypoint to resolving symbols
+bool ResolveSymbols( const std::string& imagePath, const FrameEntryList& inputEntryList,
+                     SymbolEntryList& resolvedEntries, const ResolveOptions& options)
+{
+#ifdef _WIN32
+    return ResolveSymbolsWithWinDBG(imagePath, inputEntryList, resolvedEntries);
+#else
+    if( options.resolver == "addr2line" )
+        return ResolveSymbolsWithAddr2Line(imagePath, inputEntryList, resolvedEntries);
+    else if( options.resolver == "libacktrace" )
+        return ResolveSymbolsWithLibBacktrace(imagePath, inputEntryList, resolvedEntries);
+    else
+        return ResolveSymbolsWithLibDW(imagePath, inputEntryList, resolvedEntries);
+#endif //#ifndef _WIN32
+}
+
 bool ApplyPathSubstitutions( std::string& path, const PathSubstitutionList& pathSubstitutionlist )
 {
     for( const auto& substitution : pathSubstitutionlist )
@@ -24,19 +43,107 @@ bool ApplyPathSubstitutions( std::string& path, const PathSubstitutionList& path
     return false;
 }
 
+bool ShouldSkipImage( const std::string& imagePath, const SkipImageList* skipImageList ) 
+{
+    if(!skipImageList)
+        return false;
+
+    for( const auto& skipMatch : *skipImageList )
+    {
+        if( std::regex_match( imagePath, skipMatch ) )
+        {
+            return true;
+        }
+    }
+    return false;
+}
+
 tracy::StringIdx AddSymbolString( tracy::Worker& worker, const std::string& str )
 {
     // TODO: use string hash map to reduce potential string duplication?
     tracy::StringLocation location = worker.StoreString( str.c_str(), str.length() );
     return tracy::StringIdx( location.idx );
 }
 
-bool PatchSymbolsWithRegex( tracy::Worker& worker, const PathSubstitutionList& pathSubstitutionlist, bool verbose )
+using JobCallback = std::function<void(size_t jobIndex)>;
+void processJobsInParallel( size_t maxJobs, size_t maxConcurrent, JobCallback&& onJobStart, JobCallback&& func,
+                            JobCallback&& onJobEnd )
+{
+    if (maxConcurrent <=1)
+    {
+        for(size_t index = 0; index < maxJobs; ++index)
+        {
+            onJobStart(index);
+            func(index);
+            onJobEnd(index);
+        }
+    }
+
+    struct JobEntry
+    {
+        size_t jobIndex;
+        std::future<void> future;
+    };
+
+    std::vector<JobEntry> results;
+    size_t index = 0;
+
+    while( index < maxJobs || !results.empty() )
+    {
+        // Launch new jobs if there is room
+        while( index < maxJobs && results.size() < maxConcurrent )
+        {
+            onJobStart( index );
+            auto future = std::async( std::launch::async, std::bind( func, index ) ); 
+            results.push_back( { index, std::move(future) } );
+            index++;
+        }
+
+        // Remove completed jobs
+        results.erase( std::remove_if( results.begin(), results.end(),
+            [onJobEnd]( JobEntry& entry )
+            { 
+                const bool finished = entry.future.wait_for( std::chrono::milliseconds( 100 ) ) == std::future_status::ready; 
+                if (finished)
+                {
+                    onJobEnd( entry.jobIndex );
+                }
+                return finished;
+            }),
+            results.end() );
+    }
+}
+
+class Stopwatch
 {
+public:
+    explicit Stopwatch()
+    : start_(std::chrono::high_resolution_clock::now())
+    {}
+    void start()
+    {
+        start_ = std::chrono::high_resolution_clock::now();
+    }
+    size_t getTimeFromStartInMs() const
+    {
+        auto end = std::chrono::high_resolution_clock::now();
+        auto durationMs = std::chrono::duration_cast<std::chrono::milliseconds>(end - start_).count();
+        return durationMs;
+    }
+private:
+    std::chrono::high_resolution_clock::time_point start_;
+};
+
+bool PatchSymbolsWithRegex( tracy::Worker& worker, const PathSubstitutionList& pathSubstitutionlist,
+                            const SkipImageList* skipImageList, const ResolveOptions& options)
+{
+    Stopwatch overallStopwatch;
+
     uint64_t callstackFrameCount = worker.GetCallstackFrameCount();
     std::string relativeSoNameMatch = "[unresolved]";
 
-    std::cout << "Found " << callstackFrameCount << " callstack frames. Batching into image groups..." << std::endl;
+    std::cout << "* Found " << callstackFrameCount << " callstack frames. Batching into image groups..." << std::endl;
+    Stopwatch batchIntoGroupsStopwatch;
 
     // batch the symbol queries by .so so we issue the least amount of requests
     using FrameEntriesPerImageIdx = std::unordered_map<uint32_t, FrameEntryList>;
@@ -72,53 +179,134 @@ bool PatchSymbolsWithRegex( tracy::Worker& worker, const PathSubstitutionList& p
         }
     }
 
-    std::cout << "Batched into " << entriesPerImageIdx.size() << " unique image groups" << std::endl;
+    std::cout << "* Batched into " << entriesPerImageIdx.size()
+              << " unique image groups [took: " << batchIntoGroupsStopwatch.getTimeFromStartInMs() << " ms]" << std::endl;
 
-    // FIXME: the resolving of symbols here can be slow and could be done in parallel per "image"
-    // - be careful with string allocation though as that would be not safe to do in parallel
-    for( FrameEntriesPerImageIdx::iterator imageIt = entriesPerImageIdx.begin(),
-         imageItEnd = entriesPerImageIdx.end(); imageIt != imageItEnd; ++imageIt )
+    struct JobEntry
     {
-        tracy::StringIdx imageIdx( imageIt->first );
-        std::string imagePath = worker.GetString( imageIdx );
+        FrameEntriesPerImageIdx::iterator imageIt;
+        SymbolEntryList results;
+        std::string imagePath;
+        Stopwatch jobStopWatch;
+    };
+
+    using AllResoledEntries = std::vector<JobEntry>;
+    AllResoledEntries resolvedResults;
+    resolvedResults.resize( entriesPerImageIdx.size() );
 
+    size_t index = 0;
+    size_t totalEntries = 0;
+    size_t processedEntries = 0;
+    for( FrameEntriesPerImageIdx::iterator imageIt = entriesPerImageIdx.begin(), imageItEnd = entriesPerImageIdx.end();
+         imageIt != imageItEnd; ++imageIt, ++index )
+    {
+        resolvedResults[index].imageIt = imageIt;
         FrameEntryList& entries = imageIt->second;
+        tracy::StringIdx imageIdx( imageIt->first );
+        resolvedResults[index].imagePath = worker.GetString( imageIdx );
+        totalEntries += entries.size();
+    }
+
+    unsigned int maxConcurrent = 
+        (options.maxParallelism <= 0) ? std::thread::hardware_concurrency() : int(options.maxParallelism);
 
-        if( !entries.size() ) continue;
+    std::cout << "* Running " << resolvedResults.size() << " resolution jobs in parallel (batches of " << maxConcurrent << ")" << std::endl;    
+    Stopwatch parallelResolveStopwatch;
 
-        std::cout << "Resolving " << entries.size() << " symbols for image: '" 
-                  << imagePath << "'" << std::endl;
-        const bool substituted = ApplyPathSubstitutions( imagePath, pathSubstitutionlist );
-        if( substituted )
+    // run symbol resolution for each image in parallel
+    processJobsInParallel( resolvedResults.size(), maxConcurrent,
+
+        [&resolvedResults, &worker]( size_t jobIndex )
         {
-            std::cout << "\tPath substituted to: '" << imagePath << "'" << std::endl;
-        }
+            FrameEntriesPerImageIdx::iterator imageIt = resolvedResults[jobIndex].imageIt;
+            FrameEntryList& entries = imageIt->second;
+            const std::string& imagePath = resolvedResults[jobIndex].imagePath;
 
-        SymbolEntryList resolvedEntries;
-        ResolveSymbols( imagePath, entries, resolvedEntries );
+            std::cout << "[job " << jobIndex << "/" << resolvedResults.size() << "] Starting resolving "
+                      << entries.size() << " symbols for image: '" << imagePath << "' ..." << std::endl;
+        },
 
-        if( resolvedEntries.size() != entries.size() )
+        [&resolvedResults, &worker, &pathSubstitutionlist, skipImageList, &options]( size_t jobIndex )
         {
-            std::cerr << " failed to resolve all entries! (got: " 
-                      << resolvedEntries.size() << ")" << std::endl;
-            continue;
-        }
+            std::string imagePath = resolvedResults[jobIndex].imagePath;
 
-        // finally patch the string with the resolved symbol data
-        for ( size_t i = 0; i < resolvedEntries.size(); ++i )
+            if( ShouldSkipImage( imagePath, skipImageList ) )
+            {
+                std::cerr << " * Skipping image ' " << imagePath << "' as requested..." << std::endl;
+                return;
+            }
+
+            FrameEntriesPerImageIdx::iterator imageIt = resolvedResults[jobIndex].imageIt;
+            FrameEntryList& entries = imageIt->second;
+            if( entries.size() )
+            {
+                ApplyPathSubstitutions( imagePath, pathSubstitutionlist );
+
+                SymbolEntryList& resolvedEntries = resolvedResults[jobIndex].results;
+                ResolveSymbols( imagePath, entries, resolvedEntries, options);
+
+                if( resolvedEntries.size() != entries.size() )
+                {
+                    std::cerr << " failed to resolve all entries! (got: " << resolvedEntries.size()
+                              << ", expected: " << entries.size() << ") discarding results ..." << std::endl;
+                    resolvedEntries.clear();
+                }
+            }
+        },
+        [&resolvedResults, &worker, totalEntries, &processedEntries, &parallelResolveStopwatch]( size_t jobIndex )
+        {
+            FrameEntriesPerImageIdx::iterator imageIt = resolvedResults[jobIndex].imageIt;
+            const size_t totalJobs = resolvedResults.size();
+            const size_t entriesForJob = imageIt->second.size();
+            processedEntries += entriesForJob;
+            int finishedPercent = int( ( float( processedEntries ) * 100.0f ) / float( totalEntries ) );
+
+            const std::string& imagePath = resolvedResults[jobIndex].imagePath;
+            std::cout << "[job " << jobIndex << "/" << totalJobs << "] [progress: " << finishedPercent 
+                      << "%, duration: " << parallelResolveStopwatch.getTimeFromStartInMs() / 1000 << " s] finished "
+                      << entriesForJob << " entries for: '" << imagePath << "' in: "
+                      << ( resolvedResults[jobIndex].jobStopWatch.getTimeFromStartInMs() / 1000 ) << " s" << std::endl;
+        }        
+    );
+
+    std::cout << "* Parallel resolve took " << parallelResolveStopwatch.getTimeFromStartInMs() / 1000 << " s" << std::endl;
+    std::cout << "* Patching resolved entries ..." << std::endl;
+    Stopwatch patchingEntriesStopwatch;
+
+    uint32_t totalEntriesAttemped = 0;
+    uint32_t totalFailedResolved = 0;
+
+    // after resolution, patch all the strings with the results. This has to be done serially unfortunately as the string manipulation 
+    // in the worker is not multi thread safe!
+    for( AllResoledEntries::iterator resolvedEntryit = resolvedResults.begin(), itEnd = resolvedResults.end();
+         resolvedEntryit != itEnd; ++resolvedEntryit )
+    {
+        FrameEntriesPerImageIdx::iterator imgIt = resolvedEntryit->imageIt;
+        FrameEntryList& entries = imgIt->second;
+        SymbolEntryList& resolvedEntries = resolvedEntryit->results;
+        tracy::StringIdx imageIdx( imgIt->first );
+        std::string imagePath = worker.GetString( imageIdx );
+
+        for( size_t i = 0; i < resolvedEntries.size(); ++i )
         {
             FrameEntry& frameEntry = entries[i];
             const SymbolEntry& symbolEntry = resolvedEntries[i];
 
             tracy::CallstackFrame& frame = *frameEntry.frame;
 
-            if( !symbolEntry.name.length() ) continue;
+            if (!symbolEntry.resolved)
+                ++totalFailedResolved;
+            else
+                ++totalEntriesAttemped;
+
+            if( !symbolEntry.name.length() ) 
+                continue;
 
-            if( verbose )
+            if( options.verbose )
             {
                 const char* nameStr = worker.GetString( frame.name );
-                std::cout << "patching '" << nameStr << "' of '" << imagePath 
-                          << "' -> '" << symbolEntry.name << "'" << std::endl;
+                std::cout << "patching '" << nameStr << "' of '" << imagePath << "' -> '" << symbolEntry.name << "'"
+                        << std::endl;
             }
 
             frame.name = AddSymbolString( worker, symbolEntry.name );
@@ -132,10 +320,18 @@ bool PatchSymbolsWithRegex( tracy::Worker& worker, const PathSubstitutionList& p
         }
     }
 
+    std::cout << "* Patching entries took " << patchingEntriesStopwatch.getTimeFromStartInMs() << " ms" << std::endl;
+    size_t timeInseconds = overallStopwatch.getTimeFromStartInMs() / 1000;
+    std::cout << "The whole process took  " << timeInseconds << " s" << std::endl;
+    std::cout << "* Attempted resolve of " << totalEntriesAttemped 
+              << " entries, failed to resolve " << totalFailedResolved 
+              << "(" << (totalFailedResolved*100 / totalEntriesAttemped) << "%)" << std::endl;
+
     return true;
 }
 
-void PatchSymbols( tracy::Worker& worker, const std::vector<std::string>& pathSubstitutionsStrings, bool verbose )
+void PatchSymbols( tracy::Worker& worker, const std::vector<std::string>& pathSubstitutionsStrings,
+                   const std::vector<std::string>& skipImageListStr, const ResolveOptions& options)
 {
     std::cout << "Resolving and patching symbols..." << std::endl;
 
@@ -164,7 +360,15 @@ void PatchSymbols( tracy::Worker& worker, const std::vector<std::string>& pathSu
         }
     }
 
-    if ( !PatchSymbolsWithRegex(worker, pathSubstitutionList, verbose) )
+    SkipImageList skipImageList;
+    for( const std::string& imageName : skipImageListStr )
+    {
+        std::cout << "Adding regex image skip: '" << imageName << "'" << std::endl;
+        skipImageList.push_back( std::regex( imageName ) );
+    }
+
+    if( !PatchSymbolsWithRegex( worker, pathSubstitutionList,
+                               (skipImageList.empty() ? nullptr : &skipImageList), options))
     {
         std::cerr << "Failed to patch symbols" << std::endl;
     }