Bug 845211

I have the same problem, same bridge. This is definitely due to kernel patch:  unhandled-irqs-switch-to-polling.patch
Removing this patch restores video performance.

I rebuilt the fedora 3.4.7-1 kernel (stock) using:
rpmbuild -bb --define="buildid .stock" --target x86_64 SPECS/kernel.spec
kernel-3.4.7-1.stock.fc16.x86_64
kernel-3.4.7-2.unpatch.fc16.x86_64
Installing kernel-3.4.7-1.stock.fc16.x86_64 and using mythtv to watch live video resulted in significant, frequent pauses;  It was unwatchable.

Then I commented out the patch with this mod to the kernel spec:
--- kernel.spec_orig    2012-08-18 18:55:07.184044817 -0700
+++ kernel.spec 2012-08-18 18:58:13.115579172 -0700
@@ -54,7 +54,7 @@
 # For non-released -rc kernels, this will be appended after the rcX and
 # gitX tags, so a 3 here would become part of release "0.rcX.gitX.3"
 #
-%global baserelease 1
+%global baserelease 2
 %global fedora_build %{baserelease}
 
 # base_sublevel is the kernel version we're starting with and patching
@@ -688,7 +688,7 @@
 #rhbz 754518
 #Patch21235: scsi-sd_revalidate_disk-prevent-NULL-ptr-deref.patch
 
-Patch21300: unhandled-irqs-switch-to-polling.patch
+#Patch21300: unhandled-irqs-switch-to-polling.patch
 
 #rhbz 804957 CVE-2012-1568
 Patch21306: shlib_base_randomize.patch
@@ -1312,7 +1312,7 @@
 #rhbz 754518
 #ApplyPatch scsi-sd_revalidate_disk-prevent-NULL-ptr-deref.patch
 
-ApplyPatch unhandled-irqs-switch-to-polling.patch
+#ApplyPatch unhandled-irqs-switch-to-polling.patch
 
 # debug patches
 ApplyPatch weird-root-dentry-name-debug.patch
@@ -2035,6 +2035,10 @@
 # and build.
 
 %changelog
+* Sat Aug 18 2012 Bob Arendt <rda> 3.4.7-2
+- Remove unhandled-irqs-switch-to-polling.patch for Hauppauge MCE150
+  It inhibits video playback
+
 * Mon Jul 30 2012 Dave Jones <davej> 3.4.7-1
 - Linux 3.4.7
------------------------------------------

Rebuilt the kernel:
rpmbuild -bb --define="buildid .unpatch" --target x86_64 SPECS/kernel.spec

Installing and booting to kernel-3.4.7-2.unpatch.fc16.x86_64 resulted in good video playback.  There were no IRQ messages in the unpatched version, while the original stock F16 kernel had several of these messages:
kernel: [   68.211731] IRQ 18 might be stuck.  Polling
kernel: [   78.485515] IRQ 18 might be stuck.  Polling
kernel: [   95.208553] IRQ 18 might be stuck.  Polling
kernel: [  105.302009] IRQ 18 might be stuck.  Polling
.. corresponding to the problematic mythtv video playback

I do have the architecture that this patch attempts to address, but the patch seems to be false triggering when there isn't a problem (?).

Here's my PCI layout:
# lspci
00:00.0 Host bridge: Intel Corporation Ivy Bridge DRAM Controller (rev 09)
00:01.0 PCI bridge: Intel Corporation Ivy Bridge PCI Express Root Port (rev 09)
00:02.0 Display controller: Intel Corporation Ivy Bridge Graphics Controller (rev 09)
00:14.0 USB Controller: Intel Corporation Panther Point USB xHCI Host Controller (rev 04)
00:16.0 Communication controller: Intel Corporation Panther Point MEI Controller #1 (rev 04)
00:1a.0 USB Controller: Intel Corporation Panther Point USB Enhanced Host Controller #2 (rev 04)
00:1b.0 Audio device: Intel Corporation Panther Point High Definition Audio Controller (rev 04)
00:1c.0 PCI bridge: Intel Corporation Panther Point PCI Express Root Port 1 (rev c4)
00:1c.3 PCI bridge: Intel Corporation Panther Point PCI Express Root Port 4 (rev c4)
00:1c.4 PCI bridge: Intel Corporation Panther Point PCI Express Root Port 5 (rev c4)
00:1c.5 PCI bridge: Intel Corporation Panther Point PCI Express Root Port 6 (rev c4)
00:1c.7 PCI bridge: Intel Corporation Panther Point PCI Express Root Port 8 (rev c4)
00:1d.0 USB Controller: Intel Corporation Panther Point USB Enhanced Host Controller #1 (rev 04)
00:1f.0 ISA bridge: Intel Corporation Panther Point LPC Controller (rev 04)
00:1f.2 SATA controller: Intel Corporation Panther Point 6 port SATA AHCI Controller (rev 04)
00:1f.3 SMBus: Intel Corporation Panther Point SMBus Controller (rev 04)
01:00.0 VGA compatible controller: nVidia Corporation GF100 [GeForce GTX 480] (rev a3)
01:00.1 Audio device: nVidia Corporation GF100 High Definition Audio Controller (rev a1)
03:00.0 SATA controller: ASMedia Technology Inc. Device 0612 (rev 01)
04:00.0 Ethernet controller: Broadcom Corporation NetLink BCM57781 Gigabit Ethernet PCIe (rev 10)
05:00.0 PCI bridge: ASMedia Technology Inc. Device 1080 (rev 01)
06:01.0 Multimedia video controller: Internext Compression Inc iTVC16 (CX23416) MPEG-2 Encoder (rev 01)
07:00.0 USB Controller: ASMedia Technology Inc. ASM1042 SuperSpeed USB Host Controller

# lspci -tv
-[0000:00]-+-00.0  Intel Corporation Ivy Bridge DRAM Controller
           +-01.0-[01]--+-00.0  nVidia Corporation GF100 [GeForce GTX 480]
           |            \-00.1  nVidia Corporation GF100 High Definition Audio Controller
           +-02.0  Intel Corporation Ivy Bridge Graphics Controller
           +-14.0  Intel Corporation Panther Point USB xHCI Host Controller
           +-16.0  Intel Corporation Panther Point MEI Controller #1
           +-1a.0  Intel Corporation Panther Point USB Enhanced Host Controller #2
           +-1b.0  Intel Corporation Panther Point High Definition Audio Controller
           +-1c.0-[02]--
           +-1c.3-[03]----00.0  ASMedia Technology Inc. Device 0612
           +-1c.4-[04]----00.0  Broadcom Corporation NetLink BCM57781 Gigabit Ethernet PCIe
           +-1c.5-[05-06]----00.0-[06]----01.0  Internext Compression Inc iTVC16 (CX23416) MPEG-2 Encoder
           +-1c.7-[07]----00.0  ASMedia Technology Inc. ASM1042 SuperSpeed USB Host Controller
           +-1d.0  Intel Corporation Panther Point USB Enhanced Host Controller #1
           +-1f.0  Intel Corporation Panther Point LPC Controller
           +-1f.2  Intel Corporation Panther Point 6 port SATA AHCI Controller
           \-1f.3  Intel Corporation Panther Point SMBus Controller


This board (ASRock Extreme4) has the ASMedia 1b21:1080 PCIe-PCI bridge, and the ivtv0 device is the only card behind it and it's the only device on IRQ 18.  The interrupt rate may be high, but not excessive.  Here's a log of the /proc/interrupts taken at 10 second intervals:

 18:      37187      77013      39564     132937  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      40157     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      42162     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      43634     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      50364     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      56371     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      57070     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      63591     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      73413     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      74183     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      74843     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      79051     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      79051     141975  IR-IO-APIC-fasteoi   ivtv0
 18:      37187      77013      79051     141975  IR-IO-APIC-fasteoi   ivtv0

When running, it's about 600 interrupts/sec, with a burst at the start, and more at the end.  When the ivtv0 device isn't running, there are no interrupts on IRQ 18.

Starting to read the traffic that lead up to this patch, it appears that for several people this patch improves performance in a lot of cases that were problems before.  But this patch ends up killing performance for many cards.  In this case, we don't see any log messages regarding unhandled IRQ's without this patch applied.  But the patch completely kills our PCI-based video capture cards (Hauppauge MCE150 in my case).

I'd be happy to test a modified patch or provide additional information.

Same issue with Fedora 16 kernel-3.4.9-1.fc16.  Same un-patch corrects it.

(In reply to comment #2)
> Same issue with Fedora 16 kernel-3.4.9-1.fc16.  Same un-patch corrects it.

Same here on fc17 and 3.5.2-1.fc17.x86_64.

I've done some reading on the original issue and patch here:
https://lkml.org/lkml/2011/11/29/445

It appears that there wasn't a clear consensus if it was buggy hardware, either a fundamental flaw in the chip, the way the M/B manufacturer hooked it into the board, or chipset initialization (it was hypothesized a BIOS update might fix it).  This patch made a network interface usable by periodically unsticking it.  The counts of "IRQ_NONE" threshold was lowered drastically from 990000/1000000 to 9/10.  This is in kernel/irq/spurious.c in note_interrupt().  It appears another workaround may be to assert noirqdebug at boot, disabling all calls to this routine.

At this point, I believe there might be a DVB card behavior that's tripping the new threshold.  Looking at the ivtv driver in drivers/media/video/ivtv/ivtv-irq.c, it looks like ivtv_irq_handler() will return IRQ_NONE in some circumstances.  There's an interesting comment early on in the code:

	/* The vsync interrupt is unusual in that it won't clear until
	 * the end of the first line for the current field, at which
	 * point it clears itself. This can result in repeated vsync
	 * interrupts, or a missed vsync. Read some of the registers
	 * to determine the line being displayed and ensure we handle
	 * one vsync per frame.
	 */

Indeed, in the ivtv_irq_handler() routine has some code that tries to address this, but it looks like it might error on the side of returning IRQ_NONE rather than mistakenly grabbing another card's IRQ.  This probably wasn't an issue prior to the patch, but quite possibly this could be the source of the "stuck" IRQ that's triggering this issue.  Before the patch this wasn't a problem.  Now it makes video capture look like HD video over a dial-up.

But now the test threshold is set so low, it will probably always get tripped by a DVB card with this property.  If this is really the mechanism.

Currently I'm running kernel-3.4.9-1 without the unhandled-irqs-switch-to-polling.patch.  While running, I don't see any of the log messages Jeroen Van den Keybus noted in his original lkml.org thread;  The ASM1083 on my ASRock Z77 Extreme4 seems to operate correctly - but I don't have the same devices behind it.  My only device is the DVB card.

It seems that there might be a better set of default triggers for this patch, maybe make them configurable using /proc parameters?

Is there some way I can gather more detailed metrics on this interrupt using systemtap?

I'd like to note that this isn't limited to DVB cards. I have an NVidia GeForce GTX 560 (GF114) graphics card in the PCI-Express slot; I don't have any DVB card at all. 

When I first noticed the "IRQ 16 might be stuck. Polling" message (along with a period of almost zero responsibility), I had a sound card in a PCI slot behind the bridge. So I assumed it was the crappy bridge to blame and eventually removed the sound card, meaning there's nothing behind the PCIe-PCI bridge now. Yet, I would still get the messages and periods of almost no responsibility. (And yes, the GPU does use IRQ 16 which would get switched to polling mode.)

I could reliably trigger this behaviour by plugging in a second monitor to the graphics card while KDE was up. After removing the patch and plugging and unplugging a second monitor a few times, everything seems to work fine -- no interrupt storm, no dead IRQ, no lock up, no anything. I have yet to try putting the PCI sound card back in, though.

Here's some systemtap diag info for the kernel guys.  Thanks to Will Cohen at the RedHat Summit and his excellent talks I've written my first crude script to instrument "note_interrupt" in kernel/irq/spurious.c:

---------------------------# cat irqnote.stp 
#!/usr/bin/stap

global action

function dumpstat() {
  foreach ( [a] in action- ) {
     printf ("%d:%d  ", a, action[a])
  }
  printf ("\n")
  delete action
}

probe begin { printf ("Starting probe, irq %d\n", $1) }

probe kernel.function("note_interrupt")  {
  if ( $irq == $1 ) 
    action[$action_ret]++ 
}

probe timer.s(2) { dumpstat() }
-------------------------------

Given an irq to monitor, it histograms the action_ret value and dumps/clears the  histogram counts every two seconds.  It's crude - blank lines are output note_interrupt() was never called, and it doesn't sort the indices.  I'm on IRQ18, so here's what I get using my unpatched kernel:

--------------------------------
# stap  irqnote.stp 18
Starting probe, irq 18



1:101  
0:17356  1:128  
1:127  0:55  
1:131  
0:161  1:131  
1:128  0:64  
1:126  
1:132  
0:14120  1:130  
1:127  
1:129  
1:129  0:85  
1:131  0:43  
0:8567  1:134  
1:130  
1:133  0:41  
0:471  1:132  
1:135  
0:8845  1:128  
1:127  0:40  
1:129  
0:462  1:129  
0:8336  1:130  
1:100  





^C
Done
--------------------------------

I started stap, then started mythtv live playback (using ivtv0).  Also watching irq's with "watch -d cat /proc/interrupts".  After playing for a while, I stopped (more blank lines).  In the middle are the counts.  From include/linux/irqreturn.h  IRQ_NONE=0, IRQ_HANDLED=1.  The 0: counts are the problematic unhandled interrupts that are tripping the logic in unhandled-irqs-switch-to-polling.patch.  The key here are what are probably long periods with high IRQ_NONE counts.

To get greater time resolution, change "probe.s(2)" to "probe.ms(100)", now we see more detail on IRQ timing:
# stap irqnote.stp 18
Starting probe, irq 18
1:6  
1:6  
1:6  
1:11  
1:4  
1:6  
1:6  
1:6  
1:10  
1:4  
1:6  
1:6  
1:8  
0:1871  1:11  
0:6760  1:5  
1:7  
1:6  
1:7  
1:6  
1:9  
1:4  
1:6  
1:6  
1:6  
^C1:10  
1:2  
Done

So occasionally we get a large burst of IRQ_NONE, then it goes on it's way.  For ivtv, this could be the known condition where the *card* sticks the IRQ during vsync.  The ASM108x itself probably isn't broken in this motherboard.

To run systemtap yourself (no kernel recompile required):
yum install systemtap-client kernel-debuginfo kernel-debuginfo-common

I believe this should be sufficient to run the script.  systemtap is a fantastic tool for probing a running kernel.  Perhaps other folks with this issue can chime in with some statistics.

Well well, I really wished to try that, just the debuginfo packages are 1.4GB to install, after all the manual download for older kernel I ended up with error as this needs also kernel-[PAE-]devel, systemtap-devel.

This is PAE kernel. I have two DVB cards on irq
 18:    9683497  237251958   IO-APIC-fasteoi   ohci_hcd:usb4, ohci_hcd:usb5, ohci_hcd:usb6, ohci_hcd:usb7, saa7133[0], saa7133[0]
 19:    3099458  227452980   IO-APIC-fasteoi   ahci, saa7133[1], saa7133[1]

Both having problem with patched kernel.
IRQ 18:
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:10  
0:381  1:11  
1:10  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
0:388  1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:12  
1:14  
1:10

IRQ: 19
1:10  
1:16  
1:11  
1:10  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
0:617  1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10  
1:10  
1:11  
1:10

Interesting is just that IRQ 18 has usually around 380, while 19 has above 600. That's just all I can see ATM.

Created attachment 607012 [details]
Detailed statitstics

I enhanced the system tap script to output statistics.  Running over 20 minutes (100 msec sampling) the largest burst was 8672 unhandeled irq's, with 81% total IRQ's.  Therefore instead of a 9/10 statistic, something like a 9990/10000 statistic should work for me.  Here's the final output of the run,  the full detail is attached.


1242 secs duration
0=NONE  1=HANDLED
0: avg=1324  max=8672 total=364273
value |-------------------------------------------------- count
    4 |                                                     0
    8 |                                                     0
   16 |@@                                                   6
   32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         126
   64 |@@@@@@@@@@@                                         35
  128 |                                                     0
  256 |@@@@@                                               17
  512 |@@@@@@@                                             23
 1024 |@@                                                   7
 2048 |@@@@                                                14
 4096 |@@@@@@@@@@@@                                        38
 8192 |@@@                                                  9
16384 |                                                     0
32768 |                                                     0

1: avg=6  max=13 total=80915
value |-------------------------------------------------- count
    0 |                                                       0
    1 |                                                       0
    2 |                                                      88
    4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  10368
    8 |@@@@@@@@@                                           1963
   16 |                                                       0
   32 |                                                       0

81 % unhandled IRQs
Done

Here's the systemtap script:
------------  cat irqnote2.stp
global action, stats, tstart

probe begin {
  printf ("Starting probe, irq %d\n", $1);
  tstart = gettimeofday_s()
}

probe kernel.function("note_interrupt")  {
  if ( $irq == $1 ) 
    action[$action_ret]++ 
}

probe timer.ms(100) { 
  foreach ( a in action+ ) {
    stats[a] <<< action[a]
    printf ("%d:%d  ", a, action[a])
  }
  printf ("\n")
  delete action
}

probe end { 
  printf("%d secs duration\n", gettimeofday_s()-tstart)
  print("0=NONE  1=HANDLED\n")
  foreach ( a in stats+ ) {
    printf ("%d: avg=%d  max=%d total=%d\n", a, @avg(stats[a]), @max(stats[a]), @sum(stats[a]))
    print (@hist_log   (stats[a]))
    // print (@hist_linear(stats[a], 0, 10000, 100))
  }
  
  printf( "%d %% unhandled IRQs\n", (100*@sum(stats[0]))/(@sum(stats[0]) +@sum(stats[1])))
  printf ( "Done\n")
}
-----------------

I have similar problems and did some investigating of my own before finding this bug report.

The first thing I noticed was that polling at 10Hz was too slow. Polling at 100Hz, which IIRC was done in the original patch, was still too slow - video was just as unplayable. Polling at 1000Hz (for 1 second at a time) meant that I could watch tv from the dvb card smoothly.


But I was still getting very frequent "IRQ 16 might be stuck.  Polling" messages. Triggering polling at 9/10 unhandled interrupts is obviously too sensitive for this card so I started looking at /proc/irq/16/spurious to get an idea what the right threshold is. I booted a kernel with the irqpoll mechanism disabled so I'd get clear numbers.

Checking every 10 seconds while playing tv through vlc I see that irq 16 handles about 1000 interrupts a second and typically 100-200 unhandled interrupts in flight. I noticed that note_interrupt has a anti-doomsday-counter feature in that it resets the unhandled irq count if it hasn't seen one in the last 100ms. So I compiled a kernel with that effectively disabled and saw the rate of unhandled irqs range from 30/sec to 150/sec.

Based on this I'm going to try setting the threshold to 90/100 or maybe 180/200.


I haven't yet run the systemtap script to estimate the largest burst of unhandled interrupts, but by my reading of note_interrupt it may overestimate the number.

Averaged over a few hours: With a threshold of 90/100 unhandled interrupts, polling is triggered on every 15 seconds; with a threshold of 180/200 unhandled interrupts, polling is triggered every 1,000 seconds.

We're dropping this patch entirely.  Everyone comes up with different thresholds and overall it's not proving to be worthwhile.

Thanks Josh, sooner the better.  Right now my work-around is to add "noirqdebug=1" to the boot line (in etc/default/grub);  Then note_interrupt is never called.

# Mass update to all open bugs.

Kernel 3.6.2-1.fc16 has just been pushed to updates.
This update is a significant rebase from the previous version.

Please retest with this kernel, and let us know if your problem has been fixed.

In the event that you have upgraded to a newer release and the bug you reported
is still present, please change the version field to the newest release you have
encountered the issue with.  Before doing so, please ensure you are testing the
latest kernel update in that release and attach any new and relevant information
you may have gathered.

If you are not the original bug reporter and you still experience this bug,
please file a new report, as it is possible that you may be seeing a
different problem. 
(Please don't clone this bug, a fresh bug referencing this bug in the comment is sufficient).

I did not check if the unhandled-irqs-switch-to-polling.patch is still present, but I still do get "IRQ 19 might be stuck.  Polling" on DVB card with  3.6.2-1.fc16.i686.PAE.

kernel-3.6.6-1.fc16 has been submitted as an update for Fedora 16.
https://admin.fedoraproject.org/updates/kernel-3.6.6-1.fc16

I pulled & tested the update from Bodhi, and it fixes this issue; Gave it positive karma.  Thanks!

Package kernel-3.6.6-1.fc16:
* should fix your issue,
* was pushed to the Fedora 16 testing repository,
* should be available at your local mirror within two days.
Update it with:
# su -c 'yum update --enablerepo=updates-testing kernel-3.6.6-1.fc16'
as soon as you are able to, then reboot.
Please go to the following url:
https://admin.fedoraproject.org/updates/FEDORA-2012-17751/kernel-3.6.6-1.fc16
then log in and leave karma (feedback).

kernel-3.6.6-1.fc16 has been pushed to the Fedora 16 stable repository.  If problems still persist, please make note of it in this bug report.