TVMFFIBacktrace crashes under concurrency on Windows: DbgHelp used without serialization, per-call SymInitialize/SymCleanup, unchecked SymInitialize

[pisarev]

Component: tvm-ffi — src/ffi/backtrace_win.cc
Affected version: apache-tvm-ffi 0.1.13.post3 (confirmed in the published
sdist and wheel), also present in older trees
Platform: Windows x64, MSVC
Severity: a C++ exception raised while another thread is also reporting one
kills the process, and the original error message is never printed

Summary

The crash originates in unsynchronized access to shared DbgHelp symbol-handler
state. Repeated SymInitialize/SymCleanup around every backtrace and eager
symbol loading increase the amount of DbgHelp work performed on that path. In
addition, the return value of SymInitialize is ignored, so an initialization
failure can leave subsequent symbol-handler calls operating without a
successfully established session.

The practical effect is worse than a crash in the error path. The original
exception is never printed, because the process dies while the library is
formatting the diagnostic for it. Every failure inside a multi-threaded TVM pass
therefore looks like a silent process death with no message at all.

That is how it turned up here. MetaSchedule tuning on Windows died at task
initialization with exit code 127, no Python traceback and no log line. It took
a native stack under cdb to see that the visible crash was in the reporter,
not in the code being reported on:

tvm_compiler!tvm::s_tir::SampleComputeLocation+0x5a
tvm_compiler!tvm::s_tir::ComputeInline+0x35b
tvm_ffi!TVMFFIBacktrace+0x257
dbghelp!SymInitialize -> dbghelp!LoadModule   <- access violation

The C++ exception was raised on thread 5bec; the access violation happened on
thread 6c34.

What is wrong

src/ffi/backtrace_win.cc, lines 53–58 and 141:

HANDLE process = GetCurrentProcess();
HANDLE thread = GetCurrentThread();

SymSetOptions(SYMOPT_LOAD_LINES | SYMOPT_UNDNAME);
SymInitialize(process, NULL, TRUE);     // line 58
...
SymCleanup(process);                    // line 141

One correctness bug:

1. No serialization. The DbgHelp documentation states that its functions are
   single-threaded and that calling them from more than one thread leads to
   unexpected behaviour or memory corruption; the caller is required to
   serialize them. There is no lock here. This applies to the whole body —
   StackWalk64, SymFromAddr, SymFunctionTableAccess64 and
   SymGetModuleBase64 all read the same process-wide session, as do the
   SymInitialize / SymCleanup pair discussed below.

One unchecked result:

2. SymInitialize's return value is ignored. If it fails, every later call
   in the process can go on working against a session that was never
   established, and nothing says so. This is an error-handling defect found by
   reading; it is not claimed to be what happened in the crashes measured here.

Two things that make (1) worse without being separate bugs of their own:

3. SymInitialize / SymCleanup per call. Both are per-process, not
   per-call, so one thread can tear the symbol tables down while another walks
   them. That is a striking way for (1) to fail, but it is still (1) failing:
   under a lock that covers the whole body, this lifecycle is merely expensive.
   It is deliberately not listed as a second independent correctness bug —
   see the ablation below.

4. fInvadeProcess = TRUE on every call. Enumerating every module and
   loading symbols for all of them is legitimate on its own. Doing it per call,
   in a process where tvm_compiler.dll alone is 168 MB, makes each call slow
   and allocation-heavy, which increases the amount of DbgHelp work done on the
   faulting path.

Linux is unaffected: backtrace.cc uses libbacktrace, which is designed for
concurrent use and has no global init/cleanup pair.

Minimal reproducer

No TVM, no Python — it loads tvm_ffi.dll and calls the one export from
several threads. It reports the work done, not only that it survived, so a
"fix" that produced empty backtraces could not pass it silently.

#include <windows.h>
#include <cstdio>
#include <cstdlib>
#include <thread>
#include <vector>
#include <atomic>

struct TVMFFIByteArray { const char* data; size_t size; };
typedef const TVMFFIByteArray* (*Backtrace)(const char*, int, const char*, int);

static Backtrace g_backtrace = nullptr;
static std::atomic<long long> g_calls{0};
static std::atomic<long long> g_bytes{0};

static void worker(int calls) {
  for (int i = 0; i < calls; ++i) {
    const TVMFFIByteArray* a = g_backtrace(__FILE__, __LINE__, "worker", 0);
    if (a != nullptr) g_bytes += (long long)a->size;
    g_calls += 1;
  }
}

int main(int argc, char** argv) {
  if (argc < 2) { std::fprintf(stderr, "usage: repro <tvm_ffi.dll> [threads] [calls]\n"); return 2; }
  int threads = argc > 2 ? std::atoi(argv[2]) : 8;
  int calls   = argc > 3 ? std::atoi(argv[3]) : 200;

  HMODULE h = LoadLibraryA(argv[1]);
  if (h == nullptr) { std::fprintf(stderr, "LoadLibrary failed: %lu\n", GetLastError()); return 2; }
  g_backtrace = (Backtrace)GetProcAddress(h, "TVMFFIBacktrace");
  if (g_backtrace == nullptr) { std::fprintf(stderr, "no TVMFFIBacktrace export\n"); return 2; }

  std::vector<std::thread> pool;
  for (int i = 0; i < threads; ++i) pool.emplace_back(worker, calls);
  for (auto& t : pool) t.join();

  std::printf("SURVIVED: %lld calls, %lld bytes of backtrace\n",
              g_calls.load(), g_bytes.load());
  return 0;
}

cl /nologo /EHsc /O2 /std:c++17 repro.cpp /Fe:repro.exe
repro.exe path\to\tvm_ffi.dll 8 200

It reproduces in about 300 ms.

Measurements

Windows 11 x64, i5-12500 (12 logical cores), MSVC 14.51,
apache-tvm-ffi 0.1.13.post3 rebuilt from the published sdist with no change
other than the patch below. Each run is an independent process.

build	load	runs	crashed
as published	8 threads x 200 calls	100	100
as published	8 threads x 200 calls	20	19
as published	16 threads x 2000 calls	3	3
patched	8 threads x 200 calls	300	0
patched	8 threads x 200 calls	20	0
patched	16 threads x 2000 calls	5	0
patched (final)	8 threads x 200 calls	40	0

Totals: 122 of 123 as published, 0 of 365 patched. Exit codes on the
unpatched build were 127, 139, 0xC0000005, 0xC0000374 and 0xC0000409.

The patched runs report their work: 32000 calls and 1248000 bytes of backtrace
per 16x2000 run, identical across runs.

Memory. Private bytes after 1, 100 and 1000 calls are identical
(27 328 512); after 10 000 calls, 27 332 608 — a single page. Not calling
SymCleanup does not leak per backtrace.

Backtrace content. Checked on a purpose-built chain of ten noinline
functions compiled with symbols, so that there are real named frames to resolve
— a short trace would have proved nothing. Both builds return byte-identical
text, 692 bytes, twelve frames, every one of them named with its file and line:

  File "chain.cpp", line 29, in probe_10
  File "chain.cpp", line 32, in probe_9
  ...
  File "chain.cpp", line 40, in probe_1
  File "chain.cpp", line 49, in main
  File "exe_common.inl", line 288, in __scrt_common_main_seh

SYMOPT_DEFERRED_LOADS does not degrade symbolization: same frame count, same
names, same order, no bare addresses.

The degraded path was exercised, not merely written. The patch reports why
symbols are unavailable rather than silently returning a short trace, and that
branch is reachable on purpose: DbgHelp keeps one session per process handle, so
a test program that calls SymInitialize first makes the library's own call
fail. Same program, two builds:

patched    File "failinit.cpp", line 32, in main
           File "<dbghelp>", line 0, in symbols unavailable:
                SymInitialize failed, GetLastError=87
unpatched  File "failinit.cpp", line 32, in main

87 is ERROR_INVALID_PARAMETER - the session already exists. The unpatched build
returns the short trace with nothing to explain it.

At the level of the original symptom. MetaSchedule tuning of a small
convolutional model died at 80 s in every attempt before the patch. After it,
the same run passes that point and keeps going, and the log now contains
Build errors: N sample(s) — those are the C++ exceptions that previously
killed the process while their diagnostic was being formatted. They are now
reported and the run continues.

Which part of the fix is actually required

The patch below changes three things at once — serialization, the lifetime of
SymInitialize/SymCleanup, and deferred symbol loading. Measuring only the
whole patch would show that this set of changes cures the crash, not that each
part is causally necessary. Three builds were made from the unmodified file,
each adding one thing, and measured with the same reproducer:

A  lock only        mutex around the body; init/cleanup left per call
B  lifetime only    call_once init, no SymCleanup; NO mutex
C  lock + lifetime  both, without SYMOPT_DEFERRED_LOADS

Each was run in independent processes, judged by the real exit code, and every
survivor had to report the full call count:

variant   load          runs  crashed  hollow
A         8 x 50          10      0       0
B         8 x 50          10      0       0
C         8 x 50          10      0       0
B         16 x 2000       10      0       0
C         16 x 2000       10      0       0
unpatched 16 x 2000        5      5       0     <- control, in one second

The first three rows were produced by an independent reviewer on this machine,
running the same script without being shown the expected outcome; the last three
are mine. The control row is what makes the rest readable: at 16 x 2000 the
unpatched build dies five times out of five in about a second, so a zero at that
load is not the probe being weak.

What this shows. Serializing everything (A) is sufficient: it completed the
full workload in every process. That is the minimal change worth proposing.

What it does not show. B - dropping the per-call SymInitialize/SymCleanup
without any lock - also produced no failure, in 320000 completed calls at the
load that kills the unpatched build instantly. That is strong evidence that the
per-call lifecycle was the dominant observed mechanism. It is not evidence
that B is correct: the concurrent StackWalk64, SymFromAddr and
SymGetLineFromAddr64 calls still violate the documented requirement. B removes
the most frequent collision and leaves the rest rare.

Crash counting cannot separate "the race is gone" from "the race became rare",
and no such claim is made here: any finite failure-free series is consistent
with both. Said plainly rather than papered over.

So, if it is worth saying outright: the lifetime change alone should not be
taken as the fix. It will make this reproducer stop failing.

One measurement about cost is already in, and it matters for what to recommend.
Variant A takes over two minutes for one 8-thread x 200-call run, against
about 0.3 seconds for the full patch: roughly three orders of magnitude, because
the per-call module walk is now serialized as well. The backtrace path does not
run in silence — during MetaSchedule tuning the log fills with
Build errors: N sample(s) — so a fix that removes the crash but keeps the
per-call invade turns a working build into one that looks hung. The lifetime
change is therefore proposed as a practical requirement, not a decoration, even
if the lock alone proves sufficient for correctness.

Patch

 #include <iostream>
+#include <mutex>
+#include <stdexcept>
 #include <vector>
@@
   HANDLE process = GetCurrentProcess();
   HANDLE thread = GetCurrentThread();
 
-  SymSetOptions(SYMOPT_LOAD_LINES | SYMOPT_UNDNAME);
-  SymInitialize(process, NULL, TRUE);
+  // Re-entry on the same thread would deadlock on the non-recursive mutex
+  // below, so it is answered before the lock is taken. It can happen if
+  // anything reached from inside this function raises in turn - which is
+  // exactly the situation this function exists to report on.
+  static thread_local bool collecting = false;
+  if (collecting) {
+    backtrace_str = backtrace.GetBacktrace();
+    backtrace_array.data = backtrace_str.data();
+    backtrace_array.size = backtrace_str.size();
+    return &backtrace_array;
+  }
+  struct ReentryGuard {
+    bool* flag;
+    explicit ReentryGuard(bool* f) : flag(f) { *flag = true; }
+    ~ReentryGuard() { *flag = false; }
+  } reentry_guard(&collecting);
+
+  // DbgHelp is single threaded: every call for a given process must be
+  // serialized by the caller. The lock covers the whole body on purpose -
+  // StackWalk64, SymFromAddr and SymGetLineFromAddr64 read the same session.
+  static std::mutex dbghelp_mutex;
+  std::lock_guard<std::mutex> dbghelp_lock(dbghelp_mutex);
+
+  // SymInitialize and SymCleanup are per-process, not per-call. Initialize
+  // once and never clean up: the tables live as long as the process.
+  // SYMOPT_DEFERRED_LOADS keeps that one-time invade cheap - symbol data for a
+  // module is read only when a frame lands in it.
+  //
+  // The result is checked, and the lambda throws on failure so that
+  // std::call_once does NOT record the flag as satisfied: a normal return
+  // would make one early failure permanent for the life of the process.
+  static std::once_flag sym_init_once;
+  static bool sym_ready = false;
+  static DWORD sym_error = 0;
+  try {
+    std::call_once(sym_init_once, [process]() {
+      SymSetOptions(SYMOPT_DEFERRED_LOADS | SYMOPT_LOAD_LINES | SYMOPT_UNDNAME);
+      if (!SymInitialize(process, NULL, TRUE)) {
+        sym_error = GetLastError();
+        throw std::runtime_error("SymInitialize failed");
+      }
+      sym_ready = true;
+    });
+  } catch (const std::exception&) {
+    // Deliberately swallowed: this function is the error reporter, and an
+    // exception escaping it would replace the message being reported.
+  }
+  if (!sym_ready) {
+    backtrace_str = backtrace.GetBacktrace();
+    backtrace_array.data = backtrace_str.data();
+    backtrace_array.size = backtrace_str.size();
+    return &backtrace_array;
+  }
   CONTEXT context = {};
@@
-  SymCleanup(process);
+  // No SymCleanup: the symbol tables are process-wide and are deliberately
+  // kept for the life of the process.
   backtrace_str = backtrace.GetBacktrace();

The ABI is unchanged: 119 exported names before and after, no differences. The
SymCleanup import disappears from the import table, which is a convenient way
to tell a patched binary from an unpatched one.

Remaining limits, stated rather than hidden

• The mutex serializes calls inside tvm_ffi only. Another DLL in the same
  process that uses DbgHelp does not know about it — particularly if it also
  uses GetCurrentProcess() as the session identifier and calls SymCleanup.
  That is not what the reproducer hits, but it is where the guarantee ends.
• Never calling SymCleanup is right for a process-wide singleton, but it
  makes one assumption explicit that was previously implicit: tvm_ffi.dll is
  not unloaded and reloaded inside a live process. After such a reload the
  DLL-local once_flag would be fresh while the DbgHelp session left behind is
  the old one. This is stated as a lifetime assumption rather than checked.

I am happy to open a pull request with this change if that is useful.

[pisarev]

Whether the race is removed, or merely made rare

The body of this issue says crash counting cannot answer that, and it cannot:
any finite failure-free series is consistent with both. The question was
settled instead by measuring the invariant that is violated rather than the
symptom that follows from it.

Two extra builds were made from the unmodified file — one with the per-call
SymInitialize/SymCleanup removed and no lock, one with both the lock and the
lifetime change — each carrying a counter that records how many threads are
inside the instrumented StackWalk64 call region at the same moment. Two
details of that counter matter:

• it brackets the real StackWalk64 call, so an active interval means a thread
  is inside that API rather than merely on its way to it;
• the rendezvous that encourages overlap sits inside a callback.
  StackWalk64 invokes SymFunctionTableAccess64 from within itself, so a
  thread waiting there is provably inside a StackWalk64 that has not returned.
  A barrier placed before the API would not show this — the two threads could
  still be scheduled one after the other once the barrier lifted.

The rendezvous is one-shot, with a timeout. The counter is not: it runs on every
call for the life of the process, so a maximum of 1 means no overlap was seen
anywhere in the series, not merely after the first pair. Making the rendezvous
fire on every call would be actively wrong for the serialized build — the first
thread would pay the full timeout on every frame, because the second
legitimately cannot arrive, and the program under test would no longer be the
program of interest.

16 threads, 500 calls each, 3 independent runs of each build:

build                     crashed   max concurrent call regions
lifetime only, no lock     0 of 3    16   16   16
lock + lifetime            0 of 3     1    1    1

With per-call SymInitialize/SymCleanup removed but no lock, all 16 worker
threads simultaneously occupied the instrumented StackWalk64 call region in
each of three runs, while every run still reported success. The callback
rendezvous confirms that actual StackWalk64 calls overlapped. With the lock,
the observed maximum was one.

Those are two separate results and are deliberately not merged into a stronger
one: sixteen threads concurrently in the measured call region, and at least two
concurrently inside the real API.

Both crash columns are zero, which is the point. The lifetime change alone does
not serialize anything. It removes the collision that made the race visible —
the teardown of the symbol tables under a thread that is walking them — and
leaves everything else concurrent exactly as it was. It should not be taken as
the fix, even though it will make the reproducer in this issue stop failing.

Separately, and as a distinct piece of evidence rather than the same one: one
further run of the lock-free build, outside the series above, died with
0xC0000374 (heap corruption).

The instrumentation is test-only and is not part of the proposed patch.

[tqchen]

thanks @pisarev i think we just need to lock guard the function no need for extra changes u had

[pisarev]

Thanks. I agree that one mutex must cover every DbgHelp call made by TVMFFIBacktrace. That fixes the reported race between concurrent TVMFFIBacktrace calls.

I think the patch still needs a private session handle and initialization that is retained after it succeeds. DbgHelp locates a caller's symbol state through the hProcess value passed to SymInitialize. Microsoft's SymInitialize documentation says this value must be unique to avoid sharing a session with another component. It also says not to use the value returned by GetCurrentProcess().

I tested the reduced design in an actual tvm_ffi.dll build. In a single-threaded test, the lock-only build destroyed a DbgHelp session that the host had initialized first. The host's next symbol lookup failed with ERROR_INVALID_HANDLE (6). The reduced build kept both sessions usable in either initialization order. In a separate 12-frame test, the current, lock-only, and reduced builds produced the same 692-byte backtrace, byte for byte. Every frame contained its function name, file, and line.

The reduced patch contains:

• one mutex around all DbgHelp calls made by tvm_ffi;
• one duplicated process handle, private to tvm_ffi, passed to those calls;
• lazy initialization retained after success, with no SymCleanup after each backtrace.

This version omits the re-entry guard, the throwing call_once helper, and SYMOPT_DEFERRED_LOADS.

Keeping the session also avoids repeated module enumeration under the mutex. In our six runs with 8 threads and 200 calls per thread, lock-only took 81-97 seconds. The reduced build took less than 0.4 seconds in each of eight runs of the same workload.

The mutex serializes only DbgHelp calls made inside tvm_ffi. It cannot serialize calls from an unrelated DLL.

Would this reduced version be acceptable for a pull request?