From fe07e7c9849530ef9e83f8d70cdeb1ff4acac3be Mon Sep 17 00:00:00 2001 From: Erik van der Kouwe Date: Thu, 24 Jun 2010 13:31:40 +0000 Subject: [PATCH] Optional IPC logging --- kernel/Makefile | 14 +++++++ kernel/debug.c | 87 ++++++++++++++++++++++++++++++++++++++++ kernel/debug.h | 7 ++++ kernel/extract-errno.sh | 12 ++++++ kernel/extract-mfield.sh | 45 +++++++++++++++++++++ kernel/extract-mtype.sh | 17 ++++++++ kernel/proc.c | 13 ++++++ kernel/proto.h | 8 ++++ kernel/system.c | 8 +++- 9 files changed, 210 insertions(+), 1 deletion(-) create mode 100644 kernel/extract-errno.sh create mode 100644 kernel/extract-mfield.sh create mode 100644 kernel/extract-mtype.sh diff --git a/kernel/Makefile b/kernel/Makefile index e624a3ed4..d2e2e0d58 100644 --- a/kernel/Makefile +++ b/kernel/Makefile @@ -32,3 +32,17 @@ MAN= .include "system/Makefile.inc" .include "arch/${ARCH}/Makefile.inc" .include + +debug.d: extracted-errno.h extracted-mfield.h extracted-mtype.h + +extracted-errno.h: extract-errno.sh ../include/errno.h + sh extract-errno.sh > extracted-errno.h + +extracted-mfield.h: extract-mfield.sh ../lib/libc/other/*.c ../lib/libc/posix/*.c ../lib/libsys/*.c + sh extract-mfield.sh > extracted-mfield.h + +extracted-mtype.h: extract-mtype.sh ../include/minix/com.h + sh extract-mtype.sh > extracted-mtype.h + +clean: + rm -f extracted-errno.h extracted-mfield.h extracted-mtype.h diff --git a/kernel/debug.c b/kernel/debug.c index 4199fc2d7..544fcecee 100644 --- a/kernel/debug.c +++ b/kernel/debug.c @@ -7,6 +7,7 @@ #include "proc.h" #include "debug.h" +#include #include #include #include @@ -234,3 +235,89 @@ PUBLIC void print_proc_recursive(struct proc *pp) print_proc_depends(pp, 0); } +#if DEBUG_DUMPIPC +PRIVATE const char *mtypename(int mtype, int iscall) +{ + /* use generated file to recognize message types */ + if (iscall) { + switch(mtype) { +#define IDENT(x) case x: return #x; +#include "extracted-mtype.h" +#undef IDENT( + } + } else { + switch(mtype) { +#define IDENT(x) case x: return #x; +#include "extracted-errno.h" +#undef IDENT( + } + } + + /* no match */ + return NULL; +} + +PRIVATE void printparam(const char *name, const void *data, size_t size) +{ + printf(" %s=", name); + switch (size) { + case sizeof(char): printf("%d", *(char *) data); break; + case sizeof(short): printf("%d", *(short *) data); break; + case sizeof(int): printf("%d", *(int *) data); break; + default: printf("(%u bytes)", size); break; + } +} + +PRIVATE void printproc(struct proc *rp) +{ + if (rp) + printf(" %s(%d)", rp->p_name, rp - proc); + else + printf(" kernel"); +} + +PRIVATE void printmsg(message *msg, struct proc *src, struct proc *dst, + char operation, int iscall, int printparams) +{ + const char *name; + int mtype = msg->m_type; + + /* source, destination and message type */ + printf("%c", operation); + printproc(src); + printproc(dst); + name = mtypename(mtype, iscall); + if (name) { + printf(" %s(%d)", name, mtype); + } else { + printf(" %d", mtype); + } + + if (iscall && printparams) { +#define IDENT(x, y) if (mtype == x) printparam(#y, &msg->y, sizeof(msg->y)); +#include "extracted-mfield.h" +#undef IDENT + } + printf("\n"); +} + +PUBLIC void printmsgkcall(message *msg, struct proc *proc) +{ + printmsg(msg, proc, NULL, 'k', 1, 1); +} + +PUBLIC void printmsgkresult(message *msg, struct proc *proc) +{ + printmsg(msg, NULL, proc, 'k', 0, 0); +} + +PUBLIC void printmsgrecv(message *msg, struct proc *src, struct proc *dst) +{ + printmsg(msg, src, dst, 'r', src->p_misc_flags & MF_REPLY_PEND, 0); +} + +PUBLIC void printmsgsend(message *msg, struct proc *src, struct proc *dst) +{ + printmsg(msg, src, dst, 's', src->p_misc_flags & MF_REPLY_PEND, 1); +} +#endif diff --git a/kernel/debug.h b/kernel/debug.h index 78c4b9948..78cce42d3 100644 --- a/kernel/debug.h +++ b/kernel/debug.h @@ -37,6 +37,13 @@ */ #define DEBUG_RACE 0 +/* DEBUG_DUMPIPC dumps all IPC to serial; due to the amount of logging it is + * strongly recommended to set "ctty 0" in the boot monitor and run inside a + * virtual machine if you enable this; on the hardware it would take forever + * just to boot + */ +#define DEBUG_DUMPIPC 0 + #if DEBUG_TRACE #define VF_SCHEDULING (1L << 1) diff --git a/kernel/extract-errno.sh b/kernel/extract-errno.sh new file mode 100644 index 000000000..ff0242fd9 --- /dev/null +++ b/kernel/extract-errno.sh @@ -0,0 +1,12 @@ +#!/bin/sh + +set -e + +# grep message type and errno constants and make them into a .h file +cat ../include/errno.h | \ +tr -s ' \t' ' ' | \ +sed 's/^# /#/' | \ +egrep '^#define [A-Z_][A-Z0-9_]* \( ?_SIGN ?[0-9]+ ?\)' | \ +cut -d' ' -f2 | \ +sed 's/\(.*\)/IDENT(\1)/' | \ +sort diff --git a/kernel/extract-mfield.sh b/kernel/extract-mfield.sh new file mode 100644 index 000000000..14c608294 --- /dev/null +++ b/kernel/extract-mfield.sh @@ -0,0 +1,45 @@ +#!/bin/sh + +set -e + +find_files_and_lines() +( + find ../lib/libc/other ../lib/libc/posix ../lib/libsys -name '*.c' | \ + xargs egrep -n '((_syscall|_taskcall)\([^,][^,]*,[ ]*|_kernel_call\()[A-Z_][A-Z0-9_]*,[ ]*&m\)' | \ + cut -d: -f1,2 +) + +# grep message fields +( + # find references to _syscall, _taskcall and _kernel_call in the libraries + pathprev= + linecallprev=0 + for f in `find_files_and_lines` + do + path="`echo $f | cut -d: -f1`" + linecall="`echo $f | cut -d: -f2`" + + # find the matching message declaration; we can identify fields between message decl and call + linemsg=`head -n "$linecall" "$path" | egrep -n 'message[ ][ ]*m;' | tail -n 1 | cut -d: -f1` + if [ "x$linemsg" != "x" ] + then + # watch out: message may be re-used; start from last call in this case + [ \( "x$path" != "x$pathprev" \) -o \( "$linemsg" -gt "$linecallprev" \) ] || linemsg="$linecallprev" + + # extract call name + callname=`head -n "$linecall" "$path" | tail -n 1 | sed 's/.*[ (,]\([A-Z_][A-Z0-9_]*\),[ ]*&m).*/\1/'` + + # extract message fields + linelast="`expr "$linecall" - 1`" + linecount="`expr "$linelast" - "$linemsg"`" + + head -n "$linelast" "$path" | \ + tail -n "$linecount" | \ + tr ' \t' ' ' | \ + egrep '^ *m\.[A-Za-z_][A-Za-z0-9_]* *=' | \ + sed 's/^ *m\.\([A-Za-z_][A-Za-z0-9_]*\) *=.*/IDENT('$callname', \1)/' + fi + pathprev="$path" + linemsgprev="$linemsg" + done +) | sort | uniq diff --git a/kernel/extract-mtype.sh b/kernel/extract-mtype.sh new file mode 100644 index 000000000..3322ad83c --- /dev/null +++ b/kernel/extract-mtype.sh @@ -0,0 +1,17 @@ +#!/bin/sh + +set -e + +# grep message type constants and make them into a .h file +( + cat ../include/minix/callnr.h | \ + tr -s ' \t' ' ' | \ + sed 's/^# /#/' | \ + egrep '^#define [A-Z_][A-Z0-9_]* [0-9]+' | grep -v NCALLS + + cat ../include/minix/com.h | \ + tr -s ' \t' ' ' | \ + sed 's/^# /#/' | \ + egrep '^#define [A-Z_][A-Z0-9_]* \( ?([A-Z0-9_]+_BASE|KERNEL_CALL) ?\+[A-Za-z0-9_ +]+\)' + +) | cut -d' ' -f2 | sed 's/\(.*\)/IDENT(\1)/' | sort diff --git a/kernel/proc.c b/kernel/proc.c index 4807f1dc2..64272f6d6 100644 --- a/kernel/proc.c +++ b/kernel/proc.c @@ -560,6 +560,11 @@ PUBLIC int mini_send( : (flags & NON_BLOCKING ? SENDNB : SEND)); IPC_STATUS_ADD_CALL(dst_ptr, call); RTS_UNSET(dst_ptr, RTS_RECEIVING); + +#if DEBUG_DUMPIPC + printmsgsend(&dst_ptr->p_delivermsg, caller_ptr, dst_ptr); + printmsgrecv(&dst_ptr->p_delivermsg, caller_ptr, dst_ptr); +#endif } else { if(flags & NON_BLOCKING) { return(ENOTREADY); @@ -592,6 +597,10 @@ PUBLIC int mini_send( xpp = &dst_ptr->p_caller_q; /* find end of list */ while (*xpp) xpp = &(*xpp)->p_q_link; *xpp = caller_ptr; /* add caller to end */ + +#if DEBUG_DUMPIPC + printmsgsend(&caller_ptr->p_sendmsg, caller_ptr, dst_ptr); +#endif } return(OK); } @@ -718,6 +727,10 @@ PRIVATE int mini_receive(struct proc * caller_ptr, if (sender->p_misc_flags & MF_SIG_DELAY) sig_delay_done(sender); +#if DEBUG_DUMPIPC + printmsgrecv(&caller_ptr->p_delivermsg, *xpp, caller_ptr); +#endif + *xpp = sender->p_q_link; /* remove from queue */ sender->p_q_link = NULL; return(OK); /* report success */ diff --git a/kernel/proto.h b/kernel/proto.h index b727eab22..cdb462f26 100644 --- a/kernel/proto.h +++ b/kernel/proto.h @@ -101,6 +101,14 @@ _PROTOTYPE( char *schedulerstr, (struct proc *scheduler) ); _PROTOTYPE( void print_proc, (struct proc *pp)); /* prints the given process and recursively all processes it depends on */ _PROTOTYPE( void print_proc_recursive, (struct proc *pp)); +#if DEBUG_DUMPIPC +_PROTOTYPE( void printmsgrecv, (message *msg, struct proc *src, + struct proc *dst) ); +_PROTOTYPE( void printmsgsend, (message *msg, struct proc *src, + struct proc *dst) ); +_PROTOTYPE( void printmsgkcall, (message *msg, struct proc *proc) ); +_PROTOTYPE( void printmsgkresult, (message *msg, struct proc *proc) ); +#endif /* system/do_safemap.c */ _PROTOTYPE( int map_invoke_vm, (struct proc * caller, int req_type, diff --git a/kernel/system.c b/kernel/system.c index f41b4e903..ac89638cd 100644 --- a/kernel/system.c +++ b/kernel/system.c @@ -76,6 +76,9 @@ PRIVATE void kernel_call_finish(struct proc * caller, message *msg, int result) /* copy the result as a message to the original user buffer */ msg->m_source = SYSTEM; msg->m_type = result; /* report status of call */ +#if DEBUG_DUMPIPC + printmsgkresult(msg, caller); +#endif if (copy_msg_to_user(caller, msg, (message *)caller->p_delivermsg_vir)) { printf("WARNING wrong user pointer 0x%08x from " @@ -92,7 +95,10 @@ PRIVATE int kernel_call_dispatch(struct proc * caller, message *msg) { int result = OK; int call_nr; - + +#if DEBUG_DUMPIPC + printmsgkcall(msg, caller); +#endif call_nr = msg->m_type - KERNEL_CALL; /* See if the caller made a valid request and try to handle it. */