I've been using record-trace on Linux to take traces of a long-lived process that spawns many ephemeral processes. Symbol resolution consistently takes several minutes, even for 30 second traces.
I'm running record-trace like
record-trace --on-cpu --pid <pid>
I took a profile during symbol resolution (with samply), and ~70% of samples were in
...
read [libc.so.6]
<std::sys::fd::unix::FileDesc>::read_buf [library/std/src/sys/fd/unix.rs]
<std::sys::fs::unix::File>::read_buf [library/std/src/sys/fs/unix.rs]
<&std::fs::File as std::io::Read>::read_buf [library/std/src/fs.rs]
<std::fs::File as std::io::Read>::read_buf [library/std/src/fs.rs]
<&mut std::fs::File as std::io::Read>::read_buf [library/std/src/io/impls.rs]
<std::io::buffered::bufreader::buffer::Buffer>::fill_buf::<&mut std::fs::File> [library/std/src/io/buffered/bufreader/buffer.rs]
<std::io::buffered::bufreader::BufReader<std::fs::File> as std::io::BufRead>::fill_buf [library/std/src/io/buffered/bufreader.rs]
std::io::read_until::<std::io::buffered::bufreader::BufReader<std::fs::File>> [library/std/src/io/mod.rs]
<std::io::buffered::bufreader::BufReader<std::fs::File> as std::io::BufRead>::read_line::{closure#0} [library/std/src/io/mod.rs]
std::io::append_to_string::<<std::io::buffered::bufreader::BufReader<std::fs::File> as std::io::BufRead>::read_line::{closure#0}> [library/std/src/io/mod.rs]
<std::io::buffered::bufreader::BufReader<std::fs::File> as std::io::BufRead>::read_line [library/std/src/io/mod.rs]
<one_collect::helpers::exporting::symbols::KernelSymbolReader>::load_next [/home/zach/git/one-collect/one_collect/src/helpers/exporting/symbols.rs]
<one_collect::helpers::exporting::symbols::KernelSymbolReader as one_collect::helpers::exporting::symbols::ExportSymbolReader>::next [/home/zach/git/one-collect/one_collect/src/helpers/exporting/symbols.rs]
<one_collect::helpers::exporting::mappings::ExportMapping>::add_matching_symbols::<one_collect::helpers::exporting::symbols::KernelSymbolReader> [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mappings.rs]
<one_collect::helpers::exporting::ExportMachine as one_collect::helpers::exporting::ExportMachineOSHooks>::os_add_kernel_mappings_with::<one_collect::helpers::exporting::symbols::KernelSymbolReader> [/home/zach/git/one-collect/one_collect/src/helpers/exporting/os/linux.rs]
<one_collect::helpers::exporting::ExportMachine>::add_kernel_mappings_with::<one_collect::helpers::exporting::symbols::KernelSymbolReader> [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mod.rs]
<one_collect::helpers::exporting::ExportMachine>::add_kernel_mappings [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mod.rs]
<one_collect::helpers::exporting::ExportMachine>::capture_and_resolve_symbols [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mod.rs]
<engine::recorder::Recorder>::run [/home/zach/git/one-collect/record-trace/engine/src/recorder.rs]
record_trace::main [/home/zach/git/one-collect/record-trace/src/main.rs]
...
_libc_start_main [libc.so.6]
start [record-trace]
Another ~10% of samples were in
...
<core::str::iter::SplitWhitespace as core::iter::traits::iterator::Iterator>::next [library/core/src/str/iter.rs]
<core::iter::adapters::enumerate::Enumerate<core::str::iter::SplitWhitespace> as core::iter::traits::iterator::Iterator>::next [library/core/src/iter/adapters/enumerate.rs]
<one_collect::helpers::exporting::symbols::KernelSymbolReader>::load_next [/home/zach/git/one-collect/one_collect/src/helpers/exporting/symbols.rs]
<one_collect::helpers::exporting::symbols::KernelSymbolReader as one_collect::helpers::exporting::symbols::ExportSymbolReader>::next [/home/zach/git/one-collect/one_collect/src/helpers/exporting/symbols.rs]
<one_collect::helpers::exporting::mappings::ExportMapping>::add_matching_symbols::<one_collect::helpers::exporting::symbols::KernelSymbolReader> [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mappings.rs]
<one_collect::helpers::exporting::ExportMachine as one_collect::helpers::exporting::ExportMachineOSHooks>::os_add_kernel_mappings_with::<one_collect::helpers::exporting::symbols::KernelSymbolReader> [/home/zach/git/one-collect/one_collect/src/helpers/exporting/os/linux.rs]
<one_collect::helpers::exporting::ExportMachine>::add_kernel_mappings_with::<one_collect::helpers::exporting::symbols::KernelSymbolReader> [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mod.rs]
<one_collect::helpers::exporting::ExportMachine>::add_kernel_mappings [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mod.rs]
<one_collect::helpers::exporting::ExportMachine>::capture_and_resolve_symbols [/home/zach/git/one-collect/one_collect/src/helpers/exporting/mod.rs]
...
So, nearly all the time is spent reading and parsing /proc/kallsyms. ExportMapping::add_matching_symbols resets the symbol reader, and it's called once for each process. That explains why resolution takes longer for more processes.
I tried a couple small changes:
- use
Cursor<Vec<u8>> instead of BufReader<File> in KernelSymbolReader to reduce read calls
- unroll the loop over
self.buffer.split_whitespace().enumerate() in KernelSymbolReader::load_next
They didn't make much of a difference. The cost of reparsing the data from /proc/kallsyms still dominated.
The main questions I have:
- Is it necessary to reread
/proc/kallsyms for every process?
- Is it possible to configure
perf_event_attr flags via scripting? Disabling perf_event_attr.inherit would help since, in this case, I don't care about the spawned processes
Lastly, a contrived C program that I used for testing:
#include <stdlib.h>
#include <time.h>
#include <unistd.h>
int main(void) {
const time_t start = time(NULL);
time_t elapsed = 0;
while (elapsed < 180) {
// Spawn some processes every second.
for (int i = 0; i < 30; ++i) {
system("cat /proc/meminfo | grep MemTotal > /dev/null");
}
sleep(1);
elapsed = time(NULL) - start;
}
return 0;
}
I've been using
record-traceon Linux to take traces of a long-lived process that spawns many ephemeral processes. Symbol resolution consistently takes several minutes, even for 30 second traces.I'm running
record-tracelikeI took a profile during symbol resolution (with samply), and ~70% of samples were in
Another ~10% of samples were in
So, nearly all the time is spent reading and parsing
/proc/kallsyms.ExportMapping::add_matching_symbolsresets the symbol reader, and it's called once for each process. That explains why resolution takes longer for more processes.I tried a couple small changes:
Cursor<Vec<u8>>instead ofBufReader<File>inKernelSymbolReaderto reduce read callsself.buffer.split_whitespace().enumerate()inKernelSymbolReader::load_nextThey didn't make much of a difference. The cost of reparsing the data from
/proc/kallsymsstill dominated.The main questions I have:
/proc/kallsymsfor every process?perf_event_attrflags via scripting? Disablingperf_event_attr.inheritwould help since, in this case, I don't care about the spawned processesLastly, a contrived C program that I used for testing: