From 679d7c25a607ee15d1a502b13281a2f83e28a7e6 Mon Sep 17 00:00:00 2001 From: mrg Date: Thu, 29 Oct 2015 00:27:08 +0000 Subject: [PATCH] introduce a new way of handling SYSCALL_DEBUG messages -- send them to a kernel history, settable via the SCDEBUG_KERNHIST flag. this requires a fairly significantly different set of messages than the normal debug as histories are restricted: - each message can take one literal format string and upto 4 arguments - the arguments can not be strings if you want vmstat -u to work (this could be fixed, and i might, as it would be nice if we could print syscall names as well as numbers.) introduce SCDEBUG_DEFAULT that is settable in the kernel config. fix a problem in kernhist_dump_histories() where it would crash when a history with no allocated entries was found. extend kernhist_dumpmask() to handle the usbhist and scdebughist. --- share/man/man4/options.4 | 41 ++++++++- sys/kern/init_main.c | 6 +- sys/kern/kern_history.c | 30 ++++++- sys/kern/kern_xxx.c | 179 +++++++++++++++++++++++++++++++++------ sys/sys/kernhist.h | 4 +- sys/sys/systm.h | 3 +- 6 files changed, 224 insertions(+), 39 deletions(-) diff --git a/share/man/man4/options.4 b/share/man/man4/options.4 index bf551f5711d4..295fd96cd73b 100644 --- a/share/man/man4/options.4 +++ b/share/man/man4/options.4 @@ -1,4 +1,4 @@ -.\" $NetBSD: options.4,v 1.449 2015/08/20 11:05:06 wiz Exp $ +.\" $NetBSD: options.4,v 1.450 2015/10/29 00:27:08 mrg Exp $ .\" .\" Copyright (c) 1996 .\" Perry E. Metzger. All rights reserved. @@ -30,7 +30,7 @@ .\" THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. .\" .\" -.Dd August 20, 2015 +.Dd October 28, 2015 .Dt OPTIONS 4 .Os .Sh NAME @@ -668,7 +668,9 @@ These logs can be displayed by using from DDB. See the kernel source file .Pa sys/kern/kern_history.c -for details. +and the +.Xr kernhist 9 +manual for details. .It Cd options KERNHIST_PRINT Prints the kernel history logs on the system console as entries are added. Note that the output is @@ -1508,6 +1510,36 @@ See for details. .Em NOTE : not available on all architectures. +.It Cd options SCDEBUG_DEFAULT +Used with the +.Cd options SYSCALL_DEBUG +described below to choose which types of events are displayed. +.Pp +.Bl -tag -width "SCDEBUG_KERNHIST" -compact -offset indent +.It Dv SCDEBUG_CALLS +Show system call entry points. +.It Dv SCDEBUG_RETURNS +Show system call exit points. +.It Dv SCDEBUG_ALL +Show all system call requestes, including unimplemented calls. +.It Dv SCDEBUG_SHOWARGS +Show the arguments provided. +.It Dv SCDEBUG_KERNHIST +Store a restricted form of the system call debug in a kernel history +instead of printing it to the console. This option relies upon +.Cd options KERNHIST . +.El +.Pp +The default value is +.Dv (SCDEBUG_CALLS|SCDEBUG_RETURNS|SCDEBUG_SHOWARGS) . +.It Cd options SYSCALL_DEBUG +Useful for debugging system call issues, usually in early single user bringup. +By default, writes entries to the system console for most system call events. +Can be configured with the +.Cd options SCDEBUG_DEFAULT +option to to use the +.Cd options KERNHIST +facility instead. .It Cd options SYSCALL_STATS Count the number of times each system call number is called. The values can be read through the sysctl interface and displayed using @@ -2733,7 +2765,8 @@ bolded .Xr quotaon 8 , .Xr rpc.rquotad 8 , .Xr sysctl 8 , -.Xr in_getifa 9 +.Xr in_getifa 9 , +.Xr kernhist 9 .Sh HISTORY The .Nm diff --git a/sys/kern/init_main.c b/sys/kern/init_main.c index 5dcd46a918f5..d20c196d9c1c 100644 --- a/sys/kern/init_main.c +++ b/sys/kern/init_main.c @@ -1,4 +1,4 @@ -/* $NetBSD: init_main.c,v 1.471 2015/10/17 13:52:52 jmcneill Exp $ */ +/* $NetBSD: init_main.c,v 1.472 2015/10/29 00:27:08 mrg Exp $ */ /*- * Copyright (c) 2008, 2009 The NetBSD Foundation, Inc. @@ -97,7 +97,7 @@ */ #include -__KERNEL_RCSID(0, "$NetBSD: init_main.c,v 1.471 2015/10/17 13:52:52 jmcneill Exp $"); +__KERNEL_RCSID(0, "$NetBSD: init_main.c,v 1.472 2015/10/29 00:27:08 mrg Exp $"); #include "opt_ddb.h" #include "opt_ipsec.h" @@ -601,6 +601,8 @@ main(void) procinit_sysctl(); + scdebug_init(); + /* * Create process 1 (init(8)). We do this now, as Unix has * historically had init be process 1, and changing this would diff --git a/sys/kern/kern_history.c b/sys/kern/kern_history.c index 62a2f7717d73..675288121d8f 100644 --- a/sys/kern/kern_history.c +++ b/sys/kern/kern_history.c @@ -1,4 +1,4 @@ -/* $NetBSD: kern_history.c,v 1.1 2011/05/17 04:18:06 mrg Exp $ */ +/* $NetBSD: kern_history.c,v 1.2 2015/10/29 00:27:08 mrg Exp $ */ /* * Copyright (c) 1997 Charles D. Cranor and Washington University. @@ -33,18 +33,30 @@ */ #include -__KERNEL_RCSID(0, "$NetBSD: kern_history.c,v 1.1 2011/05/17 04:18:06 mrg Exp $"); +__KERNEL_RCSID(0, "$NetBSD: kern_history.c,v 1.2 2015/10/29 00:27:08 mrg Exp $"); #include "opt_kernhist.h" -#include "opt_uvmhist.h" #include "opt_ddb.h" +#include "opt_uvmhist.h" +#include "opt_usb.h" +#include "opt_syscall_debug.h" #include #include #include #include +#ifdef UVMHIST #include +#endif + +#ifdef USB_DEBUG +#include +#endif + +#ifdef SYSCALL_DEBUG +KERNHIST_DECL(scdebughist); +#endif /* * globals @@ -112,6 +124,8 @@ kernhist_dump_histories(struct kern_history *hists[]) restart: if (cur[lcv] == -1) continue; + if (!hists[lcv]->e) + continue; /* * if the format is empty, go to the next entry @@ -174,6 +188,16 @@ kernhist_dumpmask(u_int32_t bitmask) /* XXX only support 32 hists */ hists[i++] = &loanhist; #endif +#ifdef USB_DEBUG + if ((bitmask & KERNHIST_USBHIST) || bitmask == 0) + hists[i++] = &usbhist; +#endif + +#ifdef SYSCALL_DEBUG + if ((bitmask & KERNHIST_SCDEBUGHIST) || bitmask == 0) + hists[i++] = &scdebughist; +#endif + hists[i] = NULL; kernhist_dump_histories(hists); diff --git a/sys/kern/kern_xxx.c b/sys/kern/kern_xxx.c index bd93f69b40fc..290da876949f 100644 --- a/sys/kern/kern_xxx.c +++ b/sys/kern/kern_xxx.c @@ -1,4 +1,4 @@ -/* $NetBSD: kern_xxx.c,v 1.72 2011/09/01 18:25:44 matt Exp $ */ +/* $NetBSD: kern_xxx.c,v 1.73 2015/10/29 00:27:08 mrg Exp $ */ /* * Copyright (c) 1982, 1986, 1989, 1993 @@ -32,10 +32,11 @@ */ #include -__KERNEL_RCSID(0, "$NetBSD: kern_xxx.c,v 1.72 2011/09/01 18:25:44 matt Exp $"); +__KERNEL_RCSID(0, "$NetBSD: kern_xxx.c,v 1.73 2015/10/29 00:27:08 mrg Exp $"); #ifdef _KERNEL_OPT #include "opt_syscall_debug.h" +#include "opt_kernhist.h" #endif #include @@ -49,6 +50,7 @@ __KERNEL_RCSID(0, "$NetBSD: kern_xxx.c,v 1.72 2011/09/01 18:25:44 matt Exp $"); #include #include #include +#include /* ARGSUSED */ int @@ -102,42 +104,134 @@ sys_reboot(struct lwp *l, const struct sys_reboot_args *uap, register_t *retval) #ifdef SYSCALL_DEBUG #define SCDEBUG_CALLS 0x0001 /* show calls */ #define SCDEBUG_RETURNS 0x0002 /* show returns */ -#define SCDEBUG_ALL 0x0004 /* even syscalls that are implemented */ +#define SCDEBUG_ALL 0x0004 /* even syscalls that are not implemented */ #define SCDEBUG_SHOWARGS 0x0008 /* show arguments to calls */ +#define SCDEBUG_KERNHIST 0x0010 /* use kernhist instead of printf */ -#if 0 -int scdebug = SCDEBUG_CALLS|SCDEBUG_RETURNS|SCDEBUG_SHOWARGS; +#ifndef SCDEBUG_DEFAULT +#define SCDEBUG_DEFAULT (SCDEBUG_CALLS|SCDEBUG_RETURNS|SCDEBUG_SHOWARGS) +#endif + +int scdebug = SCDEBUG_DEFAULT; + +#ifdef KERNHIST +KERNHIST_DEFINE(scdebughist); +#define SCDEBUG_KERNHIST_FUNC(a) KERNHIST_FUNC(a) +#define SCDEBUG_KERNHIST_CALLED(a) KERNHIST_CALLED(a) +#define SCDEBUG_KERNHIST_LOG(a,b,c,d,e,f) KERNHIST_LOG(a,b,c,d,e,f) #else -int scdebug = SCDEBUG_CALLS|SCDEBUG_RETURNS|SCDEBUG_SHOWARGS|SCDEBUG_ALL; +#define SCDEBUG_KERNHIST_FUNC(a) /* nothing */ +#define SCDEBUG_KERNHIST_CALLED(a) /* nothing */ +#define SCDEBUG_KERNHIST_LOG(a,b,c,d,e,f) /* nothing */ +/* The non-kernhist support version can elide all this code easily. */ +#undef SCDEBUG_KERNHIST +#define SCDEBUG_KERNHIST 0 +#endif + +#ifdef __HAVE_MINIMAL_EMUL +#define CODE_NOT_OK(code, em) ((int)(code) < 0) +#else +#define CODE_NOT_OK(code, em) (((int)(code) < 0) || \ + ((int)(code) >= (em)->e_nsysent)) #endif void scdebug_call(register_t code, const register_t args[]) { + SCDEBUG_KERNHIST_FUNC("scdebug_call"); struct lwp *l = curlwp; struct proc *p = l->l_proc; const struct sysent *sy; const struct emul *em; int i; - if (!(scdebug & SCDEBUG_CALLS)) + if ((scdebug & SCDEBUG_CALLS) == 0) return; + if (scdebug & SCDEBUG_KERNHIST) + SCDEBUG_KERNHIST_CALLED(scdebughist); + em = p->p_emul; sy = &em->e_sysent[code]; - if (!(scdebug & SCDEBUG_ALL || (int)code < 0 -#ifndef __HAVE_MINIMAL_EMUL - || code >= em->e_nsysent -#endif - || sy->sy_call == sys_nosys)) + + if ((scdebug & SCDEBUG_ALL) == 0 && + (CODE_NOT_OK(code, em) || sy->sy_call == sys_nosys)) { + if (scdebug & SCDEBUG_KERNHIST) + SCDEBUG_KERNHIST_LOG(scdebughist, "", 0, 0, 0, 0); return; + } + + /* + * The kernhist version of scdebug needs to restrict the usage + * compared to the normal version. histories must avoid these + * sorts of usage: + * + * - the format string *must* be literal, as it is used + * at display time in the kernel or userland + * - strings in the format will cause vmstat -u to crash + * so avoid using %s formats + * + * to avoid these, we have a fairly long block to print args + * as the format needs to change for each, and we can't just + * call printf() on each argument until we're done. + */ + if (scdebug & SCDEBUG_KERNHIST) { + if (CODE_NOT_OK(code, em)) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "pid %d:%d: OUT OF RANGE (%ld)", + p->p_pid, l->l_lid, code, 0); + } else { + SCDEBUG_KERNHIST_LOG(scdebughist, + "pid %d:%d: num %d call %p", + p->p_pid, l->l_lid, code, sy->sy_call); + if ((scdebug & SCDEBUG_SHOWARGS) == 0) + return; + + if (sy->sy_narg > 7) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[4-7]: (%lx, %lx, %lx, %lx, ...)", + (long)args[4], (long)args[5], + (long)args[6], (long)args[7]); + } else if (sy->sy_narg > 6) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[4-6]: (%lx, %lx, %lx)", + (long)args[4], (long)args[5], + (long)args[6], 0); + } else if (sy->sy_narg > 5) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[4-5]: (%lx, %lx)", + (long)args[4], (long)args[5], 0, 0); + } else if (sy->sy_narg == 5) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[4]: (%lx)", + (long)args[4], 0, 0, 0); + } + + if (sy->sy_narg > 3) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[0-3]: (%lx, %lx, %lx, %lx, ...)", + (long)args[0], (long)args[1], + (long)args[2], (long)args[3]); + } else if (sy->sy_narg > 2) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[0-2]: (%lx, %lx, %lx)", + (long)args[0], (long)args[1], + (long)args[2], 0); + } else if (sy->sy_narg > 1) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[0-1]: (%lx, %lx)", + (long)args[0], (long)args[1], 0, 0); + } else if (sy->sy_narg == 1) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "args[0]: (%lx)", + (long)args[0], 0, 0, 0); + } + } + return; + } printf("proc %d (%s): %s num ", p->p_pid, p->p_comm, em->e_name); - if ((int)code < 0 -#ifndef __HAVE_MINIMAL_EMUL - || code >= em->e_nsysent -#endif - ) + if (CODE_NOT_OK(code, em)) printf("OUT OF RANGE (%ld)", (long)code); else { printf("%ld call: %s", (long)code, em->e_syscallnames[code]); @@ -155,29 +249,45 @@ scdebug_call(register_t code, const register_t args[]) void scdebug_ret(register_t code, int error, const register_t retval[]) { + SCDEBUG_KERNHIST_FUNC("scdebug_ret"); struct lwp *l = curlwp; struct proc *p = l->l_proc; const struct sysent *sy; const struct emul *em; - if (!(scdebug & SCDEBUG_RETURNS)) + if ((scdebug & SCDEBUG_RETURNS) == 0) return; + if (scdebug & SCDEBUG_KERNHIST) + SCDEBUG_KERNHIST_CALLED(scdebughist); + em = p->p_emul; sy = &em->e_sysent[code]; - if (!(scdebug & SCDEBUG_ALL || (int)code < 0 -#ifndef __HAVE_MINIMAL_EMUL - || (int)code >= em->e_nsysent -#endif - || sy->sy_call == sys_nosys)) + if ((scdebug & SCDEBUG_ALL) == 0 && + (CODE_NOT_OK(code, em) || sy->sy_call == sys_nosys)) { + if (scdebug & SCDEBUG_KERNHIST) + SCDEBUG_KERNHIST_LOG(scdebughist, "", 0, 0, 0, 0); return; + } + + if (scdebug & SCDEBUG_KERNHIST) { + if (CODE_NOT_OK(code, em)) { + SCDEBUG_KERNHIST_LOG(scdebughist, + "pid %d:%d: OUT OF RANGE (%ld)", + p->p_pid, l->l_lid, code, 0); + } else { + SCDEBUG_KERNHIST_LOG(scdebughist, + "pid %d:%d: num %ld", + p->p_pid, l->l_lid, code, 0); + SCDEBUG_KERNHIST_LOG(scdebughist, + "ret: err = %d, rv = 0x%lx,0x%lx", + error, (long)retval[0], (long)retval[1], 0); + } + return; + } printf("proc %d (%s): %s num ", p->p_pid, p->p_comm, em->e_name); - if ((int)code < 0 -#ifndef __HAVE_MINIMAL_EMUL - || code >= em->e_nsysent -#endif - ) + if (CODE_NOT_OK(code, em)) printf("OUT OF RANGE (%ld)", (long)code); else printf("%ld ret %s: err = %d, rv = 0x%lx,0x%lx", (long)code, @@ -186,3 +296,16 @@ scdebug_ret(register_t code, int error, const register_t retval[]) printf("\n"); } #endif /* SYSCALL_DEBUG */ + +#ifndef SCDEBUG_KERNHIST_SIZE +#define SCDEBUG_KERNHIST_SIZE 500 +#endif + +void +scdebug_init(void) +{ +#if defined(SYSCALL_DEBUG) && defined(KERNHIST) + /* Setup scdebughist kernel history */ + KERNHIST_INIT(scdebughist, SCDEBUG_KERNHIST_SIZE); +#endif +} diff --git a/sys/sys/kernhist.h b/sys/sys/kernhist.h index d14b7e7bb5c3..090a281a7887 100644 --- a/sys/sys/kernhist.h +++ b/sys/sys/kernhist.h @@ -1,4 +1,4 @@ -/* $NetBSD: kernhist.h,v 1.9 2014/03/30 15:53:37 matt Exp $ */ +/* $NetBSD: kernhist.h,v 1.10 2015/10/29 00:27:08 mrg Exp $ */ /* * Copyright (c) 1997 Charles D. Cranor and Washington University. @@ -85,6 +85,8 @@ LIST_HEAD(kern_history_head, kern_history); #define KERNHIST_UVMPDHIST 0x00000002 /* pdhist */ #define KERNHIST_UVMUBCHIST 0x00000004 /* ubchist */ #define KERNHIST_UVMLOANHIST 0x00000008 /* loanhist */ +#define KERNHIST_USBHIST 0x00000010 /* usbhist */ +#define KERNHIST_SCDEBUGHIST 0x00000020 /* scdebughist */ #ifdef _KERNEL diff --git a/sys/sys/systm.h b/sys/sys/systm.h index 809dafb58e02..8bc6d6a9682d 100644 --- a/sys/sys/systm.h +++ b/sys/sys/systm.h @@ -1,4 +1,4 @@ -/* $NetBSD: systm.h,v 1.268 2015/08/28 07:18:40 knakahara Exp $ */ +/* $NetBSD: systm.h,v 1.269 2015/10/29 00:27:08 mrg Exp $ */ /*- * Copyright (c) 1982, 1988, 1991, 1993 @@ -489,6 +489,7 @@ extern int db_fromconsole; /* XXX ddb/ddbvar.h */ #endif /* _KERNEL */ /* For SYSCALL_DEBUG */ +void scdebug_init(void); void scdebug_call(register_t, const register_t[]); void scdebug_ret(register_t, int, const register_t[]);