benfred / py-spy

Sampling profiler for Python programs
MIT License
12.53k stars 414 forks source link

Ocassional panics recorded in py-spy output #503

Closed Renlor closed 2 years ago

Renlor commented 2 years ago

Seeing the following error a handful of times while profiling a complex build system which is a mixture of python and make. Does not appear to be a big deal and does not appear to be affecting the results significantly.

python 2.7
py-spy 0.3.12
thread '<unnamed>' panicked at 'index out of bounds: the len is 0 but the index is 0', src/python_spy.rs:767:22
stack backtrace:
   0:     0x7f53de51abcc - std::backtrace_rs::backtrace::libunwind::trace::h72af289afb6801d7
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
   1:     0x7f53de51abcc - std::backtrace_rs::backtrace::trace_unsynchronized::h677113f2dbdf0765
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x7f53de51abcc - std::sys_common::backtrace::_print_fmt::ha332f34d6dd1e5cb
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x7f53de51abcc - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hed4a14673f4c169e
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/sys_common/backtrace.rs:46:22
   4:     0x7f53de55708c - core::fmt::write::hb307c7d56669f4d5
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/core/src/fmt/mod.rs:1150:17
   5:     0x7f53de5172c5 - std::io::Write::write_fmt::h6321fce2c0519dd2
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/io/mod.rs:1667:15
   6:     0x7f53de51c750 - std::sys_common::backtrace::_print::hc2e72e447798e297
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/sys_common/backtrace.rs:49:5
   7:     0x7f53de51c750 - std::sys_common::backtrace::print::h9fa9312becfa3c21
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/sys_common/backtrace.rs:36:9
   8:     0x7f53de51c750 - std::panicking::default_hook::{{closure}}::he62c251136840a58
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:210:50
   9:     0x7f53de51c307 - std::panicking::default_hook::h41cfe94d11e1acb8
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:227:9
  10:     0x7f53de51ce04 - std::panicking::rust_panic_with_hook::h49c731c4edc99637
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:624:17
  11:     0x7f53de51c8e0 - std::panicking::begin_panic_handler::{{closure}}::hb85b790f75e6bf7a
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:521:13
  12:     0x7f53de51b094 - std::sys_common::backtrace::__rust_end_short_backtrace::hf01b37b73f9fc353
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/sys_common/backtrace.rs:141:18
  13:     0x7f53de51c849 - rust_begin_unwind
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/panicking.rs:517:5
  14:     0x7f53de217941 - core::panicking::panic_fmt::ha7efbce9f15156a2
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/core/src/panicking.rs:101:14
  15:     0x7f53de217902 - core::panicking::panic_bounds_check::h7d3ed376f3e8cd3f
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/core/src/panicking.rs:77:5
  16:     0x7f53de2789c5 - py_spy::python_spy::PythonSpy::new::h007c28ae1e75189e
  17:     0x7f53de278fad - py_spy::python_spy::PythonSpy::retry_new::h3e8ac81712c29107
  18:     0x7f53de2ec68d - std::sys_common::backtrace::__rust_begin_short_backtrace::h15a6b1ea429d68a1
  19:     0x7f53de2b4dd1 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h7555c93d3564fb3c
  20:     0x7f53de521ea3 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::ha5e0e69865dd93c4
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/alloc/src/boxed.rs:1636:9
  21:     0x7f53de521ea3 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hfa842986256d2599
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/alloc/src/boxed.rs:1636:9
  22:     0x7f53de521ea3 - std::sys::unix::thread::Thread::new::thread_start::h1162041b3acb4a7a
                               at /rustc/09c42c45858d5f3aedfa670698275303a3d19afa/library/std/src/sys/unix/thread.rs:106:17
jan11011977 commented 2 years ago

I am seeing this as well. Also with a mixture of Python and Make.

benfred commented 2 years ago

Thanks for the heads up! It looks like the error is on these lines of code https://github.com/benfred/py-spy/blob/a01ceeb98fcba54ff5c6f0cdeabf588e163bb516/src/python_spy.rs#L763-L767

Can you share how you're profiling ? Is this with the --subprocesses flag? I'd like to be able to reproduce here

This indicates that the process doesn't have any virtual memory maps to me, which I can only really see happening on process startup/exit. This shouldn't be hard to fix.

benfred commented 2 years ago

The fix I put in #509 is in the latest release - let me know if you still see this happening