[MirageOS-devel] Mirage tracing

[Thomas Leonard <talex5@xxxxxxxxx>]

I'm currently working on improving the profiling support in Mirage.
Previously [1], I was just graphing stats in libreoffice and looking
at call traces, but I've been thinking about how to get more useful
data.

Tracing individual functions was too fine-grained, I think, and failed
to follow Lwt threads, so I intrumented Lwt to record when threads are
created and resolved, and the interactions between them. Graphing the
results looks like this:

  http://test.roscidus.com/static/block-read-mirage-x86.png

  ( trace file: http://test.roscidus.com/static/log-x86.sexp )

This is for a simple test of reading a block device in a tight loop.
Horizontal lines are Lwt threads from creation to becoming resolved
(returned or failed). Blue arrows indicate one thread waiting for
another. Green arrows indicate one thread resolving another (with
Lwt.wakeup).

By default, threads just appear as numbers, but I added some code to
my unikernel to label some them (I didn't annotate any of the Mirage
libraries, though). For example, the "B.read" thread is what the
unikernel gets back when it calls B.read on the block device, but you
can see that behind this mirage-block-xen is creating other threads.

The graphs are more fun when used interactively. There's a simple GTK
viewer here:

  https://github.com/talex5/mirage-tracing

To test:

  $ git clone https://github.com/talex5/mirage-tracing
  $ cd mirage-tracing
  $ make
  $ ./viewer.native .../log-x86.sexp

Drag to pan; scroll to zoom. As you zoom in, smaller details (e.g.
thread labels for short-running threads) become visible, while gross
features (e.g. arrows that span a long time-frame) fade out.

This is very messy code; I just wanted to see if the visualisations
were useful. What do people think?

My hope is that we can hang other trace data off these diagrams, e.g.
showing when GC is happening and when interrupts occur vs when Mirage
starts handling them. If we can synchronise the clocks, it should also
be possible to combine traces from different machines too (e.g. client
and server, or mirage and dom0).

Suggestions on better ways to do things welcome...


[1] http://roscidus.com/blog/blog/2014/08/15/optimising-the-unikernel/


-- 
Dr Thomas Leonard        http://0install.net/
GPG: 9242 9807 C985 3C07 44A6  8B9A AE07 8280 59A5 3CC1
GPG: DA98 25AE CAD0 8975 7CDA  BD8E 0713 3F96 CA74 D8BA

_______________________________________________
MirageOS-devel mailing list
MirageOS-devel@xxxxxxxxxxxxxxxxxxxx
http://lists.xenproject.org/cgi-bin/mailman/listinfo/mirageos-devel