How to comprehend `sample` output

terminal

This is NOT a duplicate of this question!! The previous question received no satisfactory answer.

I'm trying to use sample to do some time profiling on a Rust process named saample. Can someone help me comprehend exactly what's going on?

This is what I've figured out so far in a line like this:
885 std::sys_common::backtrace::__rust_begin_short_backtrace::h5cb760574ede76e4 (in saample) + 10 [0x10d3556fa] backtrace.rs:125

885 – some sort of id

std::sys_common::backtrace::__rust_begin_short_backtrace::h5cb760574ede76e4 – which Rust function is running

(in saample) – where this function is running

+ 10 I think this might be time in milliseconds? However, adding up all the +\d brings the total "milliseconds" to 1624, which is a lot more than 1 second. This might be call count then.

[0x10d3556fa] The memory address

backtrace.rs:125 location for the previously ran function.

Does sample output tell me anything about how long or how frequently these functions are called?

Analysis of sampling saample (pid 2561) every 1 millisecond
Process:         saample [2561]
Path:            /Users/USER/*/saample
Load Address:    0x10d354000
Identifier:      saample
Version:         0
Code Type:       X86-64
Parent Process:  zsh [2467]

Date/Time:       2021-07-23 13:02:03.889 -0700
Launch Time:     2021-07-23 13:02:02.691 -0700
OS Version:      Mac OS X 10.15.6 (19G2021)
Report Version:  7
Analysis Tool:   /usr/bin/sample

Physical footprint:         332K
Physical footprint (peak):  332K
----

Call graph:
    885 Thread_45257   DispatchQueue_1: com.apple.main-thread  (serial)
      885 start  (in libdyld.dylib) + 1  [0x7fff715a3cc9]
        885 main  (in saample) + 41  [0x10d356209]
          885 std::rt::lang_start_internal::h0c37a46739a0311d  (in saample) + 644  [0x10d378a84]  rt.rs:51
            885 std::rt::lang_start::_$u7b$$u7b$closure$u7d$$u7d$::h5cdae29307de47d2  (in saample) + 12  [0x10d3554cc]  rt.rs:66
              885 std::sys_common::backtrace::__rust_begin_short_backtrace::h5cb760574ede76e4  (in saample) + 10  [0x10d3556fa]  backtrace.rs:125
                885 saample::main::he5a59bfa88e51949  (in saample) + 295  [0x10d355f17]  main.rs:5
                  885 std::process::Command::output::h1b9edbfbdd42bee8  (in saample) + 82  [0x10d375432]  process.rs:885
                    885 std::process::Child::wait_with_output::h7a56dcf388f23038  (in saample) + 376  [0x10d3755f8]  process.rs:1689
                      885 poll  (in libsystem_kernel.dylib) + 10  [0x7fff716eb3d6]

Total number in stack (recursive counted multiple, when >=5):

Sort by top of stack, same collapsed (when >= 5):
        poll  (in libsystem_kernel.dylib)        885

Binary Images:
       0x10d354000 -        0x10d397fff +saample (0) <CAEBBABC-C8CE-3E86-A17A-24F047B7E157> /Users/*/saample
       0x1152a7000 -        0x115338f47  dyld (750.6) <F9D4DEDC-8296-3E3F-B517-9C8B89A4C094> /usr/lib/dyld
    0x7fff6e588000 -     0x7fff6e589fff  libSystem.B.dylib (1281.100.1) <C0C9872A-E730-37EA-954A-3CE087C15535> /usr/lib/libSystem.B.dylib
    0x7fff6e86e000 -     0x7fff6e8c0fff  libc++.1.dylib (902.1) <59A8239F-C28A-3B59-B8FA-11340DC85EDC> /usr/lib/libc++.1.dylib
    0x7fff6e8c1000 -     0x7fff6e8d6ffb  libc++abi.dylib (902) <E692F14F-C65E-303B-9921-BB7E97D77855> /usr/lib/libc++abi.dylib
    0x7fff6e8d7000 -     0x7fff6e8d7fff  libcharset.1.dylib (59) <72447768-9244-39AB-8E79-2FA14EC0AD33> /usr/lib/libcharset.1.dylib
    0x7fff6f361000 -     0x7fff6f451fff  libiconv.2.dylib (59) <18311A67-E4EF-3CC7-95B3-C0EDEE3A282F> /usr/lib/libiconv.2.dylib
    0x7fff703e8000 -     0x7fff7041bfde  libobjc.A.dylib (787.1) <6DF81160-5E7F-3E31-AA1E-C875E3B98AF6> /usr/lib/libobjc.A.dylib
    0x7fff704ef000 -     0x7fff70507fff  libresolv.9.dylib (67.40.1) <C57EDFEF-D36A-310B-8D14-8C68A625B1E8> /usr/lib/libresolv.9.dylib
    0x7fff71385000 -     0x7fff7138aff3  libcache.dylib (83) <AF488D13-9E89-35E0-B078-BE37CC5B8586> /usr/lib/system/libcache.dylib
    0x7fff7138b000 -     0x7fff71396fff  libcommonCrypto.dylib (60165.120.1) <C7912BE5-993E-3581-B2A0-6AABDC8C5562> /usr/lib/system/libcommonCrypto.dylib
    0x7fff71397000 -     0x7fff7139efff  libcompiler_rt.dylib (101.2) <49B8F644-5705-3F16-BBE0-6FFF9B17C36E> /usr/lib/system/libcompiler_rt.dylib
    0x7fff7139f000 -     0x7fff713a8ff7  libcopyfile.dylib (166.40.1) <3C481225-21E7-370A-A30E-0CCFDD64A92C> /usr/lib/system/libcopyfile.dylib
    0x7fff713a9000 -     0x7fff7143bfdb  libcorecrypto.dylib (866.140.1) <60567BF8-80FA-359A-B2F3-A3BAEFB288FD> /usr/lib/system/libcorecrypto.dylib
    0x7fff71548000 -     0x7fff71588ff0  libdispatch.dylib (1173.100.2) <CD9C059C-91D9-30E8-8926-5B9CD0D5D4F5> /usr/lib/system/libdispatch.dylib
    0x7fff71589000 -     0x7fff715bffff  libdyld.dylib (750.6) <789A18C2-8AC7-3C88-813D-CD674376585D> /usr/lib/system/libdyld.dylib
    0x7fff715c0000 -     0x7fff715c0ffb  libkeymgr.dylib (30) <DB3337BE-01CA-3425-BD0C-87774FC0CDC0> /usr/lib/system/libkeymgr.dylib
    0x7fff715ce000 -     0x7fff715ceff7  liblaunch.dylib (1738.140.1) <AFBCBDD3-0B55-3ECD-8E04-A73A3A57356B> /usr/lib/system/liblaunch.dylib
    0x7fff715cf000 -     0x7fff715d4ff7  libmacho.dylib (959.0.1) <AA613A9C-961A-3B67-B696-4622FA59FC4E> /usr/lib/system/libmacho.dylib
    0x7fff715d5000 -     0x7fff715d7ff3  libquarantine.dylib (110.40.3) <F234E51D-FD0B-3EE4-B679-AE3EE9C536C3> /usr/lib/system/libquarantine.dylib
    0x7fff715d8000 -     0x7fff715d9ff7  libremovefile.dylib (48) <7C7EFC79-BD24-33EF-B073-06AED234593E> /usr/lib/system/libremovefile.dylib
    0x7fff715da000 -     0x7fff715f1ff3  libsystem_asl.dylib (377.60.2) <1563EE02-0657-3B78-99BE-A947C24122EF> /usr/lib/system/libsystem_asl.dylib
    0x7fff715f2000 -     0x7fff715f2ff7  libsystem_blocks.dylib (74) <0D53847E-AF5F-3ACF-B51F-A15DEA4DEC58> /usr/lib/system/libsystem_blocks.dylib
    0x7fff715f3000 -     0x7fff7167afff  libsystem_c.dylib (1353.100.2) <BBDED5E6-A646-3EED-B33A-91E4331EA063> /usr/lib/system/libsystem_c.dylib
    0x7fff7167b000 -     0x7fff7167effb  libsystem_configuration.dylib (1061.141.1) <0EE84C33-64FD-372B-974A-AF7A136F2068> /usr/lib/system/libsystem_configuration.dylib
    0x7fff7167f000 -     0x7fff71682fff  libsystem_coreservices.dylib (114) <A199156E-058D-3ABB-BCE9-4B9F20DCED0F> /usr/lib/system/libsystem_coreservices.dylib
    0x7fff71683000 -     0x7fff7168bfff  libsystem_darwin.dylib (1353.100.2) <5B12B5DB-3F30-37C1-8ECC-49A66B1F2864> /usr/lib/system/libsystem_darwin.dylib
    0x7fff7168c000 -     0x7fff71693fff  libsystem_dnssd.dylib (1096.100.3) <EBB4C2C2-E031-3094-B40A-E67BF261D295> /usr/lib/system/libsystem_dnssd.dylib
    0x7fff71694000 -     0x7fff71695ffb  libsystem_featureflags.dylib (17) <29FD922A-EC2C-3F25-BCCC-B58D716E60EC> /usr/lib/system/libsystem_featureflags.dylib
    0x7fff71696000 -     0x7fff716e3ff7  libsystem_info.dylib (538) <8A321605-5480-330B-AF9E-64E65DE61747> /usr/lib/system/libsystem_info.dylib
    0x7fff716e4000 -     0x7fff71710ff7  libsystem_kernel.dylib (6153.141.1) <2B6311E6-6240-3EF7-8C87-475B66F7452C> /usr/lib/system/libsystem_kernel.dylib
    0x7fff71711000 -     0x7fff71758fff  libsystem_m.dylib (3178) <00F331F1-0D09-39B3-8736-1FE90E64E903> /usr/lib/system/libsystem_m.dylib
    0x7fff71759000 -     0x7fff71780fff  libsystem_malloc.dylib (283.100.6) <8549294E-4C53-36EB-99F3-584A7393D8D5> /usr/lib/system/libsystem_malloc.dylib
    0x7fff71781000 -     0x7fff7178effb  libsystem_networkextension.dylib (1095.140.2) <F06C65C5-2CBE-313C-96E1-A09240F9FE57> /usr/lib/system/libsystem_networkextension.dylib
    0x7fff7178f000 -     0x7fff71798ff7  libsystem_notify.dylib (241.100.2) <FA22F928-D91B-3AA5-96BB-3186AC0FB264> /usr/lib/system/libsystem_notify.dylib
    0x7fff71799000 -     0x7fff717a1fef  libsystem_platform.dylib (220.100.1) <009A7C1F-313A-318E-B9F2-30F4C06FEA5C> /usr/lib/system/libsystem_platform.dylib
    0x7fff717a2000 -     0x7fff717acfff  libsystem_pthread.dylib (416.100.3) <62CB1A98-0B8F-31E7-A02B-A1139927F61D> /usr/lib/system/libsystem_pthread.dylib
    0x7fff717ad000 -     0x7fff717b1ff3  libsystem_sandbox.dylib (1217.141.1) <6DE13684-5A67-3009-A53A-C9086CF241C3> /usr/lib/system/libsystem_sandbox.dylib
    0x7fff717b2000 -     0x7fff717b4fff  libsystem_secinit.dylib (62.100.2) <F80872AA-E1FD-3D7E-8729-467656EC6561> /usr/lib/system/libsystem_secinit.dylib
    0x7fff717b5000 -     0x7fff717bcffb  libsystem_symptoms.dylib (1238.120.1) <5820A2AF-CE72-3AB3-ABCC-273A3419FB55> /usr/lib/system/libsystem_symptoms.dylib
    0x7fff717bd000 -     0x7fff717d3ff2  libsystem_trace.dylib (1147.120) <04B47629-847B-3D74-8ABE-C05EF9DEEFE4> /usr/lib/system/libsystem_trace.dylib
    0x7fff717d5000 -     0x7fff717daff7  libunwind.dylib (35.4) <42B7B509-BAFE-365B-893A-72414C92F5BF> /usr/lib/system/libunwind.dylib
    0x7fff717db000 -     0x7fff71810ffe  libxpc.dylib (1738.140.1) <3E243A41-030F-38E3-9FD2-7B38C66C35B1> /usr/lib/system/libxpc.dylib

Best Answer

You have it almost right, but not quite:

885 is not an id number, it is actually the number of milliseconds spent in this node in the call graph and its children. Note that this accumulates, so that for example the number of milliseconds shown for the "main" function near the top includes the number of milliseconds spent in functions called by main (and so on for its children).

+ 10 is not the time in milliseconds. Instead it is actually the number distance from the beginning of the specified function and to the current program counter. I.e. for example + 800 would indicate that this is not is not something that happens at the beginning of the function, but rather a number of instructions in.

backtrace.rs:125 is not the previously run function, rather it is the source code file and line number for this particular node in the call graph. I.e. this means that at line 125 in backtrace.rs is the code that this node represents (which is then 10 bytes of machine code after the beginning of the function.

Note: In the above I write "time spent", however you should be aware that technically this is a sampling profiler - so it actually means "how many time was the program sampled at this particular point".

As sample by defaults samples once per millisecond (which you're also doing) this means that you can think of this as the number of milliseconds spent at that node.

Again, as it is a sampling profiler, you get no information about what happens when the process is not being sampled. I.e. that the process is doing X when you sample it 10 times in a row doesn't necessarily mean that it spent 10 milliseconds doing X, it could be spending 5 milliseconds doing X and 5 milliseconds doing Y, but you just never happened to sample when it was doing Y.

Regarding your final question, this means that the output does not tell you how frequently a particular function was called (i.e. 100 samples of 100 separate calls to a function could show up the same in the output as 100 samples of 1 very long call to the function).

Related Question