- 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

3 files changed, 59 insertions, 30 deletions

diff --git a/sys/kern/subr_syscall.c b/sys/kern/subr_syscall.c
index fe5cd0e..3dcfcf5 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 c440a41..28442e2 100644
--- a/sys/sys/ktr.h
+++ b/sys/sys/ktr.h
@@ -244,6 +244,50 @@ void	ktr_tracepoint(u_int mask, const char *file, int line,
 	    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
diff --git a/sys/tools/vnode_if.awk b/sys/tools/vnode_if.awk
index 5e194a8..fc12ce9 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");