Built-in CPU profiling causes a segmentation fault on macOS 11

[sticnarf]

Bug Report

What version of TiKV are you using?

Release Version:   5.0.0-rc.x
Edition:           Community
Git Commit Hash:   4807a3d610f2809bd6cc5b1e7645dbb01d5e9e52
Git Commit Branch: release-5.0
UTC Build Time:    2021-04-05 07:11:09
Rust Version:      rustc 1.51.0-nightly (bc39d4d9c 2021-01-15)
Enable Features:   jemalloc sse protobuf-codec test-engines-rocksdb cloud-aws cloud-gcp

What operating system and CPU are you using?

macOS 11.2.3. Intel 4258U.

It does not happen on macOS 10.14 or 10.15.

Steps to reproduce

Executing a write workload on TiKV (for example running TPC-C on TiDB). Then, use the built-in profiling tool to get a flame graph by GET http://{TiKV_IP}:20180/debug/pprof/profile?seconds=30

What did you expect?

A CPU flame graph is generated.

What did happened?

A segmentation fault occurs.

Examining the core dump, we find the CFI parser in libunwind.dylib tries to access 0x0:

(lldb) t 38
* thread #38, stop reason = signal SIGSTOP
    frame #0: 0x00007fff2a55e8b0 libunwind.dylib`libunwind::CFI_Parser<libunwind::LocalAddressSpace>::decodeFDE(libunwind::LocalAddressSpace&, unsigned long, libunwind::CFI_Parser<libunwind::LocalAddressSpace>::FDE_Info*, libunwind::CFI_Parser<libunwind::LocalAddressSpace>::CIE_Info*) + 30
libunwind.dylib`libunwind::CFI_Parser<libunwind::LocalAddressSpace>::decodeFDE:
->  0x7fff2a55e8b0 <+30>: movl   (%rsi), %r13d
    0x7fff2a55e8b3 <+33>: leaq   0x4(%rsi), %rbx
    0x7fff2a55e8b7 <+37>: movl   $0xffffffff, %eax         ; imm = 0xFFFFFFFF 
    0x7fff2a55e8bc <+42>: movq   %rbx, -0x30(%rbp)
(lldb) bt
* thread #38, stop reason = signal SIGSTOP
  * frame #0: 0x00007fff2a55e8b0 libunwind.dylib`libunwind::CFI_Parser<libunwind::LocalAddressSpace>::decodeFDE(libunwind::LocalAddressSpace&, unsigned long, libunwind::CFI_Parser<libunwind::LocalAddressSpace>::FDE_Info*, libunwind::CFI_Parser<libunwind::LocalAddressSpace>::CIE_Info*) + 30
    frame #1: 0x00007fff2a56093c libunwind.dylib`libunwind::UnwindCursor<libunwind::LocalAddressSpace, libunwind::Registers_x86_64>::step() + 124
    frame #2: 0x00007fff2a562eba libunwind.dylib`_Unwind_Backtrace + 188
    frame #3: 0x00000001035c13a9 tikv-server`backtrace::backtrace::trace_unsynchronized::hb3ff981861709778 [inlined] backtrace::backtrace::libunwind::trace::h80928dc4f295b02a at libunwind.rs:88:5
    frame #4: 0x00000001035c139a tikv-server`backtrace::backtrace::trace_unsynchronized::hb3ff981861709778 at mod.rs:66
    frame #5: 0x00000001035b88e3 tikv-server`perf_signal_handler at profiler.rs:128:17
    frame #6: 0x00007fff203d9d7d libsystem_platform.dylib`_sigtramp + 29
    frame #7: 0x00007fff2036266a libsystem_kernel.dylib`__commpage_gettimeofday + 1
    frame #8: 0x00007fff20278b6d libsystem_c.dylib`gettimeofday + 45
    frame #9: 0x0000000104a59a79 tikv-server`rocksdb::(anonymous namespace)::PosixEnv::NowMicros(this=0x0000000107042b48) at env_posix.cc:915:5
    frame #10: 0x00000001047d7700 tikv-server`rocksdb::EnvWrapper::NowMicros(this=0x00007f8de9d21a10) at env.h:1298:51
    frame #11: 0x00000001045533f0 tikv-server`rocksdb::StopWatch::StopWatch(this=0x0000700011fd51e0, env=0x00007f8de9d21a10, statistics=0x00007f8de9e0f718, hist_type=0, elapsed=0x0000000000000000, overwrite=true, delay_enabled=false) at stop_watch.h:32:67
    frame #12: 0x000000010451eec6 tikv-server`rocksdb::StopWatch::StopWatch(this=0x0000700011fd51e0, env=0x00007f8de9d21a10, statistics=0x00007f8de9e0f718, hist_type=0, elapsed=0x0000000000000000, overwrite=true, delay_enabled=false) at stop_watch.h:33:65
    frame #13: 0x000000010451e203 tikv-server`rocksdb::DBImpl::GetImpl(this=0x00007f8dea82a400, read_options=0x00007f8dabbdfd00, column_family=0x00007f8de9f09790, key=0x0000700011fd5480, pinnable_val=0x00007f8dabbdeab0, value_found=0x0000000000000000, callback=0x0000000000000000, is_blob_index=0x0000000000000000) at db_impl.cc:1473:13
    frame #14: 0x000000010451e088 tikv-server`rocksdb::DBImpl::Get(this=0x00007f8dea82a400, read_options=0x00007f8dabbdfd00, column_family=0x00007f8de9f09790, key=0x0000700011fd5480, value=0x00007f8dabbdeab0) at db_impl.cc:1464:10
    frame #15: 0x0000000104c63abe tikv-server`::crocksdb_get_pinned_cf(db=0x00007f8de9f094f0, options=0x00007f8dabbdfd00, column_family=0x00007f8de9f06870, key="zt\x80", keylen=64, errptr=0x0000700011fd5580) at c.cc:4779:23
    frame #16: 0x000000010432fe3f tikv-server`rocksdb::rocksdb::DB::get_cf_opt::h9de717b9fb3f7c02 at rocksdb.rs:860:23
    frame #17: 0x0000000104263339 tikv-server`_$LT$engine_rocks..snapshot..RocksSnapshot$u20$as$u20$engine_traits..peekable..Peekable$GT$::get_value_cf_opt::hbd0bcfd9bc92db42 at snapshot.rs:109:17
    frame #18: 0x0000000102850e68 tikv-server`_$LT$raftstore..store..region_snapshot..RegionSnapshot$LT$S$GT$$u20$as$u20$engine_traits..peekable..Peekable$GT$::get_value_cf_opt::h366b06b75e915303 at region_snapshot.rs:215:9
    frame #19: 0x00000001015da956 tikv-server`engine_traits::peekable::Peekable::get_value_cf::h09451bbe349596af at peekable.rs:47:9
    frame #20: 0x0000000101656b5d tikv-server`tikv::server::raftkv::_$LT$impl$u20$tikv..storage..kv..Snapshot$u20$for$u20$raftstore..store..region_snapshot..RegionSnapshot$LT$S$GT$$GT$::get_cf::h521faa0bb64c8087 at raftkv.rs:533:26
    frame #21: 0x0000000101ba24f3 tikv-server`tikv::storage::mvcc::reader::reader::MvccReader$LT$S$GT$::load_lock::h978c90eaa276ee58 at reader.rs:170:19
    frame #22: 0x00000001025837af tikv-server`tikv::storage::txn::actions::prewrite::prewrite::h83bf38e1155500be at prewrite.rs:48:29
    frame #23: 0x0000000102173f85 tikv-server`tikv::storage::txn::commands::prewrite::Prewriter$LT$K$GT$::prewrite::h47f1ff28727f321e at prewrite.rs:445:35
    frame #24: 0x000000010217194c tikv-server`tikv::storage::txn::commands::prewrite::Prewriter$LT$K$GT$::process_write::h1e8469469b4b71d0 at prewrite.rs:370:44
    frame #25: 0x0000000101f4372c tikv-server`_$LT$tikv..storage..txn..commands..prewrite..Prewrite$u20$as$u20$tikv..storage..txn..commands..WriteCommand$LT$S$C$L$GT$$GT$::process_write::h078fbbd4cba1a87e at prewrite.rs:198:9
    frame #26: 0x000000010216e5f4 tikv-server`tikv::storage::txn::commands::Command::process_write::h4e189ae2f7b30472 at mod.rs:539:37
    frame #27: 0x0000000102175a79 tikv-server`tikv::storage::txn::scheduler::Scheduler$LT$E$C$L$GT$::process_write::h3fa094d8e6d1275f at scheduler.rs:635:15
    frame #28: 0x0000000102180232 tikv-server`tikv::storage::txn::scheduler::Scheduler$LT$E$C$L$GT$::process_by_worker::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h85f36a64b17cefc5 at scheduler.rs:579:29
    frame #29: 0x00000001021607a8 tikv-server`tikv::storage::kv::with_tls_engine::_$u7b$$u7b$closure$u7d$$u7d$::h1afde245e02b45af at mod.rs:402:9
    frame #30: 0x000000010239ca0e tikv-server`std::thread::local::LocalKey$LT$T$GT$::try_with::h395b908e8c3772ae at local.rs:272:16
    frame #31: 0x0000000102396eb3 tikv-server`std::thread::local::LocalKey$LT$T$GT$::with::h4144e294c30e0fbe at local.rs:248:9
    frame #32: 0x000000010215fad8 tikv-server`tikv::storage::kv::with_tls_engine::h2f8290439adb3d5c at mod.rs:400:5
    frame #33: 0x000000010217fa19 tikv-server`tikv::storage::txn::scheduler::Scheduler$LT$E$C$L$GT$::process_by_worker::_$u7b$$u7b$closure$u7d$$u7d$::hd8a200dad356bc34 at scheduler.rs:578:25
    frame #34: 0x0000000102268684 tikv-server`_$LT$core..future..from_generator..GenFuture$LT$T$GT$$u20$as$u20$core..future..future..Future$GT$::poll::h70709bf14eac3171 at mod.rs:80:19
    frame #35: 0x00000001027eeba4 tikv-server`tikv_util::yatp_pool::future_pool::FuturePool::spawn::_$u7b$$u7b$closure$u7d$$u7d$::hb58261fbf9029946 at future_pool.rs:112:21
    frame #36: 0x00000001022689f4 tikv-server`_$LT$core..future..from_generator..GenFuture$LT$T$GT$$u20$as$u20$core..future..future..Future$GT$::poll::h72cd38892f6b1397 at mod.rs:80:19
    frame #37: 0x0000000104e31f49 tikv-server`_$LT$yatp..task..future..Runner$u20$as$u20$yatp..pool..runner..Runner$GT$::handle::h6a30500c1234d2e7 at future.rs:261:41
    frame #38: 0x00000001026c9087 tikv-server`_$LT$tikv_util..yatp_pool..YatpPoolRunner$LT$T$GT$$u20$as$u20$yatp..pool..runner..Runner$GT$::handle::h1fe532e5b4cb5979 at mod.rs:93:24
    frame #39: 0x00000001025a4cf2 tikv-server`yatp::pool::worker::WorkerThread$LT$T$C$R$GT$::run::h621099963af660a2 at worker.rs:48:13
    frame #40: 0x00000001016ad523 tikv-server`yatp::pool::builder::LazyBuilder$LT$T$GT$::build::_$u7b$$u7b$closure$u7d$$u7d$::h5fab5d1dded055b2 at builder.rs:91:25
    frame #41: 0x00000001023873f3 tikv-server`std::sys_common::backtrace::__rust_begin_short_backtrace::h920f0bfd29e167bf at backtrace.rs:125:18
    frame #42: 0x0000000101611a73 tikv-server`std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::_$u7b$$u7b$closure$u7d$$u7d$::h522a378da6cf1b63 at mod.rs:474:17
    frame #43: 0x00000001022b0eb3 tikv-server`_$LT$std..panic..AssertUnwindSafe$LT$F$GT$$u20$as$u20$core..ops..function..FnOnce$LT$$LP$$RP$$GT$$GT$::call_once::he1c0ae54f1c0d037 at panic.rs:322:9
    frame #44: 0x00000001020219dc tikv-server`std::panicking::try::do_call::h4162a8834f81dbce at panicking.rs:379:40
    frame #45: 0x00000001022ad5cd tikv-server`__rust_try + 29
    frame #46: 0x000000010200b360 tikv-server`std::panicking::try::h186c50e892e0a323 at panicking.rs:343:19
    frame #47: 0x0000000102393223 tikv-server`std::panic::catch_unwind::h408f7ad6134371d3 at panic.rs:396:14
    frame #48: 0x000000010160e704 tikv-server`std::thread::Builder::spawn_unchecked::_$u7b$$u7b$closure$u7d$$u7d$::h127d2a83aefb7c27 at mod.rs:473:30
    frame #49: 0x00000001023af03d tikv-server`core::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::he4289cc251f1765d at function.rs:227:5
    frame #50: 0x000000010647e63d tikv-server`std::sys::unix::thread::Thread::new::thread_start::h23116ad77b076564 [inlined] _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::h0da94c34a9a2cef3 at boxed.rs:1484:9 [opt]
    frame #51: 0x000000010647e637 tikv-server`std::sys::unix::thread::Thread::new::thread_start::h23116ad77b076564 [inlined] _$LT$alloc..boxed..Box$LT$F$C$A$GT$$u20$as$u20$core..ops..function..FnOnce$LT$Args$GT$$GT$::call_once::hecf760fdfc6f18d2 at boxed.rs:1484 [opt]
    frame #52: 0x000000010647e62e tikv-server`std::sys::unix::thread::Thread::new::thread_start::h23116ad77b076564 at thread.rs:71 [opt]
    frame #53: 0x00007fff20395950 libsystem_pthread.dylib`_pthread_start + 224
    frame #54: 0x00007fff2039147b libsystem_pthread.dylib`thread_start + 15

(lldb) register read rsi
     rsi = 0x0000000000000000

[sticnarf]

After some investigation, I find it is probably a macOS unwinder bug.

I made a minimal reproducible example:

#include <stdio.h>
#include <string.h>
#include <signal.h>
#include <unwind.h>
#include <sys/time.h>

_Unwind_Reason_Code trace_func(_Unwind_Context *ctx, void *arg)
{
    return _URC_NO_REASON;
}

void sig_handler(int signal)
{
    _Unwind_Backtrace(trace_func, NULL);
}

void register_sig_handler()
{
    signal(SIGPROF, sig_handler);
}

void start_timer()
{
    struct itimerval val;
    memset(&val, 0, sizeof(struct itimerval));
    val.it_interval.tv_usec = 10101;
    val.it_value.tv_usec = 10101;

    setitimer(ITIMER_PROF, &val, NULL);
}

void work()
{
    struct timeval tp, tzp;
    gettimeofday(&tp, &tzp);
}

int main(void)
{
    register_sig_handler();
    start_timer();
    for (;;)
    {
        work();
    }
    return 0;
}

This C program leads to a segmentation fault. The backtrace shows the cause is the same:

* thread #1, stop reason = signal SIGSTOP
  * frame #0: 0x00007fff2a55e8b0 libunwind.dylib`libunwind::CFI_Parser<libunwind::LocalAddressSpace>::decodeFDE(libunwind::LocalAddressSpace&, unsigned long, libunwind::CFI_Parser<libunwind::LocalAddressSpace>::FDE_Info*, libunwind::CFI_Parser<libunwind::LocalAddressSpace>::CIE_Info*) + 30
    frame #1: 0x00007fff2a56093c libunwind.dylib`libunwind::UnwindCursor<libunwind::LocalAddressSpace, libunwind::Registers_x86_64>::step() + 124
    frame #2: 0x00007fff2a562eba libunwind.dylib`_Unwind_Backtrace + 188
    frame #3: 0x000000010a459e7b a.out`sig_handler + 27
    frame #4: 0x00007fff203d9d7d libsystem_platform.dylib`_sigtramp + 29
    frame #5: 0x00007fff2036266a libsystem_kernel.dylib`__commpage_gettimeofday + 1
    frame #6: 0x00007fff20278b6d libsystem_c.dylib`gettimeofday + 45
    frame #7: 0x000000010a459f28 a.out`work + 24
    frame #8: 0x000000010a459f4e a.out`main + 30
    frame #9: 0x00007fff203b0621 libdyld.dylib`start + 1

Therefore, the problem is the macOS system libunwind cannot handle the debug information of macOS kernel functions like gettimeofday.

[BusyJay]

I guess we can't do anything practical for the problem. We should check if it's MacOS and return error for the http API.

[mornyx]

x86 does not guarantee the existence of frame-pointer, so maybe it can be solved with a custom unwind implementation: when it finds that context.pc is in the kernel address space, stop backtracking. This may be a bit crude, but may be sufficient for our profiler.

[YangKeao]

when it finds that context.pc is in the kernel address space, stop backtracking

@mornyx It's fine. The pprof-rs in tikv skips backtracking when it founds it's inside the libgcc, glibc, or pthread. But I'm not familiar with macos, I don't know whether this feature can work properly on macos. See https://github.com/tikv/pprof-rs/blob/master/src/profiler.rs#L58 and https://github.com/tikv/pprof-rs/blob/master/src/profiler.rs#L58

[mornyx]

@mornyx It's fine. The pprof-rs in tikv skips backtracking when it founds it's inside the libgcc, glibc, or pthread. But I'm not familiar with macos, I don't know whether this feature can work properly on macos. See https://github.com/tikv/pprof-rs/blob/master/src/profiler.rs#L58 and https://github.com/tikv/pprof-rs/blob/master/src/profiler.rs#L58

This is a good way, blocklist_segments can help us filter those dynamic link library address spaces, we can add the kernel space address range to the list on this basis. But I'm not sure if this would increase the margin of error.

[mstange]

How can a kernel space address end up on the user stack?

[mornyx]

How can a kernel space address end up on the user stack?

Sorry, this is a misrepresentation, the correct one should be addresses other than the current process's stack address space. This check has been implemented by @YangKeao in https://github.com/YangKeao/pprof-rs/blob/frame-pointer/src/addr_validate.rs

[YangKeao]

How can a kernel space address end up on the user stack?

vdso is actually not a "kernel space address". It's automatically mapped to the program memory space by the system when exec the program, so it's surely a user space address. (At least in Linux, I'm not sure about Mac OS), the standard library (e.g. glibc or go runtime) will lookup the start address of vdso in auxv, and call the function in it.

[mstange]

How can a kernel space address end up on the user stack?

Sorry, this is a misrepresentation, the correct one should be addresses other than the current process's stack address space.

Ah I see, that makes sense. Thanks!

This check has been implemented by @YangKeao in https://github.com/YangKeao/pprof-rs/blob/frame-pointer/src/addr_validate.rs

Whoa, using write on a pipe with a random source pointer in order to validate the pointer! Wild! I didn't know you could do that.