pisarev opened a new issue, #727:
URL: https://github.com/apache/tvm-ffi/issues/727
**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:
```cpp
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.
```cpp
#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
```diff
#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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
