From 0a985cfcdeb6ea9385d67b191d021ed1b74c3702 Mon Sep 17 00:00:00 2001 From: jeff Date: Wed, 19 Dec 2012 20:10:00 +0000 Subject: [PATCH] - 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 --- sys/kern/subr_syscall.c | 18 ++++++++--------- sys/sys/ktr.h | 44 +++++++++++++++++++++++++++++++++++++++++ sys/tools/vnode_if.awk | 27 +++++++------------------ 3 files changed, 59 insertions(+), 30 deletions(-) diff --git a/sys/kern/subr_syscall.c b/sys/kern/subr_syscall.c index fe5cd0e5e6bb..3dcfcf59e78a 100644 --- a/sys/kern/subr_syscall.c +++ b/sys/kern/subr_syscall.c @@ -77,13 +77,12 @@ syscallenter(struct thread *td, struct syscall_args *sa) 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 syscall_args *sa) 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, struct syscall_args *sa __unused) */ 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 ? diff --git a/sys/sys/ktr.h b/sys/sys/ktr.h index c440a411b671..28442e2abdc1 100644 --- a/sys/sys/ktr.h +++ b/sys/sys/ktr.h @@ -243,6 +243,50 @@ void ktr_tracepoint(u_int mask, const char *file, int line, KTR_EVENT4(m, egroup, ident, "point:\"%s\"", \ 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 diff --git a/sys/tools/vnode_if.awk b/sys/tools/vnode_if.awk index 5e194a89b5a1..fc12ce99cb31 100644 --- a/sys/tools/vnode_if.awk +++ b/sys/tools/vnode_if.awk @@ -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");