3.3.4-5 is a very old kernel at this point, and the backtrace is from a custom-built upstream kernel.  Given you're clearly working with upstream source, did you report this bug to the upstream developers?

I started looking into  issue of NMI during 256 FCoE luns and looked into all three RHEL6.3 GA, FC17 and upstream kernel based on FC17 config. The FC17 and RHEL6.3 completely locks up and no useful info before lockup while upstream only has NMI WARN as attached above in the trace. The upstream trace can be use as data point to root cause FC17 and RHEL6.3 lock up and so far I've isolated FCoE/SCSI/network, that suggests likely real root cause and fix would be in NMI or console driver, so someone more familiar with these subsystems could be of quick help here and can pursue with any of these config, anyone @rehat owner/expert for those area ?

Also trying attached test module is very quick, so Josh can you give quick try on latest FC17 kernel, it should give another data point in case lock-up is unique to my HW setup though I had two HW flavor with details attached to the bug ?

Any response to my comment #2 ?

Related RHEL6.x BZ https://bugzilla.redhat.com/show_bug.cgi?id=647041, I believe RHEL worked around this issue with increased watchdog threshold to 60, since as I mentioned before that lock up occurs with RHEL6.3 also once watchdog threshold set to 10 as in FC17, so real underlying issue exist for quite some time.

Vasu, also, can you try this without the netconsole module?  Thats often a path that responsible for lockups.

(In reply to comment #4)
> Vasu, also, can you try this without the netconsole module?  Thats often a
> path that responsible for lockups.

I also suspected that and therefore I had it disabled in my test. 

I started with FCoE on this issue and then isolatted SCSI and networking in my debugging as I described in the bug description. The attached test module triggeres the issues w/o networking module loaded. This isolates entire networking subsystems including netconsole.

thank you vasu, thats very helpful.  I'll use that to reproduce here shortly.

I've used the module to reproduce the problem.  Not sure what to do about it at this point though.  Thinking....

hmm, something just occured to me, looking at this code.  The test case is running _much_ faster than I would expect it to, and its not printing everything it should be.  investigating....

Ok, found the problem - and its code that you simply can't run in the kernel.  I noted your pr_count variables was decremented in a while loop. If you create a process renice it to be the highest priority task in the system, and never yield the cpu in the kernel and do nothing but issue printks, the kernel will do that to the exclusion of all other tasks in the system.  And if you do so on every cpu, deadlocks are inevitible.  It might cause the same symptom as what you see in fcoe, but its not really a fixable issue.  More specifically the fix may be simply to ratelimit the printk with the __ratelimit function.  I presume that you're see the sd_revalidate_disk printk when this problem occurs?

yeah, the more I look at this the more I think its not really a bug, at least not one thats worth fixing.  The test case here busys every cpu on the system with a high priority thread that never yields the cpu, so we basically are guaranteed to loose responsivness in user space immediately.  And flooding the console is something that is consistently handled upstream with ratelimiting (as flooding the console isn't useful).  Additionally if this is a problem with constant printouts from sd_revalidate_disk, then we've either found a call that needs ratelimiting, or we've got debugging turned on and created a pessimal situation which will never be encountered with production systems (i.e. in this case we would need to reduce scsi_logging_level to reduce console stress).

(In reply to comment #10)
> yeah, the more I look at this the more I think its not really a bug, at
> least not one thats worth fixing.  The test case here busys every cpu on the
> system with a high priority thread that never yields the cpu,

Test thread does yields CPU as:

1) it simply writes prints in thread context thus interrupts, soft IRQ and other threads becoming higher priorty due to long delay would always preepmt the test thread.

2) the test threads sleeps for 100 seconds after each print cycle, that is really long period to allow other to finish doing job while no other load with all networking disabled.


Its okay to be not responsive for time being but I don't see any way the test thread its self could result in masking timer interrupt or soft IRQ and then resulting in NMI or soft lockup for above reason, but indirectly these prints from the threads probably hitting a console bug causing NMI or system lockup.

> so we
> basically are guaranteed to loose responsivness in user space immediately. 

Thats fine, if you do insmod followed by rmmod after some delay then you would expect system to comeback but it doesn't most of the time as that is the issue.

> And flooding the console is something that is consistently handled upstream
> with ratelimiting (as flooding the console isn't useful).  Additionally if
> this is a problem with constant printouts from sd_revalidate_disk, then
> we've either found a call that needs ratelimiting, or we've got debugging
> turned on and created a pessimal situation which will never be encountered
> with production systems (i.e. in this case we would need to reduce
> scsi_logging_level to reduce console stress).

Its fine to work around using ratelimit but real root cause fix would better.
I call it workaround as the ratelimit means reducing prints and that masks the underlying issue as RHEL 6.3 did different by masking with increasing watchoug threshold to 60 seconds which is really long time for timer interrupt to not occurs and then NMI after 120 seconds long time of timer interrupt being disabled. If you set threshold to 10 seconds then production system kernel such as FC kernel hits same issue either with this test module or FCoE scsi HBA discoverying of 256 luns on intermittent link up/down. I think it would occur with any HBA as scsi console prints are common.

>Test thread does yields CPU as:
Not in any meaningful way it doesn't.

>1) it simply writes prints in thread context thus interrupts, soft IRQ and other >threads becoming higher priorty due to long delay would always preepmt the test >thread.
>
Thats not yielding in any meaningful way.  Interrupts and softirqs will still run, yes, but will quickly exhaust system resources because while they create consumable requests (skbs get queued for reception and processing, data arrives on serial ports or input devices/etc, timers schedule delayed work, etc), nothing ever consumes them.  While tasks at the same or higher priority would get scheduled to interleave with your test module, that won't ever happen because you've set the nice level of these tasks to -20, so while they're in the kernel, they will never get pre-empted by any other user space task, hence the user space lock up, and if nothing in user space handles the data being generated by interrupts, we eventually deadlock.  Simply removing the renicing call in your test module (along with another minor fix, see below), prevents any deadlock from occuring.

>2) the test threads sleeps for 100 seconds after each print cycle, that is >really long period to allow other to finish doing job while no other load with >all networking disabled.
Not quite, your origional code has a bug.  you appear to have intended to have each kthread preform this sequence test_pr_count times:
1)printk(VDBG Console print flood from CPU:)
2) sleep(100 seconds)
3) printk(VDBG out of sleep CPU:%d)

But the while loop indicates you're going to print step 1, test_pr_count times before sleeping at all.  Since test_pr_count defaults to 1000000, you're going to print that first line 1000000 times before sleeping.  if you do that on each cpu, making them compete for the logbuf lock, thats going to take alot of time, especially when you consider that one of those tasks needs to write everything to each console, which is more often then not a hardware device like a SOL or RAC card that will block when its full of buffered data.  Couple this with the fact that each of these runs at a nice of -20, and no other user space task will run at all until these cpus actually allow anything to, and they simply dont.

If you modify your test case to simply remove the nice level and call schedule_timeout between the printks on each iteration, you can sleep for as little as 1 jiffy between each call and the problem doesn't occur.  Alternatively if you don't schedule a printk on one or more cpus, you don't get any lockup, and don't even need to sleep.  Only if you execute on all cpus and don't yield, do you get any sort of deadlock.

>Its okay to be not responsive for time being but I don't see any way the test >thread its self could result in masking timer interrupt or soft IRQ and then >resulting in NMI or soft lockup for above reason, but indirectly these prints >from the threads probably hitting a console bug causing NMI or system lockup.
The NMI triggers for me just fine after it times out (as it does for you, since thats what generated the stack trace in the initial comment of this bz, and irqs and softirqs do in fact run (thats how the softlockup notices are triggered), but eventually the tasks in the test module monopolize the cpu to a degree where its irrelevant, just running irqs and softirqs won't prevent a system from deadlocking.

I think the same thing is happening in your production case, if you encounter an error in a FCoE connection and you wind up calling sd_revalidate_disk.  The code path for that does a fair amount of spin_lock_irqsave, which means that a good portion of the time these printk's are actually being issued with irqs blocked.  And there can be up to 256 worker threads running at any one time.  So I think we're really just seeing another way that a set of tasks is monopolizing the system to the exclusion of other important work.  

We don't necessecarily need to just ratelimit the printks, looking at this, the scsi midlayer looks like its doing a fair amount of redundant work, so eliminating some of that might be an alternate solution.  I'll try to put together a patch for that soon

hmm, upstream commit 083b804c4d3e1e3d0eace56bdbc0f674946d2847 might be useful here.  As it seems the async code that runs in RHEL6 has a horrible habbit ofcreating more threads than we have cpus to run them, and I'm bettting that creates some real contention problems, I'll see if I can get this commit backported, which moves the async code to using a workqueue, whcih should reduce cpu contentino significantly.

Created attachment 645175 [details]
patch to reduce the async thread count to be sane

soo, looking at it, pulling in the above commit implies a complete update of the workqueue code, and that way too much, at least to do it without taking lots of care, I think maybe the rhel6 only async thread count that I noted earlier would be good.

Note, this fix is for RHEL6, not fedora.  But since the description of this problem mixes a problem on rhel6 with the reproducer on fedora, I want to be clear this doesn't apply to the reproducer module, but I think will fix the actual fcoe problem on RHEL6.  Please build a test kernel with this patch and confirm that it solves the origional problem.  Thank you.

(In reply to comment #14)
> Created attachment 645175 [details]
patch to reduce the async thread count
> to be sane

soo, looking at it, pulling in the above commit implies a
> complete update of the workqueue code, and that way too much, at least to do
> it without taking lots of care, I think maybe the rhel6 only async thread
> count that I noted earlier would be good.

Note, this fix is for RHEL6, not
> fedora.  But since the description of this problem mixes a problem on rhel6
> with the reproducer on fedora, I want to be clear this doesn't apply to the
> reproducer module, but I think will fix the actual fcoe problem on RHEL6. 
> Please build a test kernel with this patch and confirm that it solves the
> origional problem. 

Neil, which original problem to test with this RHEL patch ?  This BZ is for system lock up when console flooded using test module w/o having any networking module loaded and on the console at run-level 3. 

I'm not sure if I can address all recent notes in-line, so instead I'll try to to address key points from your so far findings.

On your point that the per CPU test kernel thread with nice of -20 is the bug in test code as it would starve defered SKBs tasks, I had complete networking disabled on the system, so  no such task to starve. The goal of the test was to hammer just the console with no other load and expect system not to lockup, that means if test modules loaded for some finite time then system would come back alive after test module done at some point of time but that is not the case. If any specific thread you think might starve here then may be testing w/o nice -20 would help. 

On your point possiblly SCSI code is I got the point of just stressing the console test after making sure

Ooops, in middle of my notes BZ got updated, I'll continue on comment # 15.

On your point that possiblly SCSI code disbling IRQ while issuing prints could lead thread to monoplize threads. I did verify that before and found that NMI occurred from just any single printks while interrupts not disabled. I stored all info in an array then triggred its print on NMI watchdoug while timer interrupt was missed causing NMI, used array to have minimum affect on runtime flows. So unlikely SCSI code is leading NMI and possibbly thereafter lock up, I think down inside printk or console driver implementation possibly waiting on a lock with intr disabled could be the cause here. We can always work this around by limiting prints in code or simply using "dmesg -n 1 or loglevel=1" but instead if console driver could handle load w/o causing NMI then that would be better. Below is the trace I had on NMI indicating no IRQ or bh disaabled before scsi printks when NMI from console printk occured:-

[ 2961.406214] VDBG scsi idx: 23 : func: sd_revalidate_disk line 2562: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612436 and delta:0
[ 2961.406216] VDBG scsi idx: 22 : func: sd_revalidate_disk line 2560: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612436 and delta:0
[ 2961.406217] VDBG scsi idx: 21 : func: sd_revalidate_disk line 2557: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612436 and delta:0
[ 2961.406218] VDBG scsi idx: 20 : func: sd_revalidate_disk line 2555: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612436 and delta:0
[ 2961.406220] VDBG scsi idx: 19 : func: sd_revalidate_disk line 2541: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612436 and delta:0
[ 2961.406221] VDBG scsi idx: 18 : func: sd_revalidate_disk line 2539: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612436 and delta:0
[ 2961.406222] VDBG scsi idx: 17 : func: sd_revalidate_disk line 2537: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612436 and delta:0
[ 2961.406224] VDBG scsi idx: 16 : func: sd_revalidate_disk line 2535: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d431 pip: ffffffff8108b288 CPU: 12 TS:4297612435 and delta:1
[ 2961.406225] VDBG scsi idx: 15 : func: sd_revalidate_disk line 2562: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:168
[ 2961.406226] VDBG scsi idx: 14 : func: sd_revalidate_disk line 2560: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406227] VDBG scsi idx: 13 : func: sd_revalidate_disk line 2557: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406229] VDBG scsi idx: 12 : func: sd_revalidate_disk line 2555: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406230] VDBG scsi idx: 11 : func: sd_revalidate_disk line 2541: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406231] VDBG scsi idx: 10 : func: sd_revalidate_disk line 2539: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406233] VDBG scsi idx: 9 : func: sd_revalidate_disk line 2537: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406234] VDBG scsi idx: 8 : func: sd_revalidate_disk line 2535: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406236] VDBG scsi idx: 7 : func: sd_revalidate_disk line 2494: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406237] VDBG scsi idx: 6 : func: sd_revalidate_disk line 2486: irq_dis: 0 bh_dis: 0  cip: ffffffff812f3c45 pip: ffffffff811c56b6 CPU: 12 TS:4297612267 and delta:0
[ 2961.406238] VDBG scsi idx: 5 : func: sd_revalidate_disk line 2533: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d314 pip: ffffffff8108b288 CPU: 12 TS:4297612266 and delta:1
[ 2961.406240] VDBG scsi idx: 4 : func: sd_revalidate_disk line 2510: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d314 pip: ffffffff8108b288 CPU: 12 TS:4297612266 and delta:0
[ 2961.406241] VDBG scsi idx: 3 : func: sd_revalidate_disk line 2484: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d314 pip: ffffffff8108b288 CPU: 12 TS:4294672865 and delta:2939401
[ 2961.406242] VDBG scsi idx: 2 : func: sd_revalidate_disk line 2466: irq_dis: 0 bh_dis: 0  cip: ffffffff8141d314 pip: ffffffff8108b288 CPU: 12 TS:4294672865 and delta:0
[ 2961.406243] VDBG scsi idx: 1 : func: sd_probe_async line 2672: irq_dis: 0 bh_dis: 0  cip: ffffffff8108b288 pip: ffffffff8107bfcf CPU: 12 TS:4294672813 and delta:52

Vasu, in your initial description of this problem you said you noted this console lockup while add 256 Luns over FCoE during a cable pull test (ostensibly under RHEL 6.3), This patch is meant to address that.  Please build and test a kernel against that test.

I started on reported  256 FCoE luns & cable pull test causing  lockup on upstream using FC17 config, I didn't see complete lockup but NMI WARN and that was due to 20 seconds temporary lock up. I pursed that further using test module and with that I could see FC17 and RHEL6.3 completey locks up, the test module was streching further which left system locked while networking completely disabled at run level-3. I think there is underlying issue in console or NMI code  and I wish we had help from expert in those area here. As for FCoE RHEL6.3 is fine as watchdog threshold is 60 and RHEL BZ is already verified. The upsteram and FC17 kernels can avoid NMI WARN using less console prints with "dmes -n 1" or loglevel=1. We can workaround but using test module fixing the root cause in console or NMI would have better fix. 

The test module doesn't uses SCSI code so testing SCSI fix patch won't help.

I'm perfectly well aware of what you started with and what the test module does.  What I'm asserting is that:

1) The test module reproduces a problem that would never exist is production environments.  If you write code that prevents the system from doing enough real work, yes, it will stop working properly, the solution is "don't do that".  While it presents simmilar symptoms to what you initially encountered (and in fact does so in a simmilar way), The solution in both cases is don't monopolize the cpus on the system like that.

2) In the initial problem you encountered, it appears to have happened because the code which runs sd_revalidate_disk does so from a library that, in RHEL6, spawns an almost unlimited number of threads (due to an atomic_dec/inc race) that can monopolize the cpu while running in kernel space.  I've found an upstream commit that reworks that code, moving it to a workqueue that limits the thread executution to scale to the number of cpus we have on a given system.  RHEL6 can't take that change because its too invasive, so I've found a way to work around it an approximate what that change does.

So, if you're still seeing the origional problem that you reported, please try the patch.  If you're not seeing it, then we should probably close this bz.

Original problem was with upstream with FC17 config and that is now has only NMI warnon and that doesn't happen with loglevel=1 kernel cmdline.

The RHEL prior to 6.4 is tested w/o any issue with FCoE in this case. I don't know of any production FCoE test cases and I've seen with only test module with RHEL testing and that was for debugging on RHEL but as you said that is not practical. RHEL might have worked with production test case and its higher watchdog thresh=60 might have helped there. I think identified upstream commit backport is useful in case such issue found in the RHEL fisrt. So bottom line let us limit this BZ to upsream and its warn on doesn't happen with loglevel=1 and we cannot fix issue with test module here as we talked before. So I'm closing this BZ.