RFC: klogger: kernel tracing and logging tool

RFC: klogger: kernel tracing and logging tool

[Yoav Etsion]

Hi all,

This may look like a shameless plug, but it is intended as an RFC:
over the past few years I've developed a kernel logging tool called 
Klogger: http://www.cs.huji.ac.il/~etsman/klogger

In some senses, it is similar to the LTT - Linux Trace Toolkit (and was 
actually developed because LTT did not suit my needs).
However, Klogger is much more flexible. The two key points being:
1.
it offers extremely low logging overhead (better than LTT and Dtrace) by 
auto-generating the logging code from user-specified config files.
2.
it allows new events to be defined, and more importantly shared among 
subsystems' developers, thus allowing to understand module/subsystem 
interactions without an all encompassing knowledge.
This feature can allow developers to design the performance logging 
while designing the subsystem to be logged, allowing other 
developers/researchers to get some insights without having to fully 
understand a subsystem's code.

I am very interested in the community's opinion on this matter, so if 
anyone is interested you can find the design document, a HOWTO and 
patches against 2.6.14/2.6.9 on my website: 
http://www.cs.huji.ac.il/~etsman/klogger
or
http://linux-klogger.sf.net

Currently, we use this tool at the the Hebrew University, but if there 
is public interest I can work on it further so it adheres to kernel code 
standards (the tool currently does obscene things like writing to disk 
from kernel threads :-P --- it was written before relayfs was out there).

Thanks,

Yoav Etsion

Re: RFC: klogger: kernel tracing and logging tool

[Steven Rostedt]

YALU (Yet Another Logging Utility :)

On Wed, 22 Feb 2006, Yoav Etsion wrote:

> Hi all,
>
> This may look like a shameless plug, but it is intended as an RFC:
> over the past few years I've developed a kernel logging tool called
> Klogger: http://www.cs.huji.ac.il/~etsman/klogger
>
> In some senses, it is similar to the LTT - Linux Trace Toolkit (and was
> actually developed because LTT did not suit my needs).
> However, Klogger is much more flexible. The two key points being:
> 1.
> it offers extremely low logging overhead (better than LTT and Dtrace) by
> auto-generating the logging code from user-specified config files.
> 2.
> it allows new events to be defined, and more importantly shared among
> subsystems' developers, thus allowing to understand module/subsystem
> interactions without an all encompassing knowledge.
> This feature can allow developers to design the performance logging
> while designing the subsystem to be logged, allowing other
> developers/researchers to get some insights without having to fully
> understand a subsystem's code.
>
> I am very interested in the community's opinion on this matter, so if
> anyone is interested you can find the design document, a HOWTO and
> patches against 2.6.14/2.6.9 on my website:
> http://www.cs.huji.ac.il/~etsman/klogger
> or
> http://linux-klogger.sf.net
>
> Currently, we use this tool at the the Hebrew University, but if there
> is public interest I can work on it further so it adheres to kernel code
> standards (the tool currently does obscene things like writing to disk
> from kernel threads :-P --- it was written before relayfs was out there).
>

Interesting.  I'll take a look to see how you did things.  I have my own
little logging utility that works wonders in finding race conditions and
was also written before relayfs. In fact, Tom Zanussi once made relayfs a
back end for the tool.  But relayfs still has separate buffers for each
CPU and I usually use my tool to see how the CPUs interract, and time
stamps just don't cut it (my tool is best on a lock up, BUG or panic).

You can take a look at what I did, but the documentation is a little out
of date.  I don't think I recorded yet edprint(char *fmt,...) which
records automatically, the cpu, function and line number as well as the
message. Also the print format has changed on how my logread program
prints it out.

Anyway, mine's called logdev and can be found here:

http://www.kihontech.com/logdev

hmmph, maybe someday I'll go back to updating the documentation.

-- Steve

Static instrumentation, was Re: RFC: klogger: kernel tracing and logging tool

[Frank Ch. Eigler]

Yoav Etsion <etsman@gmail.com> writes:

> [...]  I've developed a kernel logging tool called
> Klogger: http://www.cs.huji.ac.il/~etsman/klogger
> In some senses, it is similar to the LTT [...]

It seems like several projects would benefit from markers being
inserted into key kernel code paths for purposes of tracing / probing.

Both LTTng and klogger have macros that expand to largish inline
function calls that appear to cause a noticeable amount of work even
for tracing requests are not actually active.  (klogger munges
interrupts, gets timestamps, before ever testing whether logging was
requested; lttng similar; icache bloat in both cases.)

In other words, even in the inactive state, tracing markers like those
of klogger and ltt impose some performance disruption.  Assuming that
detailed tracing / probing would be a useful facility to have
available, are there any other factors that block adoption of such
markers in official kernels?  In other words, if they could go "fast
enough", especially in the inactive case, would you start placing them
into your code?


- FChE

Re: Static instrumentation, was Re: RFC: klogger: kernel tracing and logging tool

[Yoav Etsion]

Frank,

You raise two important issues:
1. code markers/annotations for tracing/probing purposes.
2. overhead of the kernel loggers in their inactive state

Of these, I think the first is more important, as it addresses some 
basic defeciency of software development --- getting to know someone 
else's code.
In my experience, writing instrumentation for a kernel subsystem (schema 
in Klogger lingo) requires in depth understanding of the code. This 
sometimes tunnel tremendous efforts towards measurements that could 
otherwise become trivial.

Since no one knows the code like its coder, having developers annotate 
their code using some semi-formal language/definitions (or even compiler 
pragmas) can serve as the best basis for any kernel logger.
Once such markers are in place, the second issue --- overheads (as most 
anything else)--- becomes a technical issue. So even when incurring 
inactive overheads, such a tool can be very useful for developers and 
researchers alike.

After all my babble, the bottom line to the community:
will kernel developers annotate their code? can such policies be instated?

Yoav


Frank Ch. Eigler wrote:
> Yoav Etsion <etsman@gmail.com> writes:
> 
> 
>>[...]  I've developed a kernel logging tool called
>>Klogger: http://www.cs.huji.ac.il/~etsman/klogger
>>In some senses, it is similar to the LTT [...]
> 
> 
> It seems like several projects would benefit from markers being
> inserted into key kernel code paths for purposes of tracing / probing.
> 
> Both LTTng and klogger have macros that expand to largish inline
> function calls that appear to cause a noticeable amount of work even
> for tracing requests are not actually active.  (klogger munges
> interrupts, gets timestamps, before ever testing whether logging was
> requested; lttng similar; icache bloat in both cases.)
> 
> In other words, even in the inactive state, tracing markers like those
> of klogger and ltt impose some performance disruption.  Assuming that
> detailed tracing / probing would be a useful facility to have
> available, are there any other factors that block adoption of such
> markers in official kernels?  In other words, if they could go "fast
> enough", especially in the inactive case, would you start placing them
> into your code?
> 
> 
> - FChE
> 

Re: Static instrumentation, was Re: RFC: klogger: kernel tracing and logging tool

[Steven Rostedt]

On Wed, 22 Feb 2006, Frank Ch. Eigler wrote:

>
> Yoav Etsion <etsman@gmail.com> writes:
>
> > [...]  I've developed a kernel logging tool called
> > Klogger: http://www.cs.huji.ac.il/~etsman/klogger
> > In some senses, it is similar to the LTT [...]
>
> It seems like several projects would benefit from markers being
> inserted into key kernel code paths for purposes of tracing / probing.
>
> Both LTTng and klogger have macros that expand to largish inline
> function calls that appear to cause a noticeable amount of work even
> for tracing requests are not actually active.  (klogger munges
> interrupts, gets timestamps, before ever testing whether logging was
> requested; lttng similar; icache bloat in both cases.)
>
> In other words, even in the inactive state, tracing markers like those
> of klogger and ltt impose some performance disruption.  Assuming that
> detailed tracing / probing would be a useful facility to have
> available, are there any other factors that block adoption of such
> markers in official kernels?  In other words, if they could go "fast
> enough", especially in the inactive case, would you start placing them
> into your code?
>
>

Have you taken a look at my logdev utility.  I usually use something like
the macro of this:

edprint("print my var %08lx", var);

which is defined as:

#ifdef CONFIG_LOGDEV
#  define LOGDEV(x,y...) logdev_##x(y)
#  define LOGTFPRINT(x...) do { if (atomic_read(&logdev_print_enabled)) \
     LOGDEV(print_time_func,__FUNCTION__,__LINE__,x); } while(0)

#  define _edprint(x,y...) do { \
    LOGTFPRINT(x "%s\n", y);} } while(0)
#  define edprint(x...) _edprint(x,"")

#else

#  define LOGTFPRINT(x...) do {} while(0)
#  define edprint(x...) do {} while(0)

#endif


This is just an idea of what is done.  This crazy macros are used because
I also have the logdev as a module, and if it is not compiled in, the
LOGTFPRINT turns into a spinlock holder  to safely load and unload
it.  I haven't used the module version in a few years, so I probably
should get rid of that feature.

Anyway, the atomic variable logdev_print_enabled is checked before doing
anything else, so it doesn't invade the code too much when disabled.  And
of course has no affect when not configured.

It also has ways to store everything binary.  The function name is saved
as a pointer and my read utility (which I don't know if I uploaded the
latest) does a mmap of /dev/mem to find the actual name. If you don't have
root, then it miss out, but the utility doesn't crash, it just doesn't
show the name.

 http://www.kihontech.com/logdev

-- Steve