Rate limit smsc95xx: kevent 2 messages

[MilhouseVH]

Running Transmission on a 512MB Pi with the latest Raspbian 2012-10-28, and with two concurrent torrent downloads the Pi is guaranteed to generate a swapper page allocation failure (issue #153).

The result of this allocation failure, and the focus of this issue, is that a mass of smsc95xx: kevent 2 messages are spammed to syslog AND kern.log at the rate of almost a thousand per second - that's almost 2 thousand messages being logged per second. Sometimes it's not even necessary for an allocation failure to occur for these messages to be generated, as I've also seen them - in reduced quantities - with just a single torrent download.

In a 20 minute period, I've just had 175,932 kevent 2 messages logged to syslog, and another 175,932 smsc95xx: kevent 2 messages logged to kern.log.

This is ridiculously excessive so these messages need to be rate limited (though finding a solution to issue #153 would be pretty mega!)

Example messages that should be rate limited:

Nov  7 00:13:46 raspberrypi kernel: [264450.487462] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:13:46 raspberrypi kernel: [264450.487479] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:13:46 raspberrypi kernel: [264450.487494] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Nov  7 00:13:46 raspberrypi kernel: [264450.487509] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
etc.

Typical RX/TX rates when these errors occur are low, eg. RX 1.5MBytes/second and TX 100KBytes/second. Available free memory is in excess of 350MB.

Forum discussion link

[steveglen]

kevent 2 (EVENT_RX_MEMORY) is produced by usbnet in rx_submit when it fails to allocate memory for an RX packet buffer, so this is related to issue #153.

Note that when turning off turbo_mode (as recommended for issue #153) the buffer size we allocate for USB RX gets a lot smaller (18944 -> 2048 bytes), so it's easier for the kernel to find a buffer that size. I suspect that disabling turbo_mode will stop the generation of these kevents in the first place.

These messages indicate usbnet may have not handled its event, as the event has occurred during processing of the last one. I agree that flooding the kernel log isn't the best approach to take here, so we should rate limit this message. We should also look into fixing the underlying issue - usbnet's deferred event handler design. There's a comment in there to say "hope the failure is rare" - it turns out it's not so rare.

[popcornmix]

I've pulled in Steve's patch from upstream. Messages are now rate limited.

[MilhouseVH]

Many thanks to you both!