Re: [MirageOS-devel] Tracing and profiling blog post

[Thomas Leonard <talex5@xxxxxxxxx>]

On 30 October 2014 18:26, Richard Mortier
<Richard.Mortier@xxxxxxxxxxxxxxxx> wrote:
>
> On 30 Oct 2014, at 16:29, Thomas Leonard <talex5@xxxxxxxxx> wrote:
>
>> On 30 October 2014 14:20, Richard Mortier
>> <Richard.Mortier@xxxxxxxxxxxxxxxx> wrote:
>>>
>>> would it make sense for note_{suspend,resume} to be string -> unit (or some 
>>> more opaque type than string even, though perhaps of fixed size) so that 
>>> the programmer can indicate reasons for the suspend/resume?
>>
>> This name is perhaps confusing, but it's for block_domain/poll/select.
>> On Xen, mirage-platform's main.ml is that only thing that calls it.
>> The reason for suspending is always that there isn't any work to do
>> (exactly what we're waiting for is indicated by the sleeping event
>> channel threads at that moment).
>>
>> If we had a more general version, it could perhaps be used for GC
>> pauses too, but there's a separate entry point for that using
>> Callback, because it's called from C code. Actual suspend-to-disk
>> could be another reason.
>>
>> Are there any more types?
>
> ah-- see comment to other mail i guess. seems likely to be better to 
> parameterise this rather than bake it into the api, doesn't it?  (i may be 
> missing something obvious about types and ocaml here :)

I'm less concerned about this bit of the API because it's only called
from one place anyway (mirage-xen/main.ml).

>>> can labels on threads be changed over their lifetime?  can labels overlap 
>>> or are they unique?  if unique, within what context?
>>
>> Originally there was one label per thread, but now they're essentially
>> just log messages that get attached to the active thread. They can be
>> used to label a thread, but also to note interesting events, so
>> perhaps a different name would be useful here (Trace.log?
>> Trace.note?). There should probably be a printf version too.
>>
>> Actual labelling more often happens with named_wait, named_task, etc now.
>
> ah right; i guess i'm talking about an api that subsumes lwt tracing and 
> supports more general tracing throughout many libraries.

It would be good to be general, but labelling of Lwt threads is always
going to be Lwt-specific. We could generalise the concept of "thread"
to just "some period of time", although creating a labelled Lwt.wait
thread has much the same effect anyway.

I does sound like we need separate concepts for tags (fixed strings
with well-known names, used frequently and probably interned), and
free text messages.

>>> trace_enabled.mli:
>>>
>>> how do i interact with the buffer other than to snapshot it?
>>
>> What kind of interations did you have in mind?
>
> one thing ETW allowed which was nice was to have real-time consumers of the 
> tracing buffers. would allow this kind of infrastructure to plugin to 
> something that was doing more dynamic resource management for unikernels 
> across (e.g.) a datacenter.

I'd imagine that would plug in to the counters system rather than the tracing.

However, I think we can make the "snapshots" very efficient. If the
trace buffer is a Cstruct then snapshot can just pass a view onto the
bit that's already been written (and set a flag to make it allocate a
new buffer when this one is full instead of overwriting it).

>>> ...and what's counter for?  (ie., how general/widely used is it intended to 
>>> be?)
>>
>> In the examples, I used counters for:
>>
>> - Number of active grant refs
>> - Number of block reads completed
>> - Bytes written to console
>> - IP packets sent
>> - TCP bytes submitted
>> - TCP bytes ack'd
>>
>> Measuring stuff can get complicated quickly. The last monitoring
>> system I worked on had many different types of "metric" (instantaneous
>> measurements, cumulative usage, on-going rates of increase, etc). You
>> could efficiently query for e.g. average response latecy between any
>> two points in time, allowing for real-time display of "average latency
>> over the last 5 min" or "number of requests since midnight", etc.
>>
>> The counters were also arranged in a hierarchy. For example, you could
>> have a segments-acked counter for each TCP stream, which would then
>> also get aggregated as totals for that VM, and then further aggregated
>> both per-customer (across multiple VMs), and per resource pool. You
>> could see graphs of aggregated data and then drill down to see what
>> had contributed to it.
>>
>> Some of the metrics were shared with customers[*], who treated them as
>> extra monitoring data for their own (outsourced) resource pools.
>>
>> I don't know whether we want to go down that route just yet, though.
>> It took a while to explain everything ;-)
>
> :)
>
> i guess there are two orthogonal things here.
>
> metrics as you describe above, which to my mind sound like (e.g.) SNMP MIBs. 
> most useful for understanding aggregate performance of a system.
>
> event tracing as i've been implicitly assuming, which permits more detailed 
> cuts through system performance at the cost of added complexity (per magpie).
>
> both are useful i think, though you ought to be able to build the former on 
> the latter (though that might be more complex than seems reasonable).

Yes. I imagine we might want the counters to be active even when
tracing isn't. The connection is that, when you are tracing, having a
trace event for each counter change is useful (even when counters
record their history, it might not be high resolution enough for
tracing work).

Things we used metrics/counters for included:

- Customer billing
- Enforcing per-customer resource limits (e.g. max N requests per day)
- Warning if we were close to missing customer SLA targets (average
latency must be < T ms each day)
- Resource monitoring (disk is 90% full, disk error rate, etc)
- Attack detection (ratio of failed to successful logins becomes
suspiciously high)

>>> agree to some extent -- though if some components wish to control tracing 
>>> in other components as a result of observation of their own behaviour, the 
>>> control API may become  more pervasively used than the dumping/display api 
>>> i guess.
>>
>> Perhaps. I suspect we'd have the libraries just produce events and
>> have the logic for responding to them in the unikernel config, rather
>> than having libraries reconfiguring the profiling directly. That
>> sounds confusing!
>
> heh-- having dynamic control of tracing was something we discussed with 
> magpie but never implemented. the idea would've been something like a 
> datacenter operator could notice an issue, and then "turn up" the tracing to 
> get more detailed models, to the point where they could diagnose the problems.
>
> but as i said, we never actually did that. (though ETW does allow dynamic 
> control over tracing levels from a command line tool.)

I think we should keep it simple for now. A little bit of tracing goes
a long way and Mirage makes it easy to add extra rules or tracing by
pinning components.

The important thing, I think, is that the default traces provide
enough information that you can see roughly what's happening (not just
thousands of anonymous lines). Then people can add extra output as
needed. If something turns out to be generally useful (e.g. keeping a
counter of active grant refs or recording the keys for XenStore
lookups) then we can merge them in.


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