A question about how to get trace record generated by KERNEL_DEBUG(...).

6 Sep 2011

      site_archiver@lists.apple.com
Delivered-To: darwin-kernel@lists.apple.com
Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=gamma; h=mime-version:date:message-id:subject:from:to:cc:content-type; bh=lBuYPgMNZfKR7zLsLHJxvKAjHVYNxPaUhL3yYhjfZDE=; b=IK+n0BlFK07aXdQ+/4XgtgBj1T7etmDfsPlcLIUT3/tC/4L5cP+3aF2I4eOyj77aip 3Y23Y1GnaDEOv3Pd9ikjIWfhfWd5q062qYRsatejNnh9gxXJKnOuj7wDuLIdODC5+FSR ShGtWu90AkdAQptGDPJ3HeF1kTJhK8QwxW/Og=

Hello, everyone.

I am a beginner of darwin kernel dev. I have a question and ask for
help. I found there are many kernel debug information generated by
KERNEL_DEBUG(...). For example, I want to trace the detailed info
about how NFS running, so those information are important to me. trace
record is identified by its debugid, which is a structured 32bit
object. in NFS, class is 0x03(DBG_FSYSTEM), subclass is
0x01(DBG_FSRW), code is defined in respective kernel functions. for
example, nfs_vnop_write() defines its code is 515 (0x0203). so, trace
record of nfs_vnop_write() is identified by the debugid 0x03010203.

I wrote a demo program, for fetching those trace record from kernel
via sysctl(3), but It doesn't work, no trace record with debugid
matched 0x0301XXXX. :-(

the program is listed below. please correct me if you found issues.
Thanks a lot.  BTW, uname -a shows me "Darwin bogon 10.7.0 Darwin
Kernel Version 10.7.0".

/* gcc xx.c -o xx -I/Users/myself/mysourcecode/xnu-1504.15.3/bsd/sys/ */
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/uio.h>
#include <sys/types.h>
#include <sys/sysctl.h>
#include <sys/ptrace.h>
#include <sys/syscall.h>
#include <syslog.h>
#include <errno.h>
#include <getopt.h>
#include <libgen.h>
#include <signal.h>

#define PRIVATE
#define KERNEL_PRIVATE
#include "kdebug.h"
#undef KERNEL_PRIVATE
#undef PRIVATE

int trace_enabled = 0;
int set_remove_flag = 1;
int exiting = 0;
int pid = -1;
int miblen = CTL_MAXNAME;
int *mib = NULL;
char *progname = NULL;	/* program name */
size_t oldlen = 0;

static void ukdbg_exit_handler(int);
static void ukdbg_exit(int, const char *);
static void ukdbg_setenable(int);
static void ukdbg_clear();
static void ukdbg_reinit();
static void ukdbg_setbuf(int);
static void ukdbg_getbuf(kbufinfo_t *);
static void ukdbg_setpidcheck(pid_t, int);
static void ukdbg_read(char *, size_t *);
static void ukdbg_setreg_valcheck(int val1, int val2, int val3, int val4);
static void ukdbg_entropy();

const unsigned int KDBG_FUNC_MASK = 0xfffffffc;
const unsigned int KDBG_CLASS_MASK = 0xff000000;
const unsigned int KDBG_CLASS_SHIFT = 24;

/* FSDBG code in NFS. Must be in order!! */
int CODE[] = {
	260, 263, 264, 266, 267, 269,
	273, 274, 275,
	320, 321, 322, 323, 324, 325,
	512, 513, 514, 515, 516, 518,
	521, 524, 525, 526, 527, 528, 529,
	530, 531, 532, 535, 536, 537, 538, 539,
	540, 544, 545, 547, 548,
	551, 554, 556, 557,
};

/* is a code interested? */
#define is_interest_code(c) \
	({\
	 	int i, j, n, ret=0;\
	 	i = 0; j = sizeof(CODE)/sizeof(CODE[0])-1;\
	 	while (i <= j) {\
	 		n = i + (j-i+1)/2;\
	 		if (CODE[n] > (c)) {\
	 			j = n-1;\
	 		} else if (CODE[n] < (c)) {\
	 			i = n+1;\
	 		} else {\
	 			ret = 1;\
	 			break;\
	 		}\
	 	}\
	 	ret;\
	})

int main(int argc, char *argv[])
{
	char *progname = basename(argv[0]);
	int err = 0;
	int code = 0;
	FILE *fp = stdout;
	unsigned int elem = 65536;
	size_t buflen = 0;
	char *buf = NULL;
	kd_buf *kd = NULL;
	kbufinfo_t bufinfo = { 0, 0, 0, 0 };
	int i, count;
	long long sample_interval = 1000;	/* us */

	if (argc > 1)
		pid = atoi(argv[1]);

	mib = (int *)malloc(sizeof(int)*miblen);
	if (NULL == mib) {
		err = ENOMEM;
		goto out;
	}
	memset(mib, 0, sizeof(int)*miblen);

	signal(SIGHUP, ukdbg_exit_handler);
	signal(SIGINT, ukdbg_exit_handler);
	signal(SIGQUIT, ukdbg_exit_handler);
	signal(SIGTERM, ukdbg_exit_handler);

	buflen = elem * sizeof(kd_buf);
	buf = (char *)malloc(buflen);
	if (NULL == buf) {
		err = ENOMEM;
		goto out;
	}

	ukdbg_clear();
	ukdbg_setbuf(elem);
	ukdbg_reinit();
	if (pid > 0)
		ukdbg_setpidcheck(pid, 1);
	for (i=0; i < sizeof(CODE)/sizeof(CODE[0]); i++) {
		int c = FSDBG_CODE(DBG_FSRW, CODE[i]);
		//ukdbg_setreg_valcheck(c, 0 , 0, 0);
	}
	ukdbg_setenable(1);

	while (1) {
		ukdbg_getbuf(&bufinfo);                    // Query information
		oldlen = bufinfo.nkdbufs * sizeof(kd_buf); // How much to read?
		ukdbg_read(buf, &oldlen);        // Read that much
		count = oldlen;

		kd = (kd_buf *)buf;
		for (i = 0; i < count; i++) {
			char *qual = "";
			unsigned long long  cpu=0, now=0;
			long thread;
			int debugid, type, class;

			thread = kd[i].arg5;
			debugid = kd[i].debugid;
			type = debugid & KDBG_FUNC_MASK;
			class = (debugid & KDBG_CLASS_MASK) >> KDBG_CLASS_SHIFT;
			//now = kd[i].timestamp & KDBG_TIMESTAMP_MASK;
			//cpu = (kd[i].timestamp & KDBG_CPU_MASK) >> KDBG_CPU_SHIFT;
			if (debugid <= 0)
				continue;
			//printf("%08x\n", debugid);
			if (class != DBG_FSYSTEM)
				continue;

			if (debugid & DBG_FUNC_START)
				qual = "DBG_FUNC_START";
			else if (debugid & DBG_FUNC_END)
				qual = "DBG_FUNC_END";

			code = (debugid & 0xffff) >> 2;
			//if (!is_interest_code(code)) {
			//	fprintf(stdout, ":-(\n");
			//	continue;
			//}

			fprintf(fp, "%016Lx; %08lx; %08lx; %08lx; %08lx;"\
				" %08lx; %08x.\n", kd[i].timestamp, \
				(kd[i].arg1), (kd[i].arg2), (kd[i].arg3),\
				(kd[i].arg4), (kd[i].arg5), kd[i].debugid);
		}

		usleep(sample_interval);
	}

out:
	if (buf)
		free(buf);
	if (mib)
		free(mib);

	fprintf(((0==err)? stdout:stderr), "'%s': exit(%d).\n",
		progname, err);
	exit(err);
}

void ukdbg_exit_handler(int s)
{
	exiting = 1;

	if (trace_enabled)
		ukdbg_setenable(0);

	if (pid > 0)
		ukdbg_setpidcheck(pid, 0);

	if (set_remove_flag)
		ukdbg_clear();

	fprintf(stderr, "cleaning up...\n");
	exit(s);
}

void ukdbg_exit(int err, const char *msg)
{
	fprintf(stderr, "%d: ", err);
	if (msg)
		perror(msg);
	else
		fprintf(stderr, "\n");

	ukdbg_exit_handler(0);
}

void ukdbg_setenable(int enable)
{
	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDENABLE;
	mib[3] = enable;

	if ((sysctl(mib, 4, NULL, &oldlen, NULL, 0) < 0) && !exiting)
		ukdbg_exit(errno, "ukdbg_setenable::sysctl");

	trace_enabled = enable;
}

void ukdbg_clear(void)
{
	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDREMOVE;

	if ((sysctl(mib, 3, NULL, &oldlen, NULL, 0) < 0) && !exiting) {
		set_remove_flag = 0;
		ukdbg_exit(errno, "ukdbg_clear::sysctl");
	}
}

void ukdbg_reinit(void)
{
	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDSETUP;

	if (sysctl(mib, 3, NULL, &oldlen, NULL, 0) < 0) {
		ukdbg_exit(errno, "ukdbg_reinit::sysctl");
	}
}

void ukdbg_setbuf(int nbufs)
{
	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDSETBUF;
	mib[3] = nbufs;

	if (sysctl(mib, 4, NULL, &oldlen, NULL, 0) < 0) {
		ukdbg_exit(errno, "ukdbg_setbuf::sysctl");
	}

	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDSETUP;
	mib[3] = 0;
	mib[4] = 0;
	mib[5] = 0;

	if (sysctl(mib, 3, NULL, &oldlen, NULL, 0) < 0) {
		ukdbg_exit(errno, "ukdbg_setbuf2::sysctl");
	}

}

void ukdbg_setpidcheck(pid_t pid, int check)
{
	kd_regtype kr;

	kr.type = KDBG_TYPENONE;
	kr.value1 = pid;
	kr.value2 = check;

	oldlen = sizeof(kd_regtype);

	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDPIDTR;

	if ((sysctl(mib, 3, &kr, &oldlen, NULL, 0) < 0) && !exiting) {
		ukdbg_exit(errno, "ukdbg_setpidcheck::sysctl");
	}
}

void ukdbg_setreg_valcheck(int val1, int val2, int val3, int val4)
{
	kd_regtype kr;

	kr.type = KDBG_VALCHECK;
	kr.value1 = val1;
	kr.value2 = val2;
	kr.value3 = val3;
	kr.value4 = val4;

	oldlen = sizeof(kd_regtype);

	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDSETREG;

	if (sysctl(mib, 3, &kr, &oldlen, NULL, 0) < 0) {
		ukdbg_exit(errno, "ukdbg_setreg_valcheck::sysctl");
	}
}

void ukdbg_getbuf(kbufinfo_t *bufinfop)
{
	oldlen = sizeof(bufinfop);
	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDGETBUF;

	if (sysctl(mib, 3, bufinfop, &oldlen, 0, 0) < 0) {
		ukdbg_exit(errno, "ukdbg_getbuf::sysctl");
	}
}

void ukdbg_read(char *buf, size_t *len)
{
	memset(mib, 0, sizeof(int)*miblen);
	mib[0] = CTL_KERN;
	mib[1] = KERN_KDEBUG;
	mib[2] = KERN_KDREADTR;

	if (sysctl(mib, 3, buf, len, NULL, 0) < 0) {
		ukdbg_exit(errno, "ukdbg_read::sysctl");
	}
}
 _______________________________________________
Do not post admin requests to the list. They will be ignored.
Darwin-kernel mailing list      (Darwin-kernel@lists.apple.com)
Help/Unsubscribe/Update your Subscription:
http://lists.apple.com/mailman/options/darwin-kernel/site_archiver%40lists.a...

This email sent to site_archiver@lists.apple.com

A question about how to get trace record generated by KERNEL_DEBUG(...).

Sid Moore