svn commit: r290258 - head/sys/mips/mips

[Adrian Chadd]

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;