Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tools/profile: Add additional information to backtrace for -v option #5109

Open
wants to merge 1 commit into
base: master
Choose a base branch
from
Open

tools/profile: Add additional information to backtrace for -v option #5109

wants to merge 1 commit into from

Conversation

ekyooo
Copy link
Contributor

@ekyooo ekyooo commented Sep 16, 2024

Add additional information and change format of backtrace

  • add symbol base offset, dso name
  • symbol and dso info is included if it's available in target binary
  • changed format: ADDR [SYMBOL+OFFSET] (MODULE)

before:

      # ./profile.py
          [unknown]
          _PyDict_GetItem_KnownHash
          [unknown]
          [unknown]
          [unknown]
          [unknown]
          _PyObject_MakeTpCall
          _PyObject_CallFunction_SizeT
          [unknown]
          _PyEval_EvalFrameDefault
          PyEval_EvalCode
          [unknown]
          [unknown]
          _PyRun_SimpleFileObject
          _PyRun_AnyFileObject
          Py_RunMain
          Py_BytesMain
          __libc_start_call_main
          __libc_start_main_impl
          _start
          -                python3 (384002)
              1

          [unknown]
          [unknown]
          [unknown]
          [unknown]
          [unknown]
          [unknown]
          -                gnome-shell (2302)
              1

After:

      # ./profile.py -v
          0xffffffff92d5048e apparmor_file_permission+0x4e
          0xffffffff92d5048e apparmor_file_permission+0x4e
          0xffffffff92cdee66 security_file_permission+0x36
          0xffffffff92ae0177 rw_verify_area+0x47
          0xffffffff92ae2cdb vfs_read+0x7b
          0xffffffff92ae3dd3 ksys_read+0x73
          0xffffffff92ae3e89 __x64_sys_read+0x19
          0xffffffff92606f8a x64_sys_call+0x1ada
          0xffffffff93820daf do_syscall_64+0x7f
          0xffffffff93a00130 entry_SYSCALL_64_after_hwframe+0x78
          0x00007550cbd1ba61 [unknown] [libc.so.6 (deleted)]
          0x00006481674445d8 [unknown] [sshd]
          0x000064816740be42 [unknown] [sshd]
          0x000064816740bb19 [unknown] [sshd]
          0x0000648167448feb [unknown] [sshd]
          0x00006481673dae43 [unknown] [sshd]
          0x00006481673c1641 [unknown] [sshd]
          0x00007550cbc2a1ca [unknown] [libc.so.6 (deleted)]
          -                sshd (383707)
              1

          0x0000775b473f221a [unknown] [libgobject-2.0.so.0.8000.0]
          0x0000775b473fbf14 g_value_transform+0x44 [libgobject-2.0.so.0.8000.0]
          0x0000775b46c270f4 [unknown] [libgjs.so.0.0.0]
          0x0000775b46bfe3e3 [unknown] [libgjs.so.0.0.0]
          0x0000775b43d62369 [unknown] [libmozjs-115.so.115.10.0]
          0xae0a8c7400000000 [unknown]
          0x00007ffea963ff60 [unknown]
          -                gnome-shell (2302)
              1

@Bojun-Seo
Copy link
Contributor

How about change the option name from --verbose to --syms or something else?

verbose is usually used to denote some logs which may useful for developers.
However, the feature in this patch is intended for users, not developers.

@yonghong-song
Copy link
Collaborator

In bcc tools, --verbose is mostly used to print out the eventual bpf prog source. In a few instances, the --verbose is used to print out additional information. I think it is good idea to use an option like -a or --address in this case. We can reserve --verbose for future use.

@ekyooo
Copy link
Contributor Author

ekyooo commented Dec 3, 2024 •
edited
Loading

In bcc tools, --verbose is mostly used to print out the eventual bpf prog source. In a few instances, the --verbose is used to print out additional information. I think it is good idea to use an option like -a or --address in this case. We can reserve --verbose for future use.

@yonghong-song @Bojun-Seo
What do you think about printing additional information in the backtrace by default, without requiring an option?
Many other tools, such as LeakSanitizer, GDB, and Linux provide extra information by default for enhanced usefulness. You can refer to the backtrace of LeakSanitizer in this GitHub comment.
#4288 (comment)

@Bojun-Seo
Copy link
Contributor

It seems more reasonable for me to print additional information in the backtrace by default.

@yonghong-song
Copy link
Collaborator

The kernel didn't print out the address. So we could do for the default mode

 apparmor_file_permission+0x4e
 apparmor_file_permission+0x4e
 security_file_permission+0x36
 rw_verify_area+0x47
 vfs_read+0x7b
 ksys_read+0x73
 __x64_sys_read+0x19
...

and for the verbose mode, we can do

          0xffffffff92d5048e apparmor_file_permission+0x4e
          0xffffffff92d5048e apparmor_file_permission+0x4e
          0xffffffff92cdee66 security_file_permission+0x36
          0xffffffff92ae0177 rw_verify_area+0x47
          0xffffffff92ae2cdb vfs_read+0x7b
          0xffffffff92ae3dd3 ksys_read+0x73
          0xffffffff92ae3e89 __x64_sys_read+0x19

The verbose mode will print out address as well for user convenience to search function but actually they can use func symbol to search as well. But address will be useful if the symbol cannot be found the the tool.

@ekyooo
Copy link
Contributor Author

ekyooo commented Dec 13, 2024

The verbose mode will print out address as well for user convenience to search function but actually they can use func symbol to search as well. But address will be useful if the symbol cannot be found the the tool.

Then, do you agree that the remaining additional information (such as symbol base offset and module information, if available) excluding the address is included by default?

In short,

format

for the default mode:

  • kernel stack trace: SYMBOL [+OFFSET]
  • user stack trace: SYMBOL [+OFFSET] [(MODULE+MODULE OFFSET)]

for the verbose mode:

  • kernel stack trace: ADDR SYMBOL [+OFFSET]
  • user stack trace: ADDR SYMBOL [+OFFSET] [(MODULE+MODULE OFFSET)]

('[ ]' means that it is included if available.)

option name for the verbose mode:

-A or --address ('-a' is already in use)

examples

for the default mode:

# ./profile.py 
  apparmor_file_permission+0x4e
  apparmor_file_permission+0x4e
  security_file_permission+0x36
  rw_verify_area+0x47
  vfs_read+0x7b
  ksys_read+0x73
  __x64_sys_read+0x19
  x64_sys_call+0x1ada
  do_syscall_64+0x7f
  entry_SYSCALL_64_after_hwframe+0x78
  [unknown] [libc.so.6 (deleted)]
  [unknown] [sshd]
  [unknown] [sshd]
  [unknown] [sshd]
  [unknown] [sshd]
  [unknown] [sshd]
  [unknown] [sshd]
  [unknown] [libc.so.6 (deleted)]
  -                sshd (383707)
	  1
	  
  [unknown] [libgobject-2.0.so.0.8000.0]
  g_value_transform+0x44 [libgobject-2.0.so.0.8000.0]
  [unknown] [libgjs.so.0.0.0]
  [unknown] [libgjs.so.0.0.0]
  [unknown] [libmozjs-115.so.115.10.0]
  [unknown]
  [unknown]
  -                gnome-shell (2302)
	  1

example for the verbose mode:

# ./profile.py -A
  0xffffffff92d5048e apparmor_file_permission+0x4e
  0xffffffff92d5048e apparmor_file_permission+0x4e
  0xffffffff92cdee66 security_file_permission+0x36
  0xffffffff92ae0177 rw_verify_area+0x47
  0xffffffff92ae2cdb vfs_read+0x7b
  0xffffffff92ae3dd3 ksys_read+0x73
  0xffffffff92ae3e89 __x64_sys_read+0x19
  0xffffffff92606f8a x64_sys_call+0x1ada
  0xffffffff93820daf do_syscall_64+0x7f
  0xffffffff93a00130 entry_SYSCALL_64_after_hwframe+0x78
  0x00007550cbd1ba61 [unknown] [libc.so.6 (deleted)]
  0x00006481674445d8 [unknown] [sshd]
  0x000064816740be42 [unknown] [sshd]
  0x000064816740bb19 [unknown] [sshd]
  0x0000648167448feb [unknown] [sshd]
  0x00006481673dae43 [unknown] [sshd]
  0x00006481673c1641 [unknown] [sshd]
  0x00007550cbc2a1ca [unknown] [libc.so.6 (deleted)]
  -                sshd (383707)
	  1

  0x0000775b473f221a [unknown] [libgobject-2.0.so.0.8000.0]
  0x0000775b473fbf14 g_value_transform+0x44 [libgobject-2.0.so.0.8000.0]
  0x0000775b46c270f4 [unknown] [libgjs.so.0.0.0]
  0x0000775b46bfe3e3 [unknown] [libgjs.so.0.0.0]
  0x0000775b43d62369 [unknown] [libmozjs-115.so.115.10.0]
  0xae0a8c7400000000 [unknown]
  0x00007ffea963ff60 [unknown]
  -                gnome-shell (2302)
	  1

@yonghong-song @Bojun-Seo
Do you agree?

@yonghong-song
Copy link
Collaborator

@ekyooo Your above examples looks good to me.

@ekyooo
tools/profile: Add additional information to backtrace
f692d8a 
Add additional information and change the format of the backtrace:
- Include the symbol base offset and DSO name.
- Symbol and DSO information is included if it's available in the target binary.
- Format:
  [SYMBOL+OFFSET] (MODULE)
- Add a -A(or --addr) option for a detailed format that includes the address:
  ADDR [SYMBOL+OFFSET] (MODULE)

before:
  # ./profile.py
      [unknown]
      _PyDict_GetItem_KnownHash
      [unknown]
      [unknown]
      [unknown]
      [unknown]
      _PyObject_MakeTpCall
      _PyObject_CallFunction_SizeT
      [unknown]
      _PyEval_EvalFrameDefault
      PyEval_EvalCode
      [unknown]
      [unknown]
      _PyRun_SimpleFileObject
      _PyRun_AnyFileObject
      Py_RunMain
      Py_BytesMain
      __libc_start_call_main
      __libc_start_main_impl
      _start
      -                python3 (384002)
          1

      [unknown]
      [unknown]
      [unknown]
      [unknown]
      [unknown]
      [unknown]
      -                gnome-shell (2302)
          1

After:
  # ./profile.py
      runtime.typePointers.next+0x4b [grafana]
      runtime.gcDrain+0x1f4 [grafana]
      runtime.gcBgMarkWorker.func2+0xa5 [grafana]
      runtime.systemstack.abi0+0x4a [grafana]
      runtime.gcBgMarkWorker+0x1f2 [grafana]
      runtime.goexit.abi0+0x1 [grafana]
      -                grafana (25858)
          1

      runtime.nanotime1.abi0+0x89 [containerd]
      runtime.sysmon+0x24b [containerd]
      runtime.mstart1+0x95 [containerd]
      runtime.mstart0+0x76 [containerd]
      runtime.mstart.abi0+0x5 [containerd]
      [unknown]
      -                containerd (454924)
          1

      __get_user_8+0x10 [kernel]
      __get_user_8+0x10 [kernel]
      rseq_ip_fixup+0x69 [kernel]
      __rseq_handle_notify_resume+0x2b [kernel]
      syscall_exit_to_user_mode+0x1f9 [kernel]
      do_syscall_64+0x8c [kernel]
      entry_SYSCALL_64_after_hwframe+0x78 [kernel]
      runtime.futex.abi0+0x23 [dockerd]
      runtime.notesleep+0x87 [dockerd]
      runtime.stopm+0x8c [dockerd]
      runtime.findRunnable+0xd5f [dockerd]
      runtime.schedule+0xb1 [dockerd]
      runtime.park_m+0x1ec [dockerd]
      runtime.mcall+0x50 [dockerd]
      runtime.gopark+0xce [dockerd]
      runtime.(*scavengerState).park+0x49 [dockerd]
      runtime.bgscavenge+0x59 [dockerd]
      runtime.gcenable.gowrap2+0x25 [dockerd]
      runtime.goexit.abi0+0x1 [dockerd]
      -                dockerd (144352)
          1

  # ./profile.py -A
      0xffffffff945afbb8 __get_user_nocheck_4+0x8 [kernel]
      0xffffffff945afbb8 __get_user_nocheck_4+0x8 [kernel]
      0xffffffff936267be futex_wait_setup+0x7e [kernel]
      0xffffffff9362697b __futex_wait+0x13b [kernel]
      0xffffffff93626a94 futex_wait+0x74 [kernel]
      0xffffffff93622765 do_futex+0x105 [kernel]
      0xffffffff9362302a __x64_sys_futex+0x12a [kernel]
      0xffffffff934071a7 x64_sys_call+0x1ce7 [kernel]
      0xffffffff9462601f do_syscall_64+0x7f [kernel]
      0xffffffff94800130 entry_SYSCALL_64_after_hwframe+0x78 [kernel]
      0x00007df292898d61 __GI___futex_abstimed_wait_cancelable64+0xe1 [libc.so.6]
      0x00007df29289bc7e pthread_cond_timedwait@@GLIBC_2.3.2+0x23e [libc.so.6]
      0x0000645da1a160fa os_event::timed_wait(timespec const*)+0x3a [mysqld]
      0x0000645da1a2f551 os_event::wait_time_low(std::chrono::duration<long, std::ratio<1l, 1000000l> >, long)+0x81 [mysqld]
      0x0000645da19e44a9 log_files_governor(log_t*)+0x159 [mysqld]
      0x0000645da19efb19 [unknown] [mysqld]
      0x00007df292cecdb4 [unknown] [libstdc++.so.6.0.33]
      0x00007df29289ca94 start_thread+0x384 [libc.so.6]
      0x00007df292929c3c __GI___clone3+0x2c [libc.so.6]
      -                ib_log_files_g (28830)
          1
@ekyooo
Copy link
Contributor Author

ekyooo commented Dec 27, 2024

I have updated the patch almost as I suggested, and additionally included the '[kernel]' display.
Please let me know if the '[kernel]' display is noisy.

Thank you.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@brendangregg brendangregg Awaiting requested review from brendangregg brendangregg is a code owner

@goldshtn goldshtn Awaiting requested review from goldshtn goldshtn is a code owner

@davemarchevsky davemarchevsky Awaiting requested review from davemarchevsky davemarchevsky is a code owner

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@ekyooo @Bojun-Seo @yonghong-song