Reviewed-by: Tomasz Grabiec <tgrabiec@gmail.com>
Signed-off-by: Gleb Natapov <gleb@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>

The OSv loader has a "--verbose" option to enable debug() output to be
printed to the console and not just to a memory buffer. However, needing to
pass this option in the "-e" string is annoying, and even worse when you want
to use the default command line and didn't even want an explict "-e" option.

So this patch adds a --verbose to run.py, which can be used whether or not
a "-e" option is given. For example:

    run.py --verbose
or
    run.py --verbose tests/tst-timerfd.so

As a shorthand for --verbose, I used "-V". Unfortunately, lowercase "-v"
was already taken (by the "vhost" option).

Fixes #173.

Signed-off-by: Nadav Har'El <nyh@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>

As issue #128 explains, it is annoying that once the "-e" option was used
in run.py, it overrides the default command line, so that running run.py
again without -e reruns the same modified command line, and not the default
one as usual.

This simple patch changes this behavior: On every run of run.py, the command
line is set - if "-e" is given it is set to the given command line, but if
"-e" is absent, the command line is reset to the default one. This is
basically the behavior that people always wanted from run.py.

This patch, and the behavior it performs, are much simpler than any of
the alternatives proposed in issue #128.

Please don't complain that this can only be used for development, and not
for EC2, for creating images to distribute, and so on. After all, this is a
patch to *run.py*, and it is obviously not relevant to anyone who is running
an OSv image not through run.py. This patch only makes run.py more convenient
to use.

Fixes #128.

Signed-off-by: Nadav Har'El <nyh@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>

Add a 'trace extract' command that hides the gdb magic and is
future-proof when we change the trace transport protocol.

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

This adds a '--graphics' option to run.py that enables QEMU's graphics
mode using SDL.  This is needed for testing OSv's VGA support.

Requested-by: Takuya ASADA <syuu@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>

Drop echoing: "SCRIPT, tap0"

Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>

Print the thread pointer, not the address of the thread pointer.

Reviewed-by: Nadav Har'El <nyh@cloudius-systems.com>
Signed-off-by: Avi Kivity <avi@cloudius-systems.com>
Signed-off-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>

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-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>

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

The timestamp typically will come from 'trace.py list' output.  This
change makes it easier to paste the timestamp. Listing prints the time
with '.' separating seconds from nanoseconds.  The options '--since'
and '--until' accept timestamp in nanoseconds so the dot must have
been removed. Now one only needs to append the 's' suffix which
changes the unit to seconds.

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

This:

  --since 10.0 --period 100ms

is now equivalent to:

  --since 10.0 --until 10.1

This option makes it easier to slice the time based on the output of
'trace.py list-timed' which prints trace timestamp and duration.

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-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>

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

Removing 'osv trace summary' and 'osv trace duration' commands from
loader.py. The first is added as 'trace.py summary --timed', the
second one is added as 'trace.py list-timed'.

It was easier to move both in one commit as they are coupled with each
other.

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

The call-graph tree is already using call-sites, this makes also
`trace.py list -b` also use it.

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

Prints output like this:

Collected 36843 samples spanning 8.85 s

Tracepoint statistics:

  name              count
  ----              -----
  sched_wait        18420
  sched_wait_ret    18423

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

When output is not fully consumed because of piping, eg to `head`,
we get an ugly exception:

 Traceback (most recent call last):
   File "scripts/trace.py", line 274, in <module>
     args.func(args)
   File "scripts/trace.py", line 227, in list_timed
     bt_formatter(t.backtrace),
 IOError: [Errno 32] Broken pipe

Let's ignore it, it's normal condition.

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

 - added command descriptions
 - improved clarity of options
 - extracted argument groups
 - changed command help to start with lower case letter

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

It's a left over which is not used any more.

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

Instead of always putting the tests into all images, this patch adds the
option of putting them only in some of the images, by making them into a
new module, modules/tests.

The default image (images/default.py) continues to require the tests
modules, so tests are included in the default image. Building with
"make image=tests" makes an image with only the tests and nothing else.
Other images (e.g., memcached, cassandra,...) currently do not require
the tests module, so the generated image does will not include the tests.

With this patch, "make image=memcached", for example, contains only the
bare minimum needed for memcached, and the resulting qcow image is just
18 MB, down from 69 MB when we included all the tests.

Fixes #160

Signed-off-by: Nadav Har'El <nyh@cloudius-systems.com>
Signed-off-by: Pekka Enberg <penberg@cloudius-systems.com>

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>

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>

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>

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>

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>

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

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>

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>

Usage:

  osv trace save <filename>

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

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>

Signed-off-by: Tomasz Grabiec <tgrabiec@cloudius-systems.com>
Signed-off-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>

Speeds things up slightly.

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

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>

Useful for ad-hoc printing.

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

Processing of this manifest was inside JVM-specific code which caused
the manifest was not processed if there was no java application
in the image.

For example:

  make image=empty check
  ...
  run_main(): cannot execute tests/tst-af-local.so. Powering off.
  Test tst-af-local.so FAILED
  make: *** [check] Error 1

Let's move it to the main manifest processing function.

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

If module has 'usr_files' or 'bootfs_files' declared then
their value will be interpreted as FileMaps and appended
to appropriate manifests.

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

When plain manifests are not enough this is a concise alternative
with improved expresiveness. It allows to declare exclude and include
patterns. It's python based.

Example:

  m = FileMap()
  m.add('${OSV_BUILD_PATH}/tests').to('/tests') \
     .include('**/*.so') \
     .exclude('host/**')

Declared mappings can be saved in manifest form or be subject
of further processing. To save in manifest format:

  save_as_manifest(m, 'my.manifest')

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