4 ms·

Finding out where syscalls are called from: Stack traces with strace

137 points by aheck 2y ago

aheck 2y ago
One of the great strengths of strace as a debugging tool is that it shows you what a program is doing regardless of whether it was compiled with debug info or not. The downside of this is that you only see the program’s syscall. You can use this information to deduce what is happening in the program but you don’t see from where in the program those syscalls originate...
- thundergolfer 2y ago
  Why did you just quote the start of the article?
  - codetrotter 2y ago
    He's the person that submitted the post. I assume he added it for context.
mshockwave 2y ago
Today I definitely learned! I feel like we can just patch strace to read debug info (and use it in stack trace) when present.
fjfaase 2y ago
strace is a rather powerfull tool if you want to find out what a certain executable is doing. Which files it is opening, reading and writing and also which other executables it is executing. I personally have not used the '--stack-trace' option yet. Earlier this year, I have used it to analyze what happens during the initial steps of live-bootstrap [1] and produce a web page with all the information [2]. For this, I wrote a C program to parse and process the output of strace. [1] https://github.com/fosslinux/live-bootstrap https://github.com/fosslinux/live-bootstrap [2] https://fransfaase.github.io/Emulator/ https://fransfaase.github.io/Emulator/
- ranger_danger 2y ago
  And if you want to do the same thing on a whole-system level, bpftrace is invaluable. With tools like opensnoop/execsnoop/etc. you can see all the files and processes being run and by what. There are network-level similar bpf tools also.
- amelius 2y ago
  What flags do you use when you just want to see the files that are being opened? I'm always grepping, but there must be an easier way.
  - Amezarak 2y ago
    strace -e trace=open -f -p pid If you want to see all file-related calls, replace "open" with "file" or you could add the calls one by one: e.g., trace=open,read.
spcharc 2y ago
It can be useful I think. Trying this on my toy project. This is a single thread program so it cannot do syscall from multiple cores. It is not very helpful without debug info: nanosleep({tv_sec=1, tv_nsec=299127292}, NULL) = 0 > /home/spcharc/proj/out() [0x80f1] write(1, "g1() ===== end =====\n", 21g1() ===== end ===== ) = 21 > /home/spcharc/proj/out() [0x80f1] munmap(0x7a267b491000, 66580) = 0 > /home/spcharc/proj/out() [0x80ec] exit(0) = ? +++ exited with 0 +++ > /home/spcharc/proj/out(+0x0) [0x80e7] With debug info added, the output looks much better: nanosleep({tv_sec=1, tv_nsec=297422159}, NULL) = 0 > /home/spcharc/proj/out(assert(bool, char const*)+0x14a) [0x87a8] > /home/spcharc/proj/out(fd_manager::wait_event(timespec const*, timespec&, epoll_event*, unsigned int)+0xbe) [0x5598] > /home/spcharc/proj/out(event_loop::execute_tasks()+0x56) [0x6a10] > /home/spcharc/proj/out(event_loop::main_loop()+0x5b) [0x6b19] > /home/spcharc/proj/out(main+0x184) [0x77c6] > /home/spcharc/proj/out(assert(bool, char const*)+0xc0) [0x871e] write(1, "g1() ===== end =====\n", 21g1() ===== end ===== ) = 21 > /home/spcharc/proj/out(assert(bool, char const*)+0x14f) [0x87ad] > /home/spcharc/proj/out(static_file_buffered_printer<1u, 1012u>::flush()+0x75) [0x5071] > /home/spcharc/proj/out(output_stream<static_file_buffered_printer<1u, 1012u> >::operator<<(Manip)+0x74) [0x3624] > /home/spcharc/proj/out(g1(event_loop*, uptr_t)+0x14c) [0x74bc] > /home/spcharc/proj/out(assert(bool, char const*)+0x12d) [0x878b] munmap(0x7b80db5fd000, 66580) = 0 > /home/spcharc/proj/out(assert(bool, char const*)+0x14a) [0x87a8] > /home/spcharc/proj/out(main+0x1bd) [0x77ff] > /home/spcharc/proj/out(assert(bool, char const*)+0xc0) [0x871e] exit(0) = ? +++ exited with 0 +++ > /home/spcharc/proj/out(assert(bool, char const*)+0x145) [0x87a3] > /home/spcharc/proj/out(assert(bool, char const*)+0xc8) [0x8726] Interesting that every syscall is from assert(). My assert() is basically "if (!cond) {print(msg); exit(1);}". I guess it traced to some unrecognized area and stopped there.
- rcxdude 2y ago
  Does your main have an assert(false) after the main loop? If so the return address could be set to the assert function as some kind of optimization.
  - spcharc 2y ago
tanelpoder 2y ago
There's also strace -kk (--stack-trace=source), but when I just ran it on Ubuntu 24.04, got this error: $ strace -kk pwd strace: Stack traces with source line information (-kk/--stack-trace=source option) are not supported by this build of strace Also, there's "perf trace" that has now gotten pretty good reporting the system call arguments and context (in older versions it didn't report enough details of the system call arguments & their contents). As strace uses userspace ptrace(), it slows down the traced processes and may even cause failures due to mucking around with signalling, perf trace doesn't have that problem as it uses kernel tracepoints.
hawski 2y ago
I feel stupid, because I didn't know strace can do this, I did it once with a gdb script: https://gist.github.com/hadrianw/5b8d33a4b353c49e7dbd6eb55f817901 https://gist.github.com/hadrianw/5b8d33a4b353c49e7dbd6eb55f8... My learning: RTFM.
- tanelpoder 2y ago
  Older versions of strace (like in RHEL 7) did not have such an option.
gdgghhhhh 2y ago
Perf trace is also worth noting. It was much less performance overhead than strace. https://man7.org/linux/man-pages/man1/perf-trace.1.html https://man7.org/linux/man-pages/man1/perf-trace.1.html

137 points by aheck 2y ago

One of the great strengths of strace as a debugging tool is that it shows you what a program is doing regardless of whether it was compiled with debug info or not. The downside of this is that you only see the program’s syscall. You can use this information to deduce what is happening in the program but you don’t see from where in the program those syscalls originate...

thundergolfer 2y ago
Why did you just quote the start of the article?
- codetrotter 2y ago
  He's the person that submitted the post. I assume he added it for context.

mshockwave 2y ago

Today I definitely learned! I feel like we can just patch strace to read debug info (and use it in stack trace) when present.

fjfaase 2y ago

strace is a rather powerfull tool if you want to find out what a certain executable is doing. Which files it is opening, reading and writing and also which other executables it is executing. I personally have not used the '--stack-trace' option yet. Earlier this year, I have used it to analyze what happens during the initial steps of live-bootstrap [1] and produce a web page with all the information [2]. For this, I wrote a C program to parse and process the output of strace. [1] https://github.com/fosslinux/live-bootstrap https://github.com/fosslinux/live-bootstrap [2] https://fransfaase.github.io/Emulator/ https://fransfaase.github.io/Emulator/

ranger_danger 2y ago
And if you want to do the same thing on a whole-system level, bpftrace is invaluable. With tools like opensnoop/execsnoop/etc. you can see all the files and processes being run and by what. There are network-level similar bpf tools also.
amelius 2y ago
What flags do you use when you just want to see the files that are being opened? I'm always grepping, but there must be an easier way.
- Amezarak 2y ago
  strace -e trace=open -f -p pid If you want to see all file-related calls, replace "open" with "file" or you could add the calls one by one: e.g., trace=open,read.

spcharc 2y ago

It can be useful I think. Trying this on my toy project. This is a single thread program so it cannot do syscall from multiple cores. It is not very helpful without debug info: nanosleep({tv_sec=1, tv_nsec=299127292}, NULL) = 0 > /home/spcharc/proj/out() [0x80f1] write(1, "g1() ===== end =====\n", 21g1() ===== end ===== ) = 21 > /home/spcharc/proj/out() [0x80f1] munmap(0x7a267b491000, 66580) = 0 > /home/spcharc/proj/out() [0x80ec] exit(0) = ? +++ exited with 0 +++ > /home/spcharc/proj/out(+0x0) [0x80e7] With debug info added, the output looks much better: nanosleep({tv_sec=1, tv_nsec=297422159}, NULL) = 0 > /home/spcharc/proj/out(assert(bool, char const*)+0x14a) [0x87a8] > /home/spcharc/proj/out(fd_manager::wait_event(timespec const*, timespec&, epoll_event*, unsigned int)+0xbe) [0x5598] > /home/spcharc/proj/out(event_loop::execute_tasks()+0x56) [0x6a10] > /home/spcharc/proj/out(event_loop::main_loop()+0x5b) [0x6b19] > /home/spcharc/proj/out(main+0x184) [0x77c6] > /home/spcharc/proj/out(assert(bool, char const*)+0xc0) [0x871e] write(1, "g1() ===== end =====\n", 21g1() ===== end ===== ) = 21 > /home/spcharc/proj/out(assert(bool, char const*)+0x14f) [0x87ad] > /home/spcharc/proj/out(static_file_buffered_printer<1u, 1012u>::flush()+0x75) [0x5071] > /home/spcharc/proj/out(output_stream<static_file_buffered_printer<1u, 1012u> >::operator<<(Manip)+0x74) [0x3624] > /home/spcharc/proj/out(g1(event_loop*, uptr_t)+0x14c) [0x74bc] > /home/spcharc/proj/out(assert(bool, char const*)+0x12d) [0x878b] munmap(0x7b80db5fd000, 66580) = 0 > /home/spcharc/proj/out(assert(bool, char const*)+0x14a) [0x87a8] > /home/spcharc/proj/out(main+0x1bd) [0x77ff] > /home/spcharc/proj/out(assert(bool, char const*)+0xc0) [0x871e] exit(0) = ? +++ exited with 0 +++ > /home/spcharc/proj/out(assert(bool, char const*)+0x145) [0x87a3] > /home/spcharc/proj/out(assert(bool, char const*)+0xc8) [0x8726] Interesting that every syscall is from assert(). My assert() is basically "if (!cond) {print(msg); exit(1);}". I guess it traced to some unrecognized area and stopped there.

rcxdude 2y ago
Does your main have an assert(false) after the main loop? If so the return address could be set to the assert function as some kind of optimization.
- spcharc 2y ago

tanelpoder 2y ago

There's also strace -kk (--stack-trace=source), but when I just ran it on Ubuntu 24.04, got this error: $ strace -kk pwd strace: Stack traces with source line information (-kk/--stack-trace=source option) are not supported by this build of strace Also, there's "perf trace" that has now gotten pretty good reporting the system call arguments and context (in older versions it didn't report enough details of the system call arguments & their contents). As strace uses userspace ptrace(), it slows down the traced processes and may even cause failures due to mucking around with signalling, perf trace doesn't have that problem as it uses kernel tracepoints.

hawski 2y ago

I feel stupid, because I didn't know strace can do this, I did it once with a gdb script: https://gist.github.com/hadrianw/5b8d33a4b353c49e7dbd6eb55f817901 https://gist.github.com/hadrianw/5b8d33a4b353c49e7dbd6eb55f8... My learning: RTFM.

tanelpoder 2y ago
Older versions of strace (like in RHEL 7) did not have such an option.

gdgghhhhh 2y ago

Perf trace is also worth noting. It was much less performance overhead than strace. https://man7.org/linux/man-pages/man1/perf-trace.1.html https://man7.org/linux/man-pages/man1/perf-trace.1.html