From owner-svn-src-all@freebsd.org Mon Nov 2 03:36:17 2015 Return-Path: Delivered-To: svn-src-all@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 39B4DA24CF0; Mon, 2 Nov 2015 03:36:17 +0000 (UTC) (envelope-from adrian@FreeBSD.org) Received: from repo.freebsd.org (repo.freebsd.org [IPv6:2610:1c1:1:6068::e6a:0]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id E60081ABD; Mon, 2 Nov 2015 03:36:16 +0000 (UTC) (envelope-from adrian@FreeBSD.org) Received: from repo.freebsd.org ([127.0.1.37]) by repo.freebsd.org (8.15.2/8.15.2) with ESMTP id tA23aGpB044403; Mon, 2 Nov 2015 03:36:16 GMT (envelope-from adrian@FreeBSD.org) Received: (from adrian@localhost) by repo.freebsd.org (8.15.2/8.15.2/Submit) id tA23aGQH044402; Mon, 2 Nov 2015 03:36:16 GMT (envelope-from adrian@FreeBSD.org) Message-Id: <201511020336.tA23aGQH044402@repo.freebsd.org> X-Authentication-Warning: repo.freebsd.org: adrian set sender to adrian@FreeBSD.org using -f From: Adrian Chadd Date: Mon, 2 Nov 2015 03:36:16 +0000 (UTC) To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r290258 - head/sys/mips/mips X-SVN-Group: head MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit X-BeenThere: svn-src-all@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: "SVN commit messages for the entire src tree \(except for " user" and " projects" \)" List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 02 Nov 2015 03:36:17 -0000 Author: adrian Date: Mon Nov 2 03:36:15 2015 New Revision: 290258 URL: https://svnweb.freebsd.org/changeset/base/290258 Log: mips: rate limit the trap handler output; add pid/tid/program name. I discovered that we're logging each trap, which gets pretty spendy; and there wasn't any further information on the pid/tid/progname involved. I originally noticed this because I don't attach anything to /dev/log and so the log() output stays going to the kernel. That's an oops on my part, but I'm glad I did it. This commit adds the following: * a rate limiter, which could do with some eyeballs/ideas on how to make it more predictable on SMP; * log pid, tid, progname (comm) as part of the output. I now get output like this: Unaligned Load Word: pid=621 (pmcstat), tid=100060, pc=0xffffffff803ae898, badvaddr=0x40a10055 Unaligned Load Word: pid=621 (pmcstat), tid=100060, pc=0xffffffff803ae898, badvaddr=0x40a10051 Unaligned Load Word: pid=621 (pmcstat), tid=100060, pc=0xffffffff803ae898, badvaddr=0x40a1004d Unaligned Load Word: pid=602 (login), tid=100042, pc=0xffffffff803ae898, badvaddr=0x401159 Unaligned Load Word: pid=602 (login), tid=100042, pc=0xffffffff803ae898, badvaddr=0x401155 Unaligned Load Word: pid=602 (login), tid=100042, pc=0xffffffff803ae898, badvaddr=0x401151 .. which makes it much easier to start figuring out what/where to fix. The pc looks suss (it looks like it's in kernel space); I'll dig into that one next. Tested: * AR9331 SoC (Carambola2) Modified: head/sys/mips/mips/trap.c Modified: head/sys/mips/mips/trap.c ============================================================================== --- head/sys/mips/mips/trap.c Mon Nov 2 03:14:37 2015 (r290257) +++ head/sys/mips/mips/trap.c Mon Nov 2 03:36:15 2015 (r290258) @@ -1660,11 +1660,25 @@ mips_unaligned_load_store(struct trapfra } +/* + * XXX TODO: SMP? + */ +static struct timeval unaligned_lasterr; +static int unaligned_curerr; + +static int unaligned_pps_log_limit = 4; + +SYSCTL_INT(_machdep, OID_AUTO, unaligned_log_pps_limit, CTLFLAG_RWTUN, + &unaligned_pps_log_limit, 0, + "limit number of userland unaligned log messages per second"); + static int emulate_unaligned_access(struct trapframe *frame, int mode) { register_t pc; int access_type = 0; + struct thread *td = curthread; + struct proc *p = curproc; pc = frame->pc + (DELAYBRANCH(frame->cause) ? 4 : 0); @@ -1691,9 +1705,19 @@ emulate_unaligned_access(struct trapfram else frame->pc += 4; - log(LOG_INFO, "Unaligned %s: pc=%#jx, badvaddr=%#jx\n", - access_name[access_type - 1], (intmax_t)pc, - (intmax_t)frame->badvaddr); + if (ppsratecheck(&unaligned_lasterr, + &unaligned_curerr, unaligned_pps_log_limit)) { + /* XXX TODO: keep global/tid/pid counters? */ + log(LOG_INFO, + "Unaligned %s: pid=%ld (%s), tid=%ld, " + "pc=%#jx, badvaddr=%#jx\n", + access_name[access_type - 1], + (long) p->p_pid, + p->p_comm, + (long) td->td_tid, + (intmax_t)pc, + (intmax_t)frame->badvaddr); + } } } return access_type;