gdb: make Trace convertible to string

Useful for ad-hoc printing.

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
gdb: support backtraces shorter than backtrace_len

If there are fewer frames than backtrace_len the remaining
addresses will be zeros. Let's not print them.

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
gdb: resolve tracepoint_base outside the loop

Speeds things up slightly.

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
Add python wrapper for addr2line

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
gdb: extract trace related abstractions to an independent module

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
trace: support persisting trace stream to file

Having traces persisted in a file has the follwing advantages:

 - trace collection is decoupled from trace analysis. trace analysis
   tools no longer have to be part of GDB scripts. This is important
   for EC2 instances, to which we cannot connect with GDB. In this
   case trace data can be downloaded using other channels, but tools
   remain unchanged.

 - trace analysis doesn't have to be performed in the same OSv session.
   After trace is collected OSv can be shut down or left running without
   further disturbance.

The trace is saved in a binary format of the following structure:

  <format-version>
  <N_tp>
  <tracepoint 1>
  ...
  <tracepoint N_tp>
  <trace 1>
  <trace 2>
  ...
  <trace N_t>

Where:

  <tracepoint X> = <tp_key><name><signature><format>
  <trace X> = <tp_key><thread><time><cpu>(<backtrace_addr>*)<0><data>

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
gdb: introduce command to save traces in binary form

Usage:

  osv trace save <filename>

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
trace: add command-line tool for processing trace files

For all options check:

  scripts/trace.py -h

Example: list all traces:

  scripts/trace.py list trace-file

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
Introduce python module for tree printing

Prints hierarchical data in a form of tree:

Example:

Node0
 |-- Node1
 |    |-- Node2
 |    |
 |    \-- Node3
 |
 \-- Node4

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
trace: add source address formatting options

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
sched: add tracepoint for resuming from wait

Useful for calculating time during which thread
was scheduled out because of wait().

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
trace: add command for printing wait profile

See

  scripts/trace.py prof-wait -h

The command is using sched_wait and sched_wait_ret tracepoints to
calculate the amount of time a thread was waiting. Samples are
collected and presented in a form of call graph tree.

By default callees are closer to the root. To inverse the order pass
-r|--caller-oriented.

If there is too much output, it can be narrowed down using
--max-levels and --min-duration options.

The presented time spectrum can be narrowed down using --since and --until
options which accept timestamps.

Example:

  scripts/trace.py prof-wait --max-levels 3 trace-file

=== Thread 0xffffc0003eaeb010 ===

12.43 s (100.00%, #7696) All
 |-- 12.43 s (99.99%, #7658) sched::thread::do_wait_until
 |    |-- 10.47 s (84.22%, #6417) condvar::wait(lockfree::mutex*, unsigned long)
 |    |    condvar_wait
 |    |    |-- 6.47 s (52.08%, #6250) cv_timedwait
 |    |    |    txg_delay
 |    |    |    dsl_pool_tempreserve_space
 |    |    |    dsl_dir_tempreserve_space
 |    |    |    dmu_tx_try_assign
 |    |    |    dmu_tx_assign
 |    |    |
 |    |    |-- 2.37 s (19.06%, #24) arc_read_nolock
 |    |    |    arc_read
 |    |    |    dsl_read
 |    |    |    traverse_visitbp
 |    |    |
 |    |    |-- 911.75 ms (7.33%, #3) txg_wait_open
 |    |    |    dmu_tx_wait
 |    |    |    zfs_write
 |    |    |    vfs_file::write(uio*, int)
 |    |    |    sys_write
 |    |    |    pwritev
 |    |    |    writev
 |    |    |    __stdio_write
 |    |    |    __fwritex
 |    |    |    fwrite
 |    |    |    0x100000005a5f
 |    |    |    osv::run(std::string, int, char**, int*)

By default every thread has a separate tree, because duration is best
interpreted in the context of particular thread. There is however an
option to merge samples from all threads into one tree:
-m|--merge-threads. It may be useful if you want to inspect all paths
going in/out to/from particular function. The direction can be changed
with -r|--caller-oriented option. Function names is passed to --function
parameter.

Example: check where zfs_write() blocks:

  scripts/trace.py prof-wait -rm --function=zfs_write trace-file

7.46 s (100.00%, #7314) All
 zfs_write
 |-- 6.48 s (86.85%, #6371) dmu_tx_assign
 |    |-- 6.47 s (86.75%, #6273) dmu_tx_try_assign
 |    |    dsl_dir_tempreserve_space
 |    |    |-- 6.47 s (86.75%, #6248) dsl_pool_tempreserve_space
 |    |    |    txg_delay
 |    |    |    cv_timedwait
 |    |    |    condvar_wait
 |    |    |    condvar::wait(lockfree::mutex*, unsigned long)
 |    |    |    sched::thread::do_wait_until
 |    |    |
 |    |    |-- 87.87 us (0.00%, #24) mutex_lock
 |    |    |    sched::thread::do_wait_until
 |    |    |
 |    |    \-- 6.40 us (0.00%, #1) dsl_dir_tempreserve_impl
 |    |         mutex_lock
 |    |         sched::thread::do_wait_until
 |    |
 |    \-- 7.32 ms (0.10%, #98) mutex_lock
 |         sched::thread::do_wait_until
 |
 |-- 911.75 ms (12.22%, #3) dmu_tx_wait
 |    txg_wait_open
 |    condvar_wait
 |    condvar::wait(lockfree::mutex*, unsigned long)
 |    sched::thread::do_wait_until

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
trace: add command for printing tracepoint hit profile

The new 'prof' command shows a hit profile of arbitrary tracepoint. Many
options accepted by 'prof-wait' are also accepted by this command.

Example:

  scripts/trace.py prof -t sched_wait

=== Thread 0xffffc0003eaeb010 ===

(100.00%, #7696) All
 |-- (99.51%, #7658) sched::thread::do_wait_until
 |    |-- (83.38%, #6417) condvar::wait(lockfree::mutex*, unsigned long)
 |    |    condvar_wait
 |    |    |-- (81.21%, #6250) cv_timedwait
 |    |    |    txg_delay
 |    |    |    dsl_pool_tempreserve_space
 |    |    |    dsl_dir_tempreserve_space
 |    |    |    dmu_tx_try_assign
 |    |    |    dmu_tx_assign
 |    |    |    |-- (81.19%, #6248) zfs_write
 |    |    |    |    vfs_file::write(uio*, int)
 |    |    |    |    sys_write
 |    |    |    |    pwritev
 |    |    |    |    writev
 |    |    |    |    __stdio_write
 |    |    |    |    __fwritex
 |    |    |    |    fwrite
 |    |    |    |    0x100000005a5f
 |    |    |    |    osv::run(std::string, int, char**, int*)

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
trace: separate backtrace elements with a comma rather than space

Affects output of 'trace.py list -b' and 'osv trace' GDB
commands. Makes the trace more readable when filename is also
included.

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
trace: show all digits of timestamp

It is easier to use that timestamp as argument to --since and --until
of the prof command, which accept full timestamp in nanoseconds.

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>
debug.py: fix output parsing for addr2line ver. 2.23.52.0.1-9.fc19

Pekka noticed that his addr2line responds with '?? ??:0' on
unknown symbol, whereas mine responds with '??\n??:0'.

Reported-by: Pekka Enberg <penberg@cloudius-systems.com>
Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>