Re: [MirageOS-devel] Mirage tracing

[Thomas Leonard <talex5@xxxxxxxxx>]

On 9 October 2014 21:03, Len Maxwell <len@xxxxxxxxxxxxx> wrote:
> On Thu, Oct 9, 2014 at 2:51 PM, Thomas Leonard <talex5@xxxxxxxxx> wrote:
>>
>> The PC will be somewhere in Lwt, and inlining will likely make walking
>> the stack unreliable. But something like the camlp4 annotations Anil
>> mentioned would probably help.
>
> OK, that makes sense.
>
>>> Once you can recognize common patterns in thread creation, you can
>>> present them more clearly in the visualization.  The resulting data might
>>> also be amenable to flame graph visualization:
>>
>> One problem with using flamegraphs here is that threads run in
>> parallel (and may outlive their parents, though you can't see it in
>> this example image). e.g. a thread that spawns 10 parallel sleep
>> subthreads and then joins on them - how would you account for that?
>
> Point taken.  I would focus on threads that spend significant time "blocked"
> on I/O or running on-CPU.  Given some time I might try to prototype that.

I've added notifications of when it switches threads, so you can now
see which thread was active at any time (highlighted in white).

>> I updated the picture with a new trace, which includes more labels and
>> lays out "tail-recursive" calls (where a thread merges with a thread
>> it previously created) horizontally:
>>
>> http://test.roscidus.com/static/block-read-mirage-x86.png
>> ( updated trace file: http://test.roscidus.com/static/log-x86.sexp )
>>
>> Unfortunately, I overwrote the originals so I'm not sure exactly which
>> threads you're referring to. The new layout hopefully makes it clear
>> that there are two main things going on here:
>>
>> - the test unikernel's loop reading from the the block device ("Process 
>> data")
>> - the blkfront polling loop, processing responses from dom0 ("blkfront.poll")
>>
>> I suspect there are some missing arrows. e.g. 425 gets notified by
>> blkfront and then the Process data thread suddenly resolves 426 for no
>> obvious reason. Probably just a missing notification somewhere.
>
> The thread I was interested in looked similar to 425, so that may explain it.

I've gone through all the Lwt code again and improved the tracing
(moved lots of duplicated code into a helper function) and it's
looking OK now (screenshot above updated).

>> Also, I need to add an indication of when we send a request on an
>> event channel. Here, we only see the replies.
>
> Reviewing the log with the viewer has helped me get a better idea of how
> things fit together at runtime.  It will be interesting to see more
> data around the
> interactions with Xen.

Yes, the startup process is interesting too, seeing all the xenstore
interactions. I've got it to show the exceptions for failed threads
now, so you can see it getting Xs_protocol.Eagain a few times (is that
supposed to happen?).

Thanks for the patch to stop labels going off the left edge too!


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