Re: [PATCH] tracing/markers: make markers select tracepoints

[Frederic Weisbecker]

On Fri, Feb 20, 2009 at 06:48:11PM +0100, Ingo Molnar wrote:
> 
> * Frederic Weisbecker <fweisbec@xxxxxxxxx> wrote:
> 
> > > > >  config MARKERS
> > > > >  	bool "Activate markers"
> > > > > -	depends on TRACEPOINTS
> > > > > +	select TRACEPOINTS
> > > > >  	help
> > > > >  	  Place an empty function call at each marker site. Can be
> > > > >  	  dynamically changed for a probe function.
> > > > 
> > > > but using "select" instead of "depends on" just causes the 
> > > > kind of problem that you described, whereas using "depends on" 
> > > > does follow dependency chains.
> > > 
> > > Well, as long as the secondary selects are 'expanded' along the 
> > > line of dependencies, it should still be fine. With an 
> > > increasing number of dependencies it quickly becomes ugly 
> > > though. This might be one of the cases where it works.
> > > 
> > > Eventually we should eliminate markers, their uses can either be 
> > > converted to new-style tracepoints, or to ftrace_printk().
> > > 
> > > 	Ingo
> > 
> > ftrace_printk adds more overhead if not used since it 
> > inconditionally send the trace, unless the related 
> > TRACE_ITER_PRINTK flag on ftrace is unset.
> > 
> > I don't know how markers work, but the documentation describes 
> > that a single branch check is done in case the probe is 
> > disabled.
> > 
> > With ftrace_printk, even if TRACE_ITER_PRINTK is unset, this 
> > is still one call and one branch check. So for hot callsite 
> > it's unappropriate.
> > 
> > IMHO, tracepoints are more suited to replace markers if they 
> > have to.
> 
> there's i think the KVM usecase where markers are used 
> essentially a printk()-alike flexible tracing facility.
> 
> This is how KVMTRACE looks like at the moment:
> 
> ./vmx.c:	KVMTRACE_3D(MSR_READ, vcpu, ecx, (u32)data, (u32)(data >> 32),
> ./vmx.c:	KVMTRACE_3D(MSR_WRITE, vcpu, ecx, (u32)data, (u32)(data >> 32),
> ./vmx.c:	KVMTRACE_0D(PEND_INTR, vcpu, handler);
> ./vmx.c:	KVMTRACE_3D(VMEXIT, vcpu, exit_reason, (u32)kvm_rip_read(vcpu),
> ./vmx.c:		KVMTRACE_0D(NMI, vcpu, handler);
> ./lapic.c:	KVMTRACE_1D(APIC_ACCESS, apic->vcpu, (u32)offset, handler);
> ./lapic.c:	KVMTRACE_1D(APIC_ACCESS, apic->vcpu, (u32)offset, handler);
> ./svm.c:	KVMTRACE_2D(DR_READ, vcpu, (u32)dr, (u32)val, handler);
> ./svm.c:		KVMTRACE_3D(PAGE_FAULT, &svm->vcpu, error_code,
> ./svm.c:		KVMTRACE_3D(TDP_FAULT, &svm->vcpu, error_code,
> ./svm.c:	KVMTRACE_0D(NMI, &svm->vcpu, handler);
> 
> I think this could easily be converted to a wrapper around 
> ftrace_printk() plus a "kvmtrace" ftrace plugin which activates 
> those wrapped ftrace_printk() sites via a single global 
> __read_mostly flag.
> 
> This means KVM tracing is activated via:
> 
>  echo kvmtrace > /debug/tracing/current_tracer
> 
> that's all.


Note that I haven't looked at kvm tracing in detail, so I could be wrong.
But when I look of the kind of events above which are traced through KVM,
I guess the frequency rate of traces can be high.

The use of ftrace_printk seems to me an overhead here for ring buffer space consuming
and tracing overhead itself.

ftrace_printk inserts the events on the ring buffer as already formatted, so
it consumes more space that traditional binary insertion. But I skip that since we have
16384 entries by default (large enough), though the notion of entry size is dynamic
with the ring buffer.

But doing the vsnprintf on tracing context seems to me inappropriate since
tracing should be as much transparent as possible from the traced site point
of view. I think it should be better on output time, unless the traces rate is not
as high as I imagine.

 
> Basically the conversion would look like this:
> 
> before:
> 
>         KVMTRACE_3D(MSR_READ, &svm->vcpu, ecx, (u32)data,
>                     (u32)(data >> 32), handler);
> 
> after:
> 
> 	kvm_trace("MSR_READ: %p, %08lx, %016Lx\n", &svm->vcpu, ecx, data);
> 
> As a result all these traces would become a lot more readable 
> (and a lot more flexible) both in the source code, and in the 
> trace output stage.


Right.
Anyway, it needs to be integrated into the common tracing part
of the kernel. virt/kvm_trace.c is a whole tracer.


> And any ad-hoc tracepoint can be added, without worrying about 
> the name of the macro or the number of type of arguments. Note 
> that in this specific example we didnt need to split up the u64 
> 'data' into two 32-bit values, nor do we have to pass in the 
> 'handler' name, nor do we have to provide a MSR_READ 
> enumeration.
> 
> The tracing-disabled case would still be as fast - a single 
> branch check.
> 
> Avi, what do you think, any objections against an RFC patchset 
> that shows this off?
> 
> 	Ingo

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/