SEO

this diff adds a high speed buffer for "kernel" ktrace, and uses it to see
what the scheduler is up to.

Index: kern/kern_ktrace.c
================================================== =================
RCS file: /home/tedu/cvs/src/sys/kern/kern_ktrace.c,v
retrieving revision 1.42
diff -u -u -r1.42 kern_ktrace.c
--- kern/kern_ktrace.c 16 May 2007 17:27:30 -0000 1.42
+++ kern/kern_ktrace.c 27 Nov 2007 15:22:27 -0000
@@ -45,6 +45,7 @@
#include <sys/malloc.h>
#include <sys/syslog.h>
#include <sys/sysctl.h>
+#include <sys/workq.h>

#include <sys/mount.h>
#include <sys/syscall.h>
@@ -59,6 +60,113 @@
int ktrwrite(struct proc *, struct ktr_header *);
int ktrcanset(struct proc *, struct proc *);

+
+/*
+ * special fast ring for kernel events
+ */
+int ktrkern_active;
+struct ktrkern_event *ktrkern_buf, *ktrkern_buf_start, *ktrkern_buf_end;
+int ktrkern_flushing;
+int ktrkern_bufsize = 32768;
+struct mutex ktrkern_mtx;
+struct vnode *ktrkern_vp;
+void ktrkern_flush(void);
+
+void
+ktrkern_log(struct proc *p, int event, unsigned long data)
+{
+ struct ktrkern_event *kev;
+
+ mtx_enter(&ktrkern_mtx);
+ if (ktrkern_active && ktrkern_buf < ktrkern_buf_end) {
+ kev = ktrkern_buf++;
+ ktrinitheader(&kev->ktr_head, p ? p : &proc0, KTR_KERN);
+ kev->ktr_event = event;
+ kev->ktr_data = data;
+ /* start flushing at half way full */
+ if (ktrkern_buf_end - ktrkern_buf < ktrkern_bufsize / 2 &&
+ !ktrkern_flushing) {
+ workq_add_task(NULL, 0, (workq_fn)ktrkern_flush,
+ NULL, NULL);
+ }
+ }
+ mtx_leave(&ktrkern_mtx);
+}
+
+void
+ktrkern_flush(void)
+{
+ struct vnode *vp = ktrkern_vp;
+ struct proc *p = curproc;
+ struct ktrkern_event *start, *end, *realend;
+ struct uio auio;
+ struct iovec aiov[2];
+ int error;
+ int len;
+
+ if (vp == NULL)
+ return;
+
+ /* first copy out the front half */
+ mtx_enter(&ktrkern_mtx);
+ start = ktrkern_buf_start;
+ end = ktrkern_buf;
+ realend = ktrkern_buf_end;
+ mtx_leave(&ktrkern_mtx);
+
+ len = (char *)end - (char *)start;
+ auio.uio_iov = &aiov[0];
+ auio.uio_offset = 0;
+ auio.uio_segflg = UIO_SYSSPACE;
+ auio.uio_rw = UIO_WRITE;
+ aiov[0].iov_base = start;
+ aiov[0].iov_len = len;
+ auio.uio_resid = len;
+ auio.uio_iovcnt = 1;
+ auio.uio_procp = p;
+ vn_lock(vp, LK_EXCLUSIVE | LK_RETRY, p);
+ error = VOP_WRITE(vp, &auio, IO_UNIT|IO_APPEND, p->p_ucred);
+ if (!error) {
+ /*
+ * now write out what we missed. we swizzle pointers around
+ * so that the buffer can (almost) always be used,
+ * without danger of corruption.
+ * the just written part above can now be reused.
+ */
+ mtx_enter(&ktrkern_mtx);
+ start = end;
+ end = ktrkern_buf;
+ ktrkern_buf = ktrkern_buf_start;
+ ktrkern_buf_end = start - 1;
+ mtx_leave(&ktrkern_mtx);
+
+ len = (char *)end - (char *)start;
+ auio.uio_iov = &aiov[0];
+ auio.uio_offset = 0;
+ auio.uio_segflg = UIO_SYSSPACE;
+ auio.uio_rw = UIO_WRITE;
+ aiov[0].iov_base = start;
+ aiov[0].iov_len = len;
+ auio.uio_resid = len;
+ auio.uio_iovcnt = 1;
+ auio.uio_procp = p;
+ error = VOP_WRITE(vp, &auio, IO_UNIT|IO_APPEND, p->p_ucred);
+ }
+
+ /* now make the whole buffer available again */
+ mtx_enter(&ktrkern_mtx);
+ ktrkern_buf_end = realend;
+ ktrkern_flushing = 0;
+ mtx_leave(&ktrkern_mtx);
+
+ if (error) {
+ vrele(vp);
+ ktrkern_vp = NULL;
+ }
+ VOP_UNLOCK(vp, 0, p);
+}
+
+
/*
* Change the trace vnode in a correct way (to avoid races).
*/
@@ -296,10 +404,11 @@
int descend = SCARG(uap, ops) & KTRFLAG_DESCEND;
int ret = 0;
int error = 0;
+ int flushing;
struct nameidata nd;

curp->p_traceflag |= KTRFAC_ACTIVE;
- if (ops != KTROP_CLEAR) {
+ if (ops != KTROP_CLEAR && ops != KTROP_KERNCLEAR) {
/*
* an operation which requires a file argument.
*/
@@ -332,7 +441,36 @@
}
}
goto done;
+ } else if (ops == KTROP_KERNCLEAR) {
+ if (ktrkern_vp) {
+ mtx_enter(&ktrkern_mtx);
+ flushing == ktrkern_flushing++;
+ ktrkern_active = 0;
+ mtx_leave(&ktrkern_mtx);
+
+ /* flushing will not happen above if it's not active */
+ if (!flushing)
+ ktrkern_flush();
+ vrele(ktrkern_vp);
+ ktrkern_vp = 0;
+ }
+ } else if (ops == KTROP_KERN) {
+ if (ktrkern_vp) {
+ error = EBUSY;
+ goto done;
+ }
+ VREF(vp);
+ ktrkern_vp = vp;
+ if (!ktrkern_buf_start) {
+ ktrkern_buf_start = malloc(ktrkern_bufsize * sizeof(*ktrkern_buf),
+ M_TEMP, M_WAITOK);
+ }
+ ktrkern_buf = ktrkern_buf_start;
+ ktrkern_buf_end = ktrkern_buf_start + ktrkern_bufsize - 1;
+ ktrkern_active = 1;
+ goto done;
}
+
/*
* need something to (un)trace (XXX - why is this here?)
*/
@@ -512,5 +650,6 @@

return (0);
}
+

#endif
Index: kern/kern_sched.c
================================================== =================
RCS file: /home/tedu/cvs/src/sys/kern/kern_sched.c,v
retrieving revision 1.2
diff -u -u -r1.2 kern_sched.c
--- kern/kern_sched.c 26 Nov 2007 17:15:29 -0000 1.2
+++ kern/kern_sched.c 27 Nov 2007 16:55:45 -0000
@@ -23,6 +23,7 @@
#include <sys/systm.h>
#include <sys/resourcevar.h>
#include <sys/signalvar.h>
+#include <sys/ktrace.h>
#include <sys/mutex.h>

#include <uvm/uvm_extern.h>
@@ -152,6 +153,10 @@

SCHED_LOCK(s);
idle = spc->spc_idleproc;
+ if (ktrkern_active) {
+ ktrkern_log(p, 0, cpu_number());
+ ktrkern_log(idle, 1, cpu_number());
+ }
idle->p_stat = SRUN;
cpu_switchto(NULL, idle);
}
Index: kern/sched_bsd.c
================================================== =================
RCS file: /home/tedu/cvs/src/sys/kern/sched_bsd.c,v
retrieving revision 1.15
diff -u -u -r1.15 sched_bsd.c
--- kern/sched_bsd.c 26 Nov 2007 17:15:29 -0000 1.15
+++ kern/sched_bsd.c 27 Nov 2007 16:55:45 -0000
@@ -412,6 +412,10 @@

if (p != nextproc) {
uvmexp.swtch++;
+ if (ktrkern_active) {
+ ktrkern_log(p, 0, cpu_number());
+ ktrkern_log(nextproc, 1, cpu_number());
+ }
cpu_switchto(p, nextproc);
} else {
p->p_stat = SONPROC;
Index: sys/ktrace.h
================================================== =================
RCS file: /home/tedu/cvs/src/sys/sys/ktrace.h,v
retrieving revision 1.9
diff -u -u -r1.9 ktrace.h
--- sys/ktrace.h 17 May 2006 02:11:25 -0000 1.9
+++ sys/ktrace.h 28 Nov 2007 10:37:10 -0000
@@ -38,11 +38,13 @@
#define KTROP_SET 0 /* set trace points */
#define KTROP_CLEAR 1 /* clear trace points */
#define KTROP_CLEARFILE 2 /* stop all tracing to file */
-#define KTROP(o) ((o)&3) /* macro to extract operation */
+#define KTROP_KERN 3
+#define KTROP_KERNCLEAR 4
+#define KTROP(o) ((o)&0xff) /* macro to extract operation */
/*
* flags (ORed in with operation)
*/
-#define KTRFLAG_DESCEND 4 /* perform op on all children too */
+#define KTRFLAG_DESCEND 0x100 /* perform op on all children too */

/*
* ktrace record header
@@ -56,6 +58,14 @@
caddr_t ktr_buf;
};

+/* builtin header */
+struct ktrkern_event {
+ struct ktr_header ktr_head;
+ int ktr_event;
+ long ktr_data;
+};
+
+
/*
* Test for kernel trace point
*/
@@ -134,6 +144,8 @@
#define KTR_EMUL 7
/* record contains emulation name */

+#define KTR_KERN 8
+

/*
* kernel trace points (in p_traceflag)
@@ -146,6 +158,7 @@
#define KTRFAC_PSIG (1<<KTR_PSIG)
#define KTRFAC_CSW (1<<KTR_CSW)
#define KTRFAC_EMUL (1<<KTR_EMUL)
+#define KTRFAC_KERN (1<<KTR_KERN)
/*
* trace flags (also in p_traceflags)
*/
@@ -170,6 +183,9 @@
void ktrpsig(struct proc *, int, sig_t, int, int, siginfo_t *);
void ktrsyscall(struct proc *, register_t, size_t, register_t []);
void ktrsysret(struct proc *, register_t, int, register_t);
+
+extern int ktrkern_active;
+void ktrkern_log(struct proc *, int, unsigned long);

void ktrsettracevnode(struct proc *, struct vnode *);