Bug 424581

Created attachment 288331 [details]
repeatedly reads /proc/net/dev and complains about bad data

Created attachment 288351 [details]
results of proc_net_dev_watcher on many machines

I have verified that the problem occurs on kernel 2.6.9-67.ELsmp as well.

To repeat the problem more quickly, you may wish to remove the sleep from
proc_net_dev_watcher.c, and run it on a system with a significant amount of
network traffic.

This bug makes sar and net-snmp return bogus data. I can't do performance
monitoring correctly, nor can I alert based on network error counters. I am
being laughed at by Windows admins, who's performance counters work correctly.

I have repeated this on hundreds of 64-bit systems running 2.6.9-42 and 2.6.9-67.

I beg others who have 64-bit systems running RedHat ES4 to compile and run my
simple test case. (other platforms are of course welcome as it may help narrow
things down.) The only catch is that it may take hours (on average) for a single
machine to reproduce the error.

Download the proc_net_dev_watcher.c attachment.
gcc -Wall -O2 -o proc_net_dev_watcher proc_net_dev_watcher.c
nohup ./proc_net_dev_watcher < /dev/null >& /tmp/proc_net_dev_watcher.log &

If it produces output in /tmp/proc_net_dev_watcher.log, you have repeated the
bug. The contents of /proc/net/dev, read in one read() call, is the proof.

You may wish to remove the "usleep(100000);" line and generate some network
traffic to increase the odds that it will happen.

This will be fixed in the upcoming RHEL4 update.  Please verify with my test
kernels located here:

http://people.redhat.com/agospoda/

or any beta 4.7 kernels that exist.



*** This bug has been marked as a duplicate of 430576 ***

The problem still exists with 2.6.9-69.EL.gtest.43smp. This is a separate issue.

Here are two consecutive /proc/net/dev reads, from the attached proc_net_dev_watcher

warn: counter rx_bytes on bond1 delta was 172752163853975
1209833008.751634
Inter-|   Receive                                                |  Transmit
 face |bytes    packets errs drop fifo frame compressed multicast|bytes   
packets errs drop fifo colls carrier compressed
    lo:84448910  331481    0    0    0     0          0         0 84448910 
331481    0    0    0     0       0          0
 bond0:713534965513 698989252    0    0    0     0          0         0
713484683532 698545505    0    0    0     0       0          0
 bond1:21444908   84386    0    0    0     0          0         0 21508295  
84452    0    0    0     0       0          0
  eth3:10725747   42193    0    0    0     0          0         0 10746131  
42226    0    0    0     0       0          0
  eth2:34757343  200233    0    0    0     0          0         0        0     
 0    0    0    0     0       0          0
  eth0:713500208170 698789019    0    0    0     0          0         0
713484683532 698545505    0    0    0     0       0          0
  eth1:10719161   42193    0    0    0     0          0         0 10762164  
42226    0    0    0     0       0          0

1209833008.853638
Inter-|   Receive                                                |  Transmit
 face |bytes    packets errs drop fifo frame compressed multicast|bytes   
packets errs drop fifo colls carrier compressed
    lo:84448910  331481    0    0    0     0          0         0 84448910 
331481    0    0    0     0       0          0
 bond0:713534965513 698989252    0    0    0     0          0         0
713484683532 698545505    0    0    0     0       0          0
 bond1:172752185298883 10830517    0    0    0     0          0         0
21487911   84452    0    0    0     0       0          0
  eth3:172752174579722 10788324    0    0    0     0          0         0
10725747   42226    0    0    0     0       0          0
  eth2:34757343  200233    0    0    0     0          0         0        0     
 0    0    0    0     0       0          0
  eth0:713500208170 698789019    0    0    0     0          0         0
713484683532 698545505    0    0    0     0       0          0
  eth1:10719161   42193    0    0    0     0          0         0 10762164  
42226    0    0    0     0       0          0

Sorry I closed this one too quickly on you.  We fixed a bug in rhel4 and rhel5
that dealt with totals from the bonding driver being invalid, but this appears
to be specifically from the NIC (at least in the example you've got above).  It
appears that:

bond0 contains eth0 and eth2
bond1 contains eth1 and eth3

The totals from the bonds look fine, but it seems like eth3's stats changed
drastically:

first run:
eth3:         10725747     42193
second run:
eth3:  172752174579722  10788324

This seems to account for the difference in your bonding stats.

Can you tell me more about your system, what type of NICs you are using (at
least an lspci from the system would be helpful)?

It doesn't seem realistic to expect approx 135Tb of traffic in 100ms on those
interfaces, so I'm guessing we've got a driver or hardware stats bug. :-)

I don't want to assume too much, but when looking at a few of the log files
attached it appears that this is mostly an ethernet interface statistics bug
rather than one that appears to sum the bonding stats incorrectly.  If you
happen to notice bonding totals that are invalid when running any of my gtest
kernels please let me know, but I'm going to examine the individual ethernet
devices and drivers first.

All systems are running the tg3 or bnx2 driver (all are HP DL380 or DL360
G3/G4/G5, HP DL385 G1 or DL585 G1). I didn't bother to check that bonding totals
add up since I don't think there was suspicion of that being the problem here,
but I'll modify my test program for any checks that might be useful.

32-bit systems (e.g. the HP DL380 G3s) seem to be not affected, only 64-bit
systems seem to be. But I have a lower population of 32-bit systems and they
typically do less network traffic, so it could be coincidence.

Here's an example lspci -v output for one of these interfaces.
03:00.0 Ethernet controller: Broadcom Corporation NetXtreme II BCM5708 Gigabit
Ethernet (rev 12)
        Subsystem: Hewlett-Packard Company: Unknown device 7038
        Flags: bus master, 66Mhz, medium devsel, latency 64, IRQ 74
        Memory at f8000000 (64-bit, non-prefetchable) [size=32M]
        Capabilities: [40] PCI-X non-bridge device.
        Capabilities: [48] Power Management version 2
        Capabilities: [50] Vital Product Data
        Capabilities: [58] Message Signalled Interrupts: 64bit+ Queue=0/0 Enable+

Chuck, thanks for the feedback.  I'll take a look at those drivers (tg3 and
bnx2) and see if there is anything that might be causing this.

This bug is bothering  me for a looooooong time.
I find that it's bogus just in the bnx2_get_stats() call.

So you see invalid stats on bnx2-based cards sometimes?  I haven't personally seen it, but looking at the code I can see how it might happen.  Can you describe what you see when you are seeing what appear to be invalid stats?

(In reply to comment #11)
> So you see invalid stats on bnx2-based cards sometimes?  I haven't personally
> seen it, but looking at the code I can see how it might happen.  Can you
> describe what you see when you are seeing what appear to be invalid stats?

It has been fixed~
I applied this patch in kernel 2.6.9-34 and it seems ok for me.   
The upcoming RH 4.x should apply this patch.

See linux-2.6 tree 
git log -p 02537b0676930b1bd9aff2139e0e645c79986931


commit 02537b0676930b1bd9aff2139e0e645c79986931
Author: Michael Chan <mchan>
Date:   Mon Jun 4 21:24:07 2007 -0700

    [BNX2]: Fix occasional counter corruption on 5708.
    
    The statistics block DMA on 5708 can be messed up occasionally on the
    average of about once per hour.  If the user is reading the counters
    within one second after the corruption, the counters will be all
    messed up.  One second later, the counters will be ok again until the
    next corruption occurs.
    
    The workaround is to disable the periodic statistics DMA.  Instead,
    we manually trigger the DMA once a second in bnx2_timer().  This
    manual trigger of the DMA avoids the problem.
    
    As a consequence, we can only allow 0 or 1 second settings for
    ethtool -C statistics block.
    
    Thanks to Jean-Daniel Pauget <jd> and
    CaT <cat.au> for reporting this rare problem.
    
    Signed-off-by: Michael Chan <mchan>
    Acked-by: Jeff Garzik <jeff>
    Signed-off-by: David S. Miller <davem>

Terry, That patch is already in our upcoming rhel5 update and it will get pulled into 4.8 as part of bug 452883.  Feel free to add yourself to the CC-list to that bug if you like.

I also see this problem on the loopback interface, with kernel 2.6.18-92.

Here's some example output from proc_net_dev_watcher (source attached). Note the two timestamps 100ms apart, each followed by the full /proc/net/dev contents with a gigantic delta for all of the counters on lo.

I had to run this program for about an hour on 100 machines to catch 10 occurrences of this.

If attempting to repeat this, it may happen faster if you take the usleep() out of proc_net_dev_watcher.c and generate some localhost traffic. (my 100-system test group were production systems with a nontrivial amount of localhost traffic)

warn: counter rx_bytes on lo delta was 1620963998645
1232656157.416785
Inter-|   Receive                                                |  Transmit
 face |bytes    packets errs drop fifo frame compressed multicast|bytes    packets errs drop fifo colls carrier compressed
    lo:2550068943552 3527004034    0    0    0     0          0         0 2550068943552 3527004034    0    0    0     0       0          0
  eth0:3458672361860 3760436791    0    0    0     0          0 1215017822 1633785213814 1864773066    0    0    0     0       0          0
  eth1:1308425220 9393943    0    0    0     0          0        20     4435      20    0    0    0     0       0          0
  sit0:       0       0    0    0    0     0          0         0        0       0    0    0    0     0       0          0
 bond0:3459980787080 3769830734    0    0    0     0          0 1215017842 1633785218249 1864773086    0    0    0     0       0          0

1232656157.517763
Inter-|   Receive                                                |  Transmit
 face |bytes    packets errs drop fifo frame compressed multicast|bytes    packets errs drop fifo colls carrier compressed
    lo:4171032942197 6763066679    0    0    0     0          0         0 4926815958089 6763066679    0    0    0     0       0          0
  eth0:3458672361860 3760436791    0    0    0     0          0 1215017822 1633785213814 1864773066    0    0    0     0       0          0
  eth1:1308425592 9393946    0    0    0     0          0        20     4435      20    0    0    0     0       0          0
  sit0:       0       0    0    0    0     0          0         0        0       0    0    0    0     0       0          0
 bond0:3459980787452 3769830737    0    0    0     0          0 1215017842 1633785218249 1864773086    0    0    0     0       0          0

Chuck, I'm trying to wrap up my RHEL4 bugs, and it sounds like the problems you have in bnx2 are going to be fixed for in our upcoming RHEL4.8 kernels.  Do you still see problems with tg3?  If so can you test with my test kernels to see if the latest update fixes it?  You can download them here:

http://people.redhat.com/agospoda/#rhel4

I suspect these kernels will resolve both your bnx2 and tg3 issues since they contain the patch in comment #12 (to address the bnx2 issue) as well as the following patch (to address the tg3 issue):

commit 816f8b86621000fc82e16ae5f172164de761d5eb
Author: Stefan Buehler <stbuehler>
Date:   Fri Aug 15 14:10:54 2008 -0700

    tg3: fix 64 bit counter for ethtool stats
    
    Ethtool stats are 64-bits in length.  net_device_stats members are
    unsigned long types.  When gathering information for
    a get_ethtool_stats call, the driver will call a driver-private,
    inlined get_stat64() function, which returns an unsigned long value.
    This call will inadvertently mask off the upper 32-bits of a stat on
    32-bit machines.

Thanks for your help testing this.

The patch in comment #12 that resolves this is included in RHEL4.8.  Closing as a dup of the bug used for that update.

*** This bug has been marked as a duplicate of bug 452883 ***