Panic when profiling a python module with subprocesses

[mbrookhart]

First, let me say thank you for an awesome project! It gives me much better information than any python/native profiler I've tried before!

I'm seeing an issue similar to these comments, and I figured it deserved it's own issue:
#214 (comment)
#214 (comment)

I'm trying to profile a python module with a C++ backend. The python module and the C++ backend both use threads/subprocesses in different places. I'm using py-spy v0.3.3 installed via pip on Ubuntu 18.04.

For completeness, I'm running one of the TVM tutorials Testing against TVM will require a source build, but the example is completely open source, so it might be worth testing.

I see a crash with --subprocesses, but not with --native or a vanilla profile.

-> % RUST_BACKTRACE=full py-spy record -o profile.svg --subprocesses python tune_relay_x86.py                                                                   
py-spy> Sampling process 100 times a second. Press Control-C to exit.

Extract tasks...
[Task  1/12]  Current/Best:    0.00/   0.00 GFLOPS | Progress: (0/800) | 0.00 sthread 'main' panicked at 'called `Option::unwrap()` on a `None` value', /rustc/5e1a799842ba6ed4a57e91f7ab9435947482f7d8/src/libcore/macros/mod.rs:15:40
stack backtrace:
   0:           0x6fd874 - backtrace::backtrace::libunwind::trace::hdb60e04049e1ddcc
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
   1:           0x6fd874 - backtrace::backtrace::trace_unsynchronized::h390d9f8caa87c4a6
                               at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
   2:           0x6fd874 - std::sys_common::backtrace::_print_fmt::hae15de093c38af7d
                               at src/libstd/sys_common/backtrace.rs:84
   3:           0x6fd874 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h109af5f2d3fa060e
                               at src/libstd/sys_common/backtrace.rs:61
   4:           0x7303ac - core::fmt::write::h5d107c846786f251
                               at src/libcore/fmt/mod.rs:1025
   5:           0x6fac07 - std::io::Write::write_fmt::hebbe4a845a69c3eb
                               at src/libstd/io/mod.rs:1426
   6:           0x6ffa2e - std::sys_common::backtrace::_print::haf8b94d5d4581012
                               at src/libstd/sys_common/backtrace.rs:65
   7:           0x6ffa2e - std::sys_common::backtrace::print::h1e13c5002c162dc0
                               at src/libstd/sys_common/backtrace.rs:50
   8:           0x6ffa2e - std::panicking::default_hook::{{closure}}::hdc11f88ccd2a4eb3
                               at src/libstd/panicking.rs:193
   9:           0x6ff721 - std::panicking::default_hook::ha3d4b1344eed6f10
                               at src/libstd/panicking.rs:210
  10:           0x70010b - std::panicking::rust_panic_with_hook::h3f141f4f335c2438
                               at src/libstd/panicking.rs:471
  11:           0x6ffcbe - rust_begin_unwind
                               at src/libstd/panicking.rs:375
  12:           0x72c1de - core::panicking::panic_fmt::hda0df35392775be8
                               at src/libcore/panicking.rs:84
  13:           0x72c12a - core::panicking::panic::h1b06791847ef3df5
                               at src/libcore/panicking.rs:51
  14:           0x4e570b - py_spy::run_spy_command::hd55e19aefec7bfd4
  15:           0x4e68a6 - py_spy::main::h2a094b08a9a6d3cc
  16:           0x462353 - std::rt::lang_start::{{closure}}::ha19f09e006b7b9df
  17:           0x6ffb53 - std::rt::lang_start_internal::{{closure}}::h2dde9b8c46a2bae5
                               at src/libstd/rt.rs:52
  18:           0x6ffb53 - std::panicking::try::do_call::h283deab0a73ea5c5
                               at src/libstd/panicking.rs:292
  19:           0x706d2a - __rust_maybe_catch_panic
                               at src/libpanic_unwind/lib.rs:78
  20:           0x70048b - std::panicking::try::hef4e7afae047e330
                               at src/libstd/panicking.rs:270
  21:           0x70048b - std::panic::catch_unwind::h21142f20c3430f3e
                               at src/libstd/panic.rs:394
  22:           0x70048b - std::rt::lang_start_internal::h3a042a8c7c0544dc
                               at src/libstd/rt.rs:51
  23:           0x4e7712 - main
[2020-05-26T21:17:08.395220288Z ERROR py_spy::sampler] Failed to get process tree: poisoned lock: another task failed inside
[2020-05-26T21:17:08.395242711Z ERROR py_spy::sampler] Failed to get process tree: poisoned lock: another task failed inside
[2020-05-26T21:17:08.395247339Z ERROR py_spy::sampler] Failed to get process tree: poisoned lock: another task failed inside
[2020-05-26T21:17:08.395251529Z ERROR py_spy::sampler] Failed to get process tree: poisoned lock: another task failed inside
[2020-05-26T21:17:08.395255533Z ERROR py_spy::sampler] Failed to get process tree: poisoned lock: another task failed inside
[2020-05-26T21:17:08.395259771Z ERROR py_spy::sampler] Failed to get process tree: poisoned lock: another task failed inside
[2020-05-26T21:17:08.397568719Z ERROR py_spy::sampler] Failed to get process tree: poisoned lock: another task failed inside

Any ideas? I'm not familiar enough with Rust to dive in at this point. Thanks!

[benfred]

Thanks for the bug report!

I think there was an issue when subprocesses exited that caused this - I put a fix in #265 that I believe should fix.

Can you try it out? It's included in the latest development release pip install py-spy==0.4.0.dev1

[mbrookhart]

Fixes the issue! Thank you!

[benfred]

Awesome! Glad it's working for you.

That dev release also contains a beta version of an embedded web server visualization - that lets you get live profile your program and view flamegraphs and view times on a line basis alongside the python source (py-spy serve -- python myprogram.py). I'm interested in hearing any feedback on this feature =)

[mbrookhart]

Cool! Works pretty well. When I enable --subprocess and --native, though, it seems to be too much information for the browser, it really chugs.

[alberto-dellera]

FYI: 0.4.0.dev1 solves a similar issue with --subprocess and --native that is present in 0.3.0.

And congratulations for a great tool!