wolfpld / tracy

Frame profiler
https://tracy.nereid.pl/
Other
10.16k stars 679 forks source link

Tracy Client Crashes When Timing Parallel std::async Calls #850

Open eyesoftime opened 3 months ago

eyesoftime commented 3 months ago

I'm using Tracy with a C++ program on MSYS2/UCRT gcc compiler on Win10 and I'm running consistently into a crash when I want to time the async calls that run in separate threads. I know the platform is not probably ideal but it is what I'm using right now. I've tried to distill it down to the reproducible case and I think I've managed to do that for my own machine. It links Tracy statically and to run Tracy I've also had to link my program with dbghelp and ws2_32. I've read the section on dbghelp and I've also tried to provide locking mechanism and use dlls but (after a lot of fiddling around) that does not eliminate the crash for me. Toggling delayed init and manual lifetime management doesn't change the situation either. It seems to be a segmentation fault. Sometimes it manages to pick up connection with Tracy server. When using dynamic libraries it tends to crash even before the connection is established or just after.

# meson.build

project(
    'TracyAsyncLambdaStatic',
    'cpp',
    default_options : [
        'cpp_std=c++20',
        'buildtype=debugoptimized',
    ],
)

add_global_arguments(
    [
        # The following are needed for Tracy
        '-D_WIN32_WINNT=0x0601', 
        '-DWINVER=0x0601',

        '-DTRACY_ENABLE',
        '-DTRACY_NO_EXIT',

        #'-DTRACY_DBGHELP_LOCK=DbgHelp',
        '-DTRACY_DELAYED_INIT',
        '-DTRACY_MANUAL_LIFETIME',
        #'-DTRACY_NO_DBGHELP_INIT_LOAD',
        #'-DTRACY_VERBOSE',
    ],
    language : 'cpp',
)

tracy_proj = subproject(
    'tracy', 
    default_options : [ 
        'default_library=static',
    ],
)

logging_dep = dependency('spdlog')

tracy_dep = tracy_proj.get_variable('tracy_dep')
lib_tracy = tracy_proj.get_variable('tracy')

compiler = meson.get_compiler('cpp')

dbghelp_lib = compiler.find_library('dbghelp')
dbghelp_dep = declare_dependency(dependencies : [ dbghelp_lib ])

ws2_32_lib = compiler.find_library('ws2_32')
ws2_32_dep = declare_dependency(dependencies : [ ws2_32_lib ])

executable(
    meson.project_name(),
    [
        'main.cpp',
    ],
    dependencies : [
        dbghelp_dep,
        logging_dep,
        tracy_dep,
        ws2_32_dep,
    ],
)
// main.cpp

#include <cassert>
#include <future>
#include <thread>
#include <vector>

#include <spdlog/spdlog.h>
#include <tracy/Tracy.hpp>

#include <minwindef.h>
#include <winnt.h>
#include <synchapi.h>
#include <rpc.h>
#include <winbase.h>

extern "C" {
    static HANDLE dbgHelpLock;
    void DbgHelpInit () {
        spdlog::trace("DbgHelpInit()");
        dbgHelpLock = CreateMutex(nullptr, FALSE, 0);
        spdlog::trace("DbgHelpInit.");
    }
    void DbgHelpLock () {
        spdlog::trace("DbgHelpLock()");
        WaitForSingleObject(dbgHelpLock, INFINITE);
        spdlog::trace("DbgHelpLock.");
    }
    void DbgHelpUnlock () {
        spdlog::trace("DbgHelpUnlock()");
        ReleaseMutex(dbgHelpLock);
        spdlog::trace("DbgHelpUnlock.");
    }
}

int main(int argc, char* argv[]) {
    spdlog::set_pattern("%^[%Y.%m.%d %H:%M:%S.%f] [P:%5P-T:%5t] [%-8l] [%n] %v%$");

    spdlog::info("Setting global log level to TRACE");
    spdlog::set_level(spdlog::level::trace);

    DbgHelpInit();
    assert(dbgHelpLock && "dbgHelpLock is null");
    DbgHelpLock();
    DbgHelpUnlock();

    // Start Tracy
    spdlog::info("Tracy startup");
    tracy::StartupProfiler();

    spdlog::info("Entering timed zones");

    {
        ZoneScoped;

        spdlog::trace("Starting outer loop");

        for (int i { 0 }; i < 100; ++i) {
            ZoneScopedN("outer loop");

            spdlog::trace("Outer loop: {}", i);

            std::vector<std::future<void>> fs { };
            for (int j { 0 }; j < 10; ++j) {
                ZoneScopedN("start async");

                fs.push_back(
                    std::async(
                        std::launch::async,
                        [](int x) {
                            tracy::SetThreadName(std::to_string(x).c_str());
                            ZoneScopedN("async");
                            for (int k { 0 }; k < 1000; ++k) {
                                ZoneScopedN("async loop");
                                (void)k;
                            }
                        },
                        i * 10 + j
                    )
                );
            }

            {
                spdlog::trace("Future wait loop: {}", i);

                ZoneScopedN("future wait loop");

                std::for_each(fs.begin(), fs.end(), [](auto& item) {
                    ZoneScopedN("future wait");
                    item.get();
                });
            }
        }
    }

    // Stop Tracy
    tracy::ShutdownProfiler();

    //
    spdlog::trace("End");

    return 0;
}
# tracy.wrap

[wrap-file]
directory = tracy-0.11.0
source_url = https://github.com/wolfpld/tracy/archive/refs/tags/v0.11.0.tar.gz
source_filename = tracy-0.11.0.tar.gz
source_hash = b591ef2820c5575ccbf17e2e7a1dc1f6b9a2708f65bfd00f4ebefad2a1ccf830

[provide]
tracy = tracy_dep

It's worth noting that if Tracy zone markup is removed from within the async lambda the program runs to the end. It also works when the number of parallel async calls is reduced from 10 to 1. What I noticed is that it seems to run fine with up to 6 threads, starts occasionally crashing with 7, and almost definitely crashes with 8. The machine I'm using has 8 cores so perhaps there's something about that.

I can't track it deeper into Tracy as I don't have that much expertise with the language. So apart from submitting this issue I can only ask a couple of questions. Am I trying to use Tracy in an unsupported manner? Is it the platform that I'm using? Is it something I can fix on my side?

mcourteaux commented 1 month ago

Possibly related: #875 #879.

Can you check if the fix in #879 fixes your issue?

eyesoftime commented 1 month ago

I hope I managed to test it against the correct revision but so far the issue seems to persist. After a short run the program dies with the Segmentation Fault message. Sometimes not even that much. Testing with gcc-14.2.0. FWIW, compiling it with clang has been producing a working program.

mcourteaux commented 1 month ago

I hope I managed to test it against the correct revision but so far the issue seems to persist. After a short run the program dies with the Segmentation Fault message. Sometimes not even that much. Testing with gcc-14.2.0. FWIW, compiling it with clang has been producing a working program.

Thanks for testing! Your issue sounded similar to mine. By the way, making a full Debug build of the profiler proved very useful. Seeing a stack trace of the crash, or simply having asserts enabled was really useful.