Created attachment 531597 [details]
dmesg output

I get this same error with Fedora 16, irqbalance-1.0-4.fc16.x86_64 and kernel-3.1.0-7.fc16.x86_64. IRQ 43, AHCI.

 ahci 0000:00:1f.2: version 3.0
 ahci 0000:00:1f.2: PCI INT B -> GSI 19 (level, low) -> IRQ 19
 ahci 0000:00:1f.2: irq 43 for MSI/MSI-X

 43:       [snip]   PCI-MSI-edge      ahci

(In reply to comment #0)
> Version-Release number of selected component (if applicable):
> irqbalance.i686              2:0.56-1.fc14           @fedora/$releasever
> 
> Linux localhost.localdomain 2.6.35.14-100.fc14.i686 #1 SMP Fri Oct 21 19:14:19
> UTC 2011 i686 i686 i386 GNU/Linux

Correct component version-release (should be from F16).
irqbalance-1.0-4.fc16.i686

Linux version 3.1.0-7.fc16.i686 (mockbuild.fedoraproject.org) (gcc version 4.6.2 20111027 (Red Hat 4.6.2-1) (GCC) ) #1 SMP Tue Nov 1 21:00:16 UTC 2011

I can confirm this bug

This bug hits me too

[    1.635877] ahci 0000:00:1f.2: version 3.0
[    1.635889] ahci 0000:00:1f.2: PCI INT A -> GSI 19 (level, low) -> IRQ 19
[    1.636084] ahci 0000:00:1f.2: irq 45 for MSI/MSI-X
[    1.636093] ahci 0000:00:1f.2: controller can't do SNTF, turning off CAP_SNTF
[    1.636312] ahci 0000:00:1f.2: AHCI 0001.0200 32 slots 6 ports 3 Gbps 0x3f impl RAID mode
[    1.636599] ahci 0000:00:1f.2: flags: 64bit ncq pm led clo pio slum part ccc ems 
[    1.636885] ahci 0000:00:1f.2: setting latency timer to 64

This bug seems to be fixed in kernel 3.1.1 and later, at least for me. The relevant entries are now present in sysfs and irqbalance finds them.

Davids correct, MSI classification support went it to the f16 kernel with commit 5f42e49c37c91b4993ba29d8248d9b206bd21094, which maps to kernel 3.1.1.  Interrupts will still be classified, irqbalance just won't be able to identify these interrupts as belonging to the same device, and will rely on heuristics that aren't reliable.  Thats all the warning means.

I'm seeing this on one of my systems, and by instrumenting a copy of irqbalance, I think I've localized it to one of the sysfs "msi_irqs" directory being created later than the start-up of the irqbalance process.  I've seen the directory in question bearing a timestamp of as much as 4 minutes later than the "irq" file in the same directory.  So, when the irqbalance program scans the /proc/interrupts directory, it finds a line with MSI, but it had not classified that IRQ as MSI when it started up, hence the 3 lines of system messages reported above.

The device in question uses the ominously-named "forcedeth" driver; it's the Ethernet interface on an MCP61 motherboard (Nvidia chip-set, AMD processor).  Here's its info from lspci:

00:07.0 Bridge: nVidia Corporation MCP61 Ethernet (rev a2)
00:07.0 0680: 10de:03ef (rev a2)

I've not been able to link the msi_irqs creation time to any events in the system log.

Here's some info from the relevant sysfs directory; the start-up of irqbalance was disabled in this case:

$ pwd
/sys/bus/pci/devices/0000:00:07.0
$ stat msi_irqs irq
  File: `msi_irqs'
  Size: 0         	Blocks: 0          IO Block: 4096   directory
Device: eh/14d	Inode: 19087       Links: 3
Access: (0755/drwxr-xr-x)  Uid: (    0/    root)   Gid: (    0/    root)
Context: system_u:object_r:sysfs_t:s0
Access: 2012-07-12 14:54:50.461843288 -0700
Modify: 2012-07-12 14:54:50.461843288 -0700
Change: 2012-07-12 14:54:50.461843288 -0700
 Birth: -
  File: `irq'
  Size: 4096      	Blocks: 0          IO Block: 4096   regular file
Device: eh/14d	Inode: 2586        Links: 1
Access: (0444/-r--r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Context: system_u:object_r:sysfs_t:s0
Access: 2012-07-12 14:54:05.585000000 -0700
Modify: 2012-07-12 14:54:05.585000000 -0700
Change: 2012-07-12 14:54:05.585000000 -0700
 Birth: -
$ 

I wonder if the reporters above had a system that behaved similarly.

Where should I take it from here?

The next update of irqbalance should have commit 1523a7830cb2670cb531a5fdea86885eaa648eaf in place, which will force a rescan when new irqs appear.

Neil, I'm using a "git clone" that I got on July 11th; I don't know how to check to see if it has that commit or not, but it does appear to have code that checks for IRQs that newly appear in /proc/interrupts.

On my affected system, the forcedeth driver enables MSI after the first scan of /proc/interrupts, but before the second.  I think this is why it wasn't found in sysfs when irqbalance started.  Plus, it didn't actually rescan (details below).

After some exploring, I think I've found some slight changes to the way "cycle_count" is manipulated that help considerably, at least in the case of my issue.

Here are the changes I've tried, in my private copy of file irqbalance.c, function main:

* In the "while (keep_going)" loop, moved the increment of cycle_count from the bottom to the top of the loop, so that it have the value 1 when parse_proc_interrupts() is called after the very first 10-second sleep.  As my MSI IRQ shows up during this interval, this allows its recognition as "new" by parse_proc_interrupts().

* Within that loop, in the code for "if (need_rescan)", moved the clear of cycle_count to the top of the block, rather than the bottom.  This seems to prevent a recurrent rescan, although I'm not precisely sure why.

* Also in the code for "if (need_rescan)", increment cycle_count just before the call to clear_work_stats().  This should allow noticing a new IRQ that might appear during the sleep (in the "if" block) that just finished, although I don't have a way of testing that.

These steps result in a rescan being done at the right time, whereas it wasn't before, as cycle_count was zero when the new IRQ was detected.  It now rebuilds the IRQ information from the sysfs directory.  When it does so, it has always found the msi_irqs directory and handled it properly, so far at least.  Given this scenario, the syslog warning about the MSI interrupt not being found in sysfs seems a bit harsh, because it hasn't had a chance to look for it yet.  But it does find it when it looks, and things look fine after that point.

As I don't know how to assess the impact of these changes on anything else in irqbalance, I'd be happy to test anything that incorporates these changes on a more formal basis.  Also, if you have any advice on how to test it without re-booting; maybe rmmod'ing the driver and putting it back would work for that?

Thanks,  Stan

I don't think you've actually identified the problem here.  If forcedeth actually allocated its msi interrupts after the first proc/interrupts scan but before the second, irqbalance would just pick up the existance of the new interrupts on the third scan anyway, and all should be well.  You're changes sound like they just make your problem go away, but don't actually fix anything (they actually sound like they're going to break the initial interrupt load evaluation, too).  Regardless, if you think you have a bug, please open a new bug report, either here or at the upstream project, so we can identify what your actual problem is (as this bz is currently closed, and it sounds like you may be having a different problem)

Neil, you raise some good points there.  I went back to the stock version (irqbalance-1.0.3-4.fc17.x86_64), made a little systemd unit file to run it in debug mode with the non-forking "Type=simple", disabling the stock unit file, and enabling mine.  The journalctl command let me look at the trapped stdout from stock irqbalance, started along with everything else in the system.  Strictly by the IRQ numbers, the periodic "Package" dumps never show the MSI IRQ (43) but always show the original standard IRQ (22) picked up during the original scan.  This was with the irqbalance binary as distributed, aside from running it with the --debug flag.

Is this sufficient basis to make a new bug report with, or does the irqbalance-1.0.3-4.fc17.x86_64 not yet have the new re-scan feature?

Thanks,
Stan

commit 1523a7830cb2670cb531a5fdea86885eaa648eaf isn't present in irqbalance-1.0.3-4.fc17.x86_64.  Please build the most recent irqbalance from code.google.com, run it on the command line with --debug, and post the output in a new bug with the description of the problem at the code.google.com site.  Thank you.

Neil, I did as you suggested, and opened new issue 36 at irqbalance's home on code.google.com.

I see it, I'll take a look in the am.  Thanks!