From owner-freebsd-hackers@FreeBSD.ORG Fri Jul 22 18:11:11 2005 Return-Path: X-Original-To: freebsd-hackers@freebsd.org Delivered-To: freebsd-hackers@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 41A2516A46A; Fri, 22 Jul 2005 18:10:49 +0000 (GMT) (envelope-from dillon@apollo.backplane.com) Received: from apollo.backplane.com (apollo.backplane.com [216.240.41.2]) by mx1.FreeBSD.org (Postfix) with ESMTP id EA8C6440DF; Fri, 22 Jul 2005 16:54:46 +0000 (GMT) (envelope-from dillon@apollo.backplane.com) Received: from apollo.backplane.com (localhost [127.0.0.1]) by apollo.backplane.com (8.12.9p2/8.12.9) with ESMTP id j6MGskYk076200; Fri, 22 Jul 2005 09:54:46 -0700 (PDT) (envelope-from dillon@apollo.backplane.com) Received: (from dillon@localhost) by apollo.backplane.com (8.12.9p2/8.12.9/Submit) id j6MGskBD076199; Fri, 22 Jul 2005 09:54:46 -0700 (PDT) (envelope-from dillon) Date: Fri, 22 Jul 2005 09:54:46 -0700 (PDT) From: Matthew Dillon Message-Id: <200507221654.j6MGskBD076199@apollo.backplane.com> To: Robert Watson References: <200507212344.j6LNi9HU000683@ferens.net> <20050722004940.P16902@fledge.watson.org> Cc: freebsd-hackers@freebsd.org Subject: Enhanced KTR logging (was RE: Quality of FreeBSD) X-BeenThere: freebsd-hackers@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Technical Discussions relating to FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 22 Jul 2005 18:11:11 -0000 :... :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