Tikv: 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.