Date: Wed, 19 Dec 2012 20:10:00 +0000 (UTC) From: Jeff Roberson <jeff@FreeBSD.org> To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r244445 - in head/sys: kern sys tools Message-ID: <201212192010.qBJKA0lb075959@svn.freebsd.org>
next in thread | raw e-mail | index | archive | help
Author: jeff Date: Wed Dec 19 20:10:00 2012 New Revision: 244445 URL: http://svnweb.freebsd.org/changeset/base/244445 Log: - Add new machine parsable KTR macros for timing events. - Use this new format to automatically handle syscalls and VOPs. This changes the earlier format but is still human readable. Sponsored by: EMC / Isilon Storage Division Modified: head/sys/kern/subr_syscall.c head/sys/sys/ktr.h head/sys/tools/vnode_if.awk Modified: head/sys/kern/subr_syscall.c ============================================================================== --- head/sys/kern/subr_syscall.c Wed Dec 19 20:08:06 2012 (r244444) +++ head/sys/kern/subr_syscall.c Wed Dec 19 20:10:00 2012 (r244445) @@ -77,13 +77,12 @@ syscallenter(struct thread *td, struct s if (KTRPOINT(td, KTR_SYSCALL)) ktrsyscall(sa->code, sa->narg, sa->args); #endif - - CTR6(KTR_SYSC, -"syscall: td=%p pid %d %s (%#lx, %#lx, %#lx)", - td, td->td_proc->p_pid, syscallname(p, sa->code), - sa->args[0], sa->args[1], sa->args[2]); + KTR_START4(KTR_SYSC, "syscall", syscallname(p, sa->code), + td, "pid:%d", td->td_proc->p_pid, "arg0:%p", sa->args[0], + "arg1:%p", sa->args[1], "arg2:%p", sa->args[2]); if (error == 0) { + STOPEVENT(p, S_SCE, sa->narg); if (p->p_flag & P_TRACED && p->p_stops & S_PT_SCE) { PROC_LOCK(p); @@ -150,10 +149,12 @@ syscallenter(struct thread *td, struct s sa->callp, NULL, (error) ? -1 : td->td_retval[0]); #endif syscall_thread_exit(td, sa->callp); - CTR4(KTR_SYSC, "syscall: p=%p error=%d return %#lx %#lx", - p, error, td->td_retval[0], td->td_retval[1]); } retval: + KTR_STOP4(KTR_SYSC, "syscall", syscallname(p, sa->code), + td, "pid:%d", td->td_proc->p_pid, "error:%d", error, + "retval0:%#lx", td->td_retval[0], "retval1:%#lx", + td->td_retval[1]); if (traced) { PROC_LOCK(p); td->td_dbgflags &= ~TDB_SCE; @@ -176,9 +177,6 @@ syscallret(struct thread *td, int error, */ userret(td, td->td_frame); - CTR4(KTR_SYSC, "syscall %s exit thread %p pid %d proc %s", - syscallname(p, sa->code), td, td->td_proc->p_pid, td->td_name); - #ifdef KTRACE if (KTRPOINT(td, KTR_SYSRET)) { ktrsysret(sa->code, (td->td_pflags & TDP_NERRNO) == 0 ? Modified: head/sys/sys/ktr.h ============================================================================== --- head/sys/sys/ktr.h Wed Dec 19 20:08:06 2012 (r244444) +++ head/sys/sys/ktr.h Wed Dec 19 20:10:00 2012 (r244445) @@ -244,6 +244,50 @@ void ktr_tracepoint(u_int mask, const ch point, a0, (v0), a1, (v1), a2, (v2), a3, (v3)) /* + * Start functions denote the start of a region of code or operation + * and should be paired with stop functions for timing of nested + * sequences. + * + * Specifying extra attributes with the name "key" will result in + * multi-part keys. For example a block device and offset pair + * might be used to describe a buf undergoing I/O. + */ +#define KTR_START0(m, egroup, ident, key) \ + KTR_EVENT0(m, egroup, ident, "start:0x%jX", (uintmax_t)key) +#define KTR_START1(m, egroup, ident, key, a0, v0) \ + KTR_EVENT1(m, egroup, ident, "start:0x%jX", (uintmax_t)key, a0, (v0)) +#define KTR_START2(m, egroup, ident, key, a0, v0, a1, v1) \ + KTR_EVENT2(m, egroup, ident, "start:0x%jX", (uintmax_t)key, \ + a0, (v0), a1, (v1)) +#define KTR_START3(m, egroup, ident, key, a0, v0, a1, v1, a2, v2)\ + KTR_EVENT3(m, egroup, ident, "start:0x%jX", (uintmax_t)key, \ + a0, (v0), a1, (v1), a2, (v2)) +#define KTR_START4(m, egroup, ident, key, \ + a0, v0, a1, v1, a2, v2, a3, v3) \ + KTR_EVENT4(m, egroup, ident, "start:0x%jX", (uintmax_t)key, \ + a0, (v0), a1, (v1), a2, (v2), a3, (v3)) + +/* + * Stop functions denote the end of a region of code or operation + * and should be paired with start functions for timing of nested + * sequences. + */ +#define KTR_STOP0(m, egroup, ident, key) \ + KTR_EVENT0(m, egroup, ident, "stop:0x%jX", (uintmax_t)key) +#define KTR_STOP1(m, egroup, ident, key, a0, v0) \ + KTR_EVENT1(m, egroup, ident, "stop:0x%jX", (uintmax_t)key, a0, (v0)) +#define KTR_STOP2(m, egroup, ident, key, a0, v0, a1, v1) \ + KTR_EVENT2(m, egroup, ident, "stop:0x%jX", (uintmax_t)key, \ + a0, (v0), a1, (v1)) +#define KTR_STOP3(m, egroup, ident, key, a0, v0, a1, v1, a2, v2)\ + KTR_EVENT3(m, egroup, ident, "stop:0x%jX", (uintmax_t)key, \ + a0, (v0), a1, (v1), a2, (v2)) +#define KTR_STOP4(m, egroup, ident, \ + key, a0, v0, a1, v1, a2, v2, a3, v3) \ + KTR_EVENT4(m, egroup, ident, "stop:0x%jX", (uintmax_t)key, \ + a0, (v0), a1, (v1), a2, (v2), a3, (v3)) + +/* * Trace initialization events, similar to CTR with KTR_INIT, but * completely ifdef'ed out if KTR_INIT isn't in KTR_COMPILE (to * save string space, the compiler doesn't optimize out strings Modified: head/sys/tools/vnode_if.awk ============================================================================== --- head/sys/tools/vnode_if.awk Wed Dec 19 20:08:06 2012 (r244444) +++ head/sys/tools/vnode_if.awk Wed Dec 19 20:10:00 2012 (r244445) @@ -222,8 +222,6 @@ while ((getline < srcfile) > 0) { name = $1; uname = toupper(name); - # Start constructing a ktrpoint string - ctrstr = "\"" uname; # Get the function arguments. for (numargs = 0; ; ++numargs) { if ((getline < srcfile) <= 0) { @@ -267,27 +265,15 @@ while ((getline < srcfile) > 0) { # remove trailing space (if any) sub(/ $/, ""); types[numargs] = $0; - - # We can do a maximum of 6 arguments to CTR* - if (numargs <= 6) { - if (numargs == 0) - ctrstr = ctrstr "(" args[numargs]; - else - ctrstr = ctrstr ", " args[numargs]; - if (types[numargs] ~ /\*/) - ctrstr = ctrstr " 0x%lX"; - else - ctrstr = ctrstr " %ld"; - } } - if (numargs > 6) - ctrargs = 6; + if (numargs > 4) + ctrargs = 4; else ctrargs = numargs; - ctrstr = "\tCTR" ctrargs "(KTR_VOP,\n\t " ctrstr ")\",\n\t "; - ctrstr = ctrstr "a->a_" args[0]; + ctrstr = ctrargs "(KTR_VOP, \"VOP\", \"" uname "\", a,\n\t "; + ctrstr = ctrstr "\"" args[0] ":0x%jX\", (uintptr_t)a->a_" args[0]; for (i = 1; i < ctrargs; ++i) - ctrstr = ctrstr ", a->a_" args[i]; + ctrstr = ctrstr ", \"" args[i] ":0x%jX\", a->a_" args[i]; ctrstr = ctrstr ");"; if (pfile) { @@ -377,12 +363,12 @@ while ((getline < srcfile) > 0) { printc("\tSDT_PROBE(vfs, vop, " name ", entry, a->a_" args[0] ", a, 0, 0, 0);\n"); for (i = 0; i < numargs; ++i) add_debug_code(name, args[i], "Entry", "\t"); + printc("\tKTR_START" ctrstr); add_pre(name); printc("\tif (vop->"name" != NULL)") printc("\t\trc = vop->"name"(a);") printc("\telse") printc("\t\trc = vop->vop_bypass(&a->a_gen);") - printc(ctrstr); printc("\tSDT_PROBE(vfs, vop, " name ", return, a->a_" args[0] ", a, rc, 0, 0);\n"); printc("\tif (rc == 0) {"); for (i = 0; i < numargs; ++i) @@ -392,6 +378,7 @@ while ((getline < srcfile) > 0) { add_debug_code(name, args[i], "Error", "\t\t"); printc("\t}"); add_post(name); + printc("\tKTR_STOP" ctrstr); printc("\treturn (rc);"); printc("}\n");
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201212192010.qBJKA0lb075959>