Re: [MirageOS-devel] Mirage tracing

[Thomas Leonard <talex5@xxxxxxxxx>]

On 7 October 2014 16:09, Thomas Leonard <talex5@xxxxxxxxx> wrote:
> 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

It has been pointed out to me that these instructions didn't work
(make also tried to build the sim.ml example program, and that
required a modified Lwt). Fixed now!

> 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/

How should tracing work with existing mirage libraries? We want
libraries to be able to report extra information (thread labels, when
significant events occur, performance counters, etc), but we also want
high performance when tracing is off.

One possibility is a mirage-tracing library whose default
implementation does nothing. I imagine the OCaml compiler would
optimise all calls to the library away, using cross-module inlining.
Then you could opam pin the real version if you wanted tracing on.

Or is it better to make it dynamic, so tracing can be enabled at any
time without recompiling? Or with a functor applied by the mirage
tool? Any suggestions?


-- 
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