Enhanced KTR logging (was RE: Quality of FreeBSD)

[Matthew Dillon]

:...
:have an extensive instrumentation system named KTR(9).  If you're 
:interested in giving it a try, you can find out more here:
:
:     http://www.watson.org/~robert/freebsd/netperf/ktr/
:
:This page is primarily targetted at tracing locks, memory allocation, and 
:context switching, but you can also trace I/O, bus operations, VFS 
:operations, and a range of other things. While my web page doesn't talk 
:about it, as it's generally focused on micro-tracing of kernel events, you 
:can also queue the event stream to disk using alq(9).  The man pages have 
:more information.  There are some neat tools, such as Jeff Roberson's 
:schedgraph, for managing and rendering trace results.
:...
:Robert N M Watson

    Speaking of KTR, I would recommend that you look at our implementation
    of it (modeled after the one in FreeBSD but somewhat more generic at the
    cost of being slightly more expensive).  In particular, I added some
    trivial code which traces back two stack frames and provides the 
    instruction pointer of the caller of the procedure that did the KTR log,
    and the caller of the caller of the procedure that did the KTR log.

    I then rewrote the ktrdump program to extract the kernel's namelist
    and provide actual symbolic names.  The result was a *HUGE* improvement
    in the usefullness of KTR.  Like night and day, in fact.

    The heart of the two-caller-traceback is the cpu_ktr_caller() function
    in /usr/src/sys/i386/i386/ktr.c.  I recommend that you add the traceback
    facility to your own KTR implementation.

    http://www.dragonflybsd.org/cgi-bin/cvsweb.cgi/src/sys/i386/i386/ktr.c?rev=1.1&content-type=text/x-cvsweb-markup&only_with_tag=HEAD

    Here is an example of ktrdump -a output:

index  cpu timestamp        caller2              caller1             ID                             file and line                  trace
     0 0   78286413138797   pmap_remove_pages+455 zfree+33             tokens_get               /usr/src/sys/kern/lwkt_token.c:426  REF=0xd71f2a54 TOK=0xc043e500 TD=0xcc2b7200
     1 0   78286413139038   pmap_remove_pages+455 zfree+83             tokens_release           /usr/src/sys/kern/lwkt_token.c:466  REF=0xd71f2a54 TOK=0xc043e500 TD=0xcc2b7200
     2 0   78286413140030   pmap_remove_pages+455 zfree+33             tokens_get               /usr/src/sys/kern/lwkt_token.c:426  REF=0xd71f2a54 TOK=0xc043e500 TD=0xcc2b7200
     3 0   78286413140279   pmap_remove_pages+455 zfree+83             tokens_release           /usr/src/sys/kern/lwkt_token.c:466  REF=0xd71f2a54 TOK=0xc043e500 TD=0xcc2b7200

					-Matt
					Matthew Dillon 
					<dillon at backplane.com>