Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756822AbZC1Jzj (ORCPT ); Sat, 28 Mar 2009 05:55:39 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1753738AbZC1Jz1 (ORCPT ); Sat, 28 Mar 2009 05:55:27 -0400 Received: from smtp-out-44.synserver.de ([217.119.50.44]:1589 "HELO smtp-out-44.synserver.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1753440AbZC1JzV (ORCPT ); Sat, 28 Mar 2009 05:55:21 -0400 X-SynServer-TrustedSrc: 1 X-SynServer-AuthUser: markus@trippelsdorf.de X-SynServer-PPID: 11766 Date: Sat, 28 Mar 2009 10:55:14 +0100 From: Markus Trippelsdorf To: Ilpo =?iso-8859-1?Q?J=E4rvinen?= Cc: Netdev , LKML , corbet@lwn.net Subject: Re: WARNING: at net/ipv4/tcp_input.c:2927 tcp_ack+0xd55/0x1991() Message-ID: <20090328095514.GA2599@gentoox2.trippelsdorf.de> References: <20090327211202.GA10014@gentoox2.trippelsdorf.de> <20090328045056.GA2394@gentoox2.trippelsdorf.de> MIME-Version: 1.0 Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 21905 Lines: 443 On Sat, Mar 28, 2009 at 10:29:58AM +0200, Ilpo J?rvinen wrote: > On Sat, 28 Mar 2009, Markus Trippelsdorf wrote: > > > On Sat, Mar 28, 2009 at 01:05:09AM +0200, Ilpo J?rvinen wrote: > > > On Fri, 27 Mar 2009, Markus Trippelsdorf wrote: > > > > > > > I'm running the latest git kernel (2.6.29-03321-gbe0ea69) and I've got > > > > this warning twice in the last few hours.: > > > > > > What did you run previously? > > > > 2.6.29 > > Ok, just wanted to confirm it wasn't some from 2.6.veryold transition, > where veryold didn't even have tracking for that invariant. > > > > > Mar 27 21:37:00 [kernel] ------------[ cut here ]------------ > > > > Mar 27 21:37:00 [kernel] WARNING: at net/ipv4/tcp_input.c:2927 tcp_ack+0xd55/0x1991() > > > > > > This one may or may not be a new one... Starting from the point when the > > > warning was added it has been seen and some of those miscounts got tracked > > > down but there is still something remaining (and that has been the state > > > for couple of version already). It seems to require some particularly hard > > > to reproduce network behavior people usually hit once in a lifetime. > > > However, those miscount alone should not cause crashes, stalled TCP at > > > worst but even that is quite unlikely to happen if fackets_out was not > > > counted right. > > > > The only unusual thing in my setup is that I use two Internet providers > > at the same time: > > > > # ip route show > > 192.168.1.0/24 dev eth1 proto kernel scope link src 192.168.1.2 > > 192.168.0.0/24 dev eth0 proto kernel scope link src 192.168.0.2 > > 127.0.0.0/8 via 127.0.0.1 dev lo > > default equalize > > nexthop via 192.168.1.1 dev eth1 weight 10 > > nexthop via 192.168.0.1 dev eth0 weight 1 > > Right. But I meant even larger picture, ie., the whole path(s) with the > remote hosts you're communicating with. > > > > > The machine hangs afterwards. > > > > > > Is it really related to the warning for sure? I find it hard to > > > believe... > > > > The machine is normally running stable for days. Switching back to 2.6.29 > > solves the problem... > > Sure, but does is hang right after printing that warning or much later on, > e.g., one minute is already a very long time for the crash to be related > to that warning... Even 5 seconds is a long time but I'd immediately say > it's not related then :-). I really can't tell you. In both occurrences of the warning the machine was already unusable when I noticed. I then rebooted and the last entry in the logs was that warning. > > So you never saw this warning before within 2.6.29 or 2.6.28-26 timeframe? Thats right. > Anyway, if it turns out that the warning is unrelated to the crash and at > the same time seems that you can so easily reproduce the warning it is > worth of tracking its cause down as well but lets track the crash down > first and see what to do once it is solved. > > > > We even fixed that miscount for you when the warning was printed out (and > > > the miscount alone wouldn't be able to cause crash anyway). Obviously > > > there could something that got broken but reading through all post 2.6.29 > > > tcp material doesn't reveal anything particularly suspicious or even > > > tricky... Only one thing that is remotely related to the warning that gets > > > printed out is d3d2ae454501a4dec360995649e1b002a2ad90c5 but even that has > > > very strong foundation as it does not have any potential to introduce > > > stale references, rest of the effects would be just stalled tcp connection > > > at worst. > > > > > > Please add some debugging things, at least lockdep (CONFIG_PROVE_LOCKING) > > > and soft lockup detector (CONFIG_DETECT_SOFTLOCKUP) to find out if we can > > > get some info about the actual place of hang, some other debug things > > > might also end up being useful. > > > > Ok, will try this later today and report back. (It takes ~1 hour to > > reproduce the problem with a big torrent download). > > Thanks, there are plenty of other changes in the range in question > already: > > ijjarvin@pointhope:~/linux/mainline$ git-diff --stat v2.6.29..be0ea69 | > tail -n 1 > 2871 files changed, 216209 insertions(+), 131463 deletions(-) > ijjarvin@pointhope:~/linux/mainline$ > > ...So the crash could well be because of something else. It's probably > worth of tracking bug fixes by keeping up with mainline and if crashes > vanish we know that somebody solved the (same) problem. Yes, you might be right, because running with CONFIG_PROVE_LOCKING and CONFIG_DETECT_SOFTLOCKUP enabled points to a possible bug in the BKL removal patches (fasync) by Jonathan Corbet. (I wasn't able so far to reproduce the original WARNING.) Here is one example: ========================================================= [ INFO: possible irq lock inversion dependency detected ] 2.6.29-03321-gbe0ea69 #7 --------------------------------------------------------- swapper/0 just changed the state of lock: (fasync_lock){..+.}, at: [] kill_fasync+0x24/0x45 but this lock took another, hard-irq-unsafe lock in the past: (&f->f_lock){--..} and interrupts could create inverse lock ordering between them. other info that might help us debug this: 3 locks held by swapper/0: #0: (&dev->event_lock){++..}, at: [] input_event+0x3a/0x79 #1: (rcu_read_lock){..--}, at: [] input_pass_event+0x0/0xc9 #2: (rcu_read_lock){..--}, at: [] evdev_event+0x0/0xee the first lock's dependencies: -> (fasync_lock){..+.} ops: 0 { initial-use at: [] __lock_acquire+0x6b4/0x1552 [] lock_acquire+0x55/0x71 [] _write_lock_irq+0x32/0x41 [] fasync_helper+0x52/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff in-hardirq-R at: [] 0xffffffffffffffff } ... key at: [] fasync_lock+0x18/0x30 -> (&f->f_lock){--..} ops: 0 { initial-use at: [] __lock_acquire+0x6b4/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] fasync_helper+0xce/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff softirq-on-W at: [] __lock_acquire+0x69f/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff hardirq-on-W at: [] __lock_acquire+0x67e/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff } ... key at: [] __key.20253+0x0/0x8 ... acquired at: [] __lock_acquire+0x11ed/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] fasync_helper+0xce/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff the second lock's dependencies: -> (&f->f_lock){--..} ops: 0 { initial-use at: [] __lock_acquire+0x6b4/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] fasync_helper+0xce/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff softirq-on-W at: [] __lock_acquire+0x69f/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff hardirq-on-W at: [] __lock_acquire+0x67e/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff } ... key at: [] __key.20253+0x0/0x8 stack backtrace: Pid: 0, comm: swapper Not tainted 2.6.29-03321-gbe0ea69 #7 Call Trace: [] print_irq_inversion_bug+0x174/0x182 [] check_usage_forwards+0x96/0x9e [] mark_lock+0x43a/0x955 [] __lock_acquire+0x5d9/0x1552 [] ? __lock_acquire+0x132e/0x1552 [] ? trace_hardirqs_off+0xd/0xf [] lock_acquire+0x55/0x71 [] ? kill_fasync+0x24/0x45 [] _read_lock+0x2f/0x3e [] ? kill_fasync+0x24/0x45 [] kill_fasync+0x24/0x45 [] evdev_pass_event+0x66/0x6f [] evdev_event+0x8e/0xee [] ? evdev_event+0x0/0xee [] input_pass_event+0x8a/0xc9 [] ? input_pass_event+0x0/0xc9 [] input_handle_event+0x355/0x364 [] input_event+0x5b/0x79 [] hidinput_hid_event+0x251/0x27b [] hid_process_event+0xa8/0xdc [] hid_report_raw_event+0x36e/0x382 [] hid_input_report+0xc8/0xdc [] hid_irq_in+0x94/0x185 [] usb_hcd_giveback_urb+0x60/0x94 [] uhci_giveback_urb+0x112/0x1a2 [] uhci_scan_schedule+0x5ab/0x86d [] uhci_irq+0x126/0x142 [] usb_hcd_irq+0x38/0x8e [] handle_IRQ_event+0x64/0x99 [] handle_fasteoi_irq+0x8b/0xcb [] do_IRQ+0x69/0xd6 [] ret_from_intr+0x0/0xf [] lock_hrtimer_base+0x25/0x4b [] ? __atomic_notifier_call_chain+0x0/0x86 [] ? default_idle+0x32/0x4c [] ? default_idle+0x30/0x4c [] cpu_idle+0x57/0x9a And another one: ========================================================= [ INFO: possible irq lock inversion dependency detected ] 2.6.29-03321-gbe0ea69 #7 --------------------------------------------------------- X/2567 just changed the state of lock: (fasync_lock){..+.}, at: [] kill_fasync+0x24/0x45 but this lock took another, hard-irq-unsafe lock in the past: (&f->f_lock){--..} and interrupts could create inverse lock ordering between them. other info that might help us debug this: 3 locks held by X/2567: #0: (&dev->event_lock){++..}, at: [] input_event+0x3a/0x79 #1: (rcu_read_lock){..--}, at: [] input_pass_event+0x0/0xc9 #2: (rcu_read_lock){..--}, at: [] evdev_event+0x0/0xee the first lock's dependencies: -> (fasync_lock){..+.} ops: 0 { initial-use at: [] __lock_acquire+0x6b4/0x1552 [] lock_acquire+0x55/0x71 [] _write_lock_irq+0x32/0x41 [] fasync_helper+0x52/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff in-hardirq-R at: [] 0xffffffffffffffff } ... key at: [] fasync_lock+0x18/0x30 -> (&f->f_lock){--..} ops: 0 { initial-use at: [] __lock_acquire+0x6b4/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] fasync_helper+0xce/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff softirq-on-W at: [] __lock_acquire+0x69f/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff hardirq-on-W at: [] __lock_acquire+0x67e/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff } ... key at: [] __key.20253+0x0/0x8 ... acquired at: [] __lock_acquire+0x11ed/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] fasync_helper+0xce/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff the second lock's dependencies: -> (&f->f_lock){--..} ops: 0 { initial-use at: [] __lock_acquire+0x6b4/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] fasync_helper+0xce/0x10f [] tty_fasync+0x5a/0x10c [] tty_release_dev+0x60/0x4c0 [] tty_release+0x19/0x24 [] __fput+0xe3/0x191 [] fput+0x18/0x1a [] filp_close+0x63/0x6d [] sys_close+0xa8/0xe2 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff softirq-on-W at: [] __lock_acquire+0x69f/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff hardirq-on-W at: [] __lock_acquire+0x67e/0x1552 [] lock_acquire+0x55/0x71 [] _spin_lock+0x2c/0x3b [] sys_fcntl+0x2c2/0x394 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff } ... key at: [] __key.20253+0x0/0x8 stack backtrace: Pid: 2567, comm: X Not tainted 2.6.29-03321-gbe0ea69 #7 Call Trace: [] print_irq_inversion_bug+0x174/0x182 [] check_usage_forwards+0x96/0x9e [] mark_lock+0x43a/0x955 [] __lock_acquire+0x5d9/0x1552 [] ? __lock_acquire+0x132e/0x1552 [] lock_acquire+0x55/0x71 [] ? kill_fasync+0x24/0x45 [] _read_lock+0x2f/0x3e [] ? kill_fasync+0x24/0x45 [] kill_fasync+0x24/0x45 [] evdev_pass_event+0x66/0x6f [] evdev_event+0x8e/0xee [] ? evdev_event+0x0/0xee [] input_pass_event+0x8a/0xc9 [] ? input_pass_event+0x0/0xc9 [] input_handle_event+0x355/0x364 [] input_event+0x5b/0x79 [] hidinput_hid_event+0x251/0x27b [] hid_process_event+0xa8/0xdc [] hid_report_raw_event+0x36e/0x382 [] hid_input_report+0xc8/0xdc [] hid_irq_in+0x94/0x185 [] usb_hcd_giveback_urb+0x60/0x94 [] uhci_giveback_urb+0x112/0x1a2 [] uhci_scan_schedule+0x5ab/0x86d [] uhci_irq+0x126/0x142 [] usb_hcd_irq+0x38/0x8e [] handle_IRQ_event+0x64/0x99 [] handle_fasteoi_irq+0x8b/0xcb [] do_IRQ+0x69/0xd6 [] ret_from_intr+0x0/0xf [] ? delay_tsc+0x14/0x3f [] ? __delay+0xa/0xc [] ? __const_udelay+0x43/0x45 [] ? radeon_freelist_get+0xed/0x12f [] ? radeon_cp_buffers+0xec/0x167 [] ? drm_ioctl+0x1af/0x292 [] ? radeon_cp_buffers+0x0/0x167 [] ? drm_ioctl+0x1f9/0x292 [] ? _spin_unlock_irq+0x2b/0x31 [] ? vfs_ioctl+0x6a/0x82 [] ? finish_task_switch+0x7f/0xde [] ? do_vfs_ioctl+0x463/0x4a4 [] ? thread_return+0x3d/0xdc [] ? sysret_check+0x27/0x62 [] ? sys_ioctl+0x42/0x65 [] ? system_call_fastpath+0x16/0x1b -- Markus -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/