Ever since the recent lockstat improvements, my Soekris 6501 running i386 has been having a repeatable kernel panic at boot up. I normally running CURRENT, however after tracking the issue down I verified this is happening on 10.2-BETA1 as well as CURRENT. The panic I am seeing looks along the lines of this below and is repeatable on a revision with the lockstat work. The only way I have been able to boot on an impacted revision is by using safe boot via the boot loader menu. SMP: AP CPU #1 Launched! Timecounter "TSC" frequency 1600033960 Hz quality 1000 Fatal double fault: eip = 0xc1099873 esp = 0xe1fb8000 ebp = 0xe1fb8000 cpuid = 1; apic id = 01 panic: double fault cpuid = 1 KDB: stack backtrace: #0 0xc0b7a602 at kdb_backtrace+0x52 #1 0xc0b3b79b at vpanic+0x11b #2 0xc0b3b67b at panic+0x1b #3 0xc108736b at dblfault_handler+0xab Uptime: 11s Automatic reboot in 15 seconds - press a key on the console to abort Summary of tested revisions: stable/10 -- good -- r284994 stable/10 -- bad -- r284998, r285365 head -- good -- r284296, r284256, r284233, r284194 head -- bad -- r284297, r284309, r285143-r285155 (approx, this was when I initially ran into issue) The common ground has been the several lockstat improvement commit in r284297. https://svnweb.freebsd.org/base?view=revision&revision=284297
Hi Jason, Would you be able to give the patch here a try? https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=201517
(In reply to Mark Johnston from comment #1) That was super fast. I was getting together my boot time dmesg's to attach for more detail. I will apply that patch right now and start of a build of a new NanoBSD image for my router. I'll let you know the results tomorrow evening. Thanks Mark.
Created attachment 158899 [details] panic-10.2-BETA1-r285386-IPSEC-dmesg.txt Just in case it comes of use, I'll provide all my boot longs. This Soekris has a serial console and I can assist debugging this further if the patch doesn't work.
Created attachment 158900 [details] panic-10.2-BETA1-r285386-IPSEC-verbose-dmesg.txt
Created attachment 158901 [details] panic-HEAD-r284297-IPSEC-dmesg.txt
Created attachment 158902 [details] panic-HEAD-r285155-GENERIC-dmesg.txt
Great, thank you!
Mark, thank you for taking charge of this report and bug #201517 ! Do I understand correctly that the problem is that some timecounters (at least i8254) have to take a lock internally and that leads to a recursion via lockstat_nsecs() ? Is this the only problem with the new code? If that's the case, then the patch that you suggested should certainly help during the boot time, but will it help later on when lockstat command is run?
(In reply to Andriy Gapon from comment #8) Hi Andriy, The motivation for my patch was actually a performance regression that I observed when benchmarking: https://reviews.freebsd.org/D3073 For the PRs, I had assumed that we were attempting to take a rw read lock before timecounters were initialized, and that was somehow causing the reported hangs/crashes during boot. But I think you're correct: we now do timer reads in mtx_lock_spin, which can cause recursion in i8254_get_timecount. I note that that mutex is initialized with MTX_NOPROFILE (LO_NOPROFILE); perhaps that should be used to indicate that lockstat profiling is disallowed as well?
(In reply to Mark Johnston from comment #9) Ah, I see. Yeah, the performance thing has to be fixed as well. BTW, in illumos they take the time only when the corresponding probe is enabled. For example: spin_time = LOCKSTAT_START_TIME(LS_MUTEX_ENTER_SPIN); where #define LOCKSTAT_START_TIME(probe) ( \ lockstat_probemap[(probe)] ? gethrtime_waitfree() : 0 \ ) But you patch is good as well. Returning to the original bug: I think that lockstat honouring LO_NOPROFILE is a great idea. Thanks!
Another note, bug #201517 might be a different issue as the symptoms are different. Quite possible that it is a hang because of uninitialized timecounters as you noted.
(In reply to Andriy Gapon from comment #10) Ok. I'll commit this patch tomorrow too if all goes well: https://people.freebsd.org/~markj/patches/lockstat_noprofile.diff Jason, it would still be helpful to proceed with testing the original patch. I'll test the second patch tomorrow and commit.
(In reply to Mark Johnston from comment #12) Looks good, thank you! I am contemplating reverting the change from stable/10, so that the release is not jeopardized. Would you recommend I do that? Or would you prefer to MFC your fixes promptly? Part of the problem is that today is my last day before a 2 week long vacation. P.S. not sure if the following bit of information is of any importance, but it seems that only 3 locks are initialized with NOPROFILE, all of them are spin locks.
Gentlemen, Thank you both. I'll get you feedback on the first patch on HEAD tonight then follow up with applying that to stable/10 and get you feedback that if it fixes the issue there on Saturday. I don't want to see the release affected but I also don't want to see any of the hard work behind the initial change be wasted so I'll do what I can to quickly test any patches.
(In reply to Andriy Gapon from comment #13) If you prefer to revert the change on stable/10 for now, please go ahead. But I was planning to MFC the fixes promptly (and probably send a heads-up to re@). So I can take care of getting the changes in while you're away. I also have some other pending improvements to lockstat, and I'd rather not see your work reverted. :) NOPROFILE is indeed rarely used, but I think it was intended to address the same problem: the legacy lock_profile code also calls binuptime(), so it would have hit this issue as well.
Mark, The patch in bug 201517 is working for me. Thanks! Here's the uname -a: FreeBSD xju-rtr 11.0-CURRENT FreeBSD 11.0-CURRENT #0 r285646M: Fri Jul 17 11:17:35 UTC 2015 root@xts-bsd:/usr/obj/nanobsd.soekris/i386.i386/usr/src/head/sys/IPSEC i386 I'm going to apply this to stable/10 @ r285365 (10.2-BETA1) as that exact revision was a consistent panic before. If this patch is the only change that I make and it works then I think things look promising for a commit and swift MFC with re@'s approval. What do you want for the second patch? Do you want me to test with both combined or isolate the patches and test only the second one after finishing testing it in stable/10?
(In reply to Jason Unovitch from comment #16) Excellent, thank you! I've tested the second patch already, so I'm planning to commit both later tonight. If you happen to have the time though, it would be helpful to try running "lockstat -C sleep 1" with both patches applied. I believe that command will cause a panic when only the first patch is applied, but the second patch will fix it. If it's not convenient to do more testing, no worries. Thanks again.
(In reply to Mark Johnston from comment #17) Super. Thanks again for the quick reply. It takes about 2 hours for my NAS to build a NanoBSD image. I'll test the r285365 stable/10 tonight and make sure my boot time panics are gone and I'll capture the results good or bad of the "lockstat -C sleep 1". I'll fire off a new router image build before I go to sleep and provide the feedback with boot up and a "lockstat -C sleep 1" for a kernel with both patches tomorrow morning.
A commit references this bug: Author: markj Date: Sat Jul 18 00:22:02 UTC 2015 New revision: 285663 URL: https://svnweb.freebsd.org/changeset/base/285663 Log: Modify lockstat_nsecs() to just return unless lockstat probes are actually enabled. The cost of a timecounter read can be quite significant, and the problem became more apparent after r284297, since that change resulted in a call to lockstat_nsecs() for each acquisition of an rwlock read lock. PR: 201642 Reviewed by: avg Tested by: Jason Unovitch MFC after: 3 days Differential Revision: https://reviews.freebsd.org/D3073 Changes: head/sys/cddl/dev/lockstat/lockstat.c head/sys/kern/kern_lockstat.c head/sys/sys/lockstat.h
A commit references this bug: Author: markj Date: Sat Jul 18 00:57:32 UTC 2015 New revision: 285664 URL: https://svnweb.freebsd.org/changeset/base/285664 Log: Pass the lock object to lockstat_nsecs() and return immediately if LO_NOPROFILE is set. Some timecounter handlers acquire a spin mutex, and we don't want to recurse if lockstat probes are enabled. PR: 201642 Reviewed by: avg MFC after: 3 days Changes: head/sys/kern/kern_lockstat.c head/sys/kern/kern_mutex.c head/sys/kern/kern_rwlock.c head/sys/kern/kern_sx.c head/sys/sys/lockstat.h
(In reply to Mark Johnston from comment #17) Excellent work. Patch 1 (now r285663 in HEAD) is fixing the issue for me on stable/10 r285365M. This revision had a consistent panic at boot when I last tried before the patch and now I went through 5 reboot cycles with no issues. Things are looking good for the MFC. Here is the uname -a: FreeBSD xju-rtr 10.2-BETA1 FreeBSD 10.2-BETA1 #0 r285365M: Sat Jul 18 00:01:13 UTC 2015 root@xts-bsd:/usr/obj/nanobsd.soekris/i386.i386/usr/src/stable/10/sys/GENERIC i386 For the second issue. I'm not familiar with lockstat. On this stable/10 build I get this: # lockstat -C sleep 1 lockstat: can't load kernel symbols: No such file or directory On a PCBSD 11-CURRENT system from the start of July this command causes an instant panic.
(In reply to Mark Johnston from comment #17) On this revision: FreeBSD xju-rtr 11.0-CURRENT FreeBSD 11.0-CURRENT #0 r285646M: Fri Jul 17 11:17:35 UTC 2015 root@xts-bsd:/usr/obj/nanobsd.soekris/i386.i386/usr/src/head/sys/IPSEC i386 This has patch 1 but not patch 2. I didn't see any panic running the command. # lockstat -C sleep 1 Adaptive mutex spin: 4 events in 1.081 seconds (4 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 2 50% 50% 0.00 1646 0xcc5cd0a8 trap+0x4e4 ..... (continues) ..... If there is anything else at all that you can use help with let me know. Thanks!
(In reply to Jason Unovitch from comment #21) Ah, on 10.* I believe you have to "kldload ksyms" first. On CURRENT that's done automatically. As for the panic, you may be running into a bug that existed in the tree for a brief period after a rework: https://svnweb.freebsd.org/changeset/base/285180 Though I admit to not knowing what "PCBSD 11-CURRENT" is. Is that PCBSD with a recent FreeBSD kernel? If the change from that revision applies, it should fix the panic (it certainly fixes _a_ panic); else, we have a new bug. (In reply to Jason Unovitch from comment #22) Hm, that's a bit surprising. Could you paste the output of "sysctl kern.timecounter.hardware"? It might be that the i8254 timecounter mutex is only acquired during boot, and the kernel selects a different timer soon after.
Ok, sticking with the Soekris. r285664 doesn't seem to make a difference on this hardware. I see the TSC timecounter. The i8254 is mentioned early in the boot process, see one of the earlier dmesgs. Here's the 10.2-BETA1 again which was with patch 1 but not patch 2. FreeBSD xju-rtr 10.2-BETA1 FreeBSD 10.2-BETA1 #0 r285365M: Sat Jul 18 00:01:13 UTC 2015 root@xts-bsd:/usr/obj/nanobsd.soekris/i386.i386/usr/src/stable/10/sys/GENERIC i386 # kldload ksyms # lockstat -C sleep 1 Adaptive mutex spin: 2 events in 1.026 seconds (2 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 2 100% 100% 0.00 1517 vm_page_queue_free_mtx vm_fault+0x81 ..... (continued) ..... # sysctl kern.timecounter.hardware kern.timecounter.hardware: TSC I let my build script auto update src and do a build last night. So this has both 1 and 2. FreeBSD xju-rtr 11.0-CURRENT FreeBSD 11.0-CURRENT #0 r285668: Sat Jul 18 06:42:52 UTC 2015 root@xts-bsd:/usr/obj/nanobsd.soekris/i386.i386/usr/src/head/sys/IPSEC i386 # lockstat -C sleep 1 Adaptive mutex spin: 4 events in 1.105 seconds (4 events/sec) Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------------- 4 100% 100% 0.00 21066 0xc74ea674 intr_event_execute_handlers+0x283 ..... (continued) ..... # sysctl kern.timecounter.hardware kern.timecounter.hardware: TSC
(In reply to Mark Johnston from comment #23) Regarding the PCBSD, I've been testing their CURRENT images out lately on my desktop. It's based on FreeBSD HEAD r284814 as of 2015-06-25 based off a review the commit log of https://github.com/pcbsd/freebsd/commits/master?page=2. Based on your comment, it sounds like r285180 should fix this panic.
A commit references this bug: Author: markj Date: Tue Jul 21 17:16:40 UTC 2015 New revision: 285759 URL: https://svnweb.freebsd.org/changeset/base/285759 Log: MFC r285663, r285664, r285667: Ensure that locstat_nsecs() has no effect when lockstat probes are not enabled or when the profiled lock carries the LO_NOPROFILE flag. PR: 201642, 201517 Approved by: re (gjb) Tested by: Jason Unovitch Changes: _U stable/10/ stable/10/sys/cddl/dev/lockstat/lockstat.c stable/10/sys/kern/kern_lockstat.c stable/10/sys/kern/kern_mutex.c stable/10/sys/kern/kern_rwlock.c stable/10/sys/kern/kern_sx.c stable/10/sys/sys/lockstat.h
A commit references this bug: Author: markj Date: Tue Jul 21 17:19:06 UTC 2015 New revision: 285760 URL: https://svnweb.freebsd.org/changeset/base/285760 Log: MFC r285663, r285664, r285667: Ensure that locstat_nsecs() has no effect when lockstat probes are not enabled or when the profiled lock carries the LO_NOPROFILE flag. PR: 201642, 201517 Changes: _U stable/9/sys/ stable/9/sys/cddl/dev/lockstat/lockstat.c stable/9/sys/kern/kern_lockstat.c stable/9/sys/kern/kern_mutex.c stable/9/sys/kern/kern_rwlock.c stable/9/sys/kern/kern_sx.c _U stable/9/sys/sys/ stable/9/sys/sys/lockstat.h
This is now fixed on stable/10 and 9. Thanks for the report!