From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751543Ab1GTIFd (ORCPT ); Wed, 20 Jul 2011 04:05:33 -0400 Received: from smtp-out3.tiscali.nl ([195.241.79.178]:38439 "EHLO smtp-out3.tiscali.nl" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751080Ab1GTIF3 (ORCPT ); Wed, 20 Jul 2011 04:05:29 -0400 Subject: Re: recursive locking: epoll. From: Paul Bolle To: Dave Jones Cc: Linux Kernel , davidel@xmailserver.org Date: Wed, 20 Jul 2011 10:05:23 +0200 In-Reply-To: <20110715210420.GA22551@redhat.com> References: <4E1FF63F.4040704@gmail.com> <20110715210420.GA22551@redhat.com> Content-Type: text/plain; charset="UTF-8" X-Mailer: Evolution 3.1.3 (3.1.3-1.fc16) Content-Transfer-Encoding: 7bit Message-ID: <1311149128.2098.10.camel@t41.thuisdomein> Mime-Version: 1.0 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Fri, 2011-07-15 at 17:04 -0400, Dave Jones wrote: > We just had a Fedora user report this lockdep trace. 0) Does this have a bugzilla.redhat.com number? > ============================================= > [ INFO: possible recursive locking detected ] > 3.0-0.rc7.git0.1.fc16.i686 #1 > --------------------------------------------- > systemd-logind/651 is trying to acquire lock: > (&ep->mtx){+.+.+.}, at: [] ep_scan_ready_list+0x32/0x154 > > but task is already holding lock: > (&ep->mtx){+.+.+.}, at: [] sys_epoll_ctl+0x103/0x481 > > other info that might help us debug this: > Possible unsafe locking scenario: > > CPU0 > ---- > lock(&ep->mtx); > lock(&ep->mtx); > > *** DEADLOCK *** > > May be due to missing lock nesting notation > > 2 locks held by systemd-logind/651: > #0: (epmutex){+.+.+.}, at: [] sys_epoll_ctl+0xbe/0x481 > #1: (&ep->mtx){+.+.+.}, at: [] sys_epoll_ctl+0x103/0x481 > > stack backtrace: > Pid: 651, comm: systemd-logind Not tainted 3.0-0.rc7.git0.1.fc16.i686 #1 > Call Trace: > [] ? printk+0x2d/0x2f > [] __lock_acquire+0x811/0xb63 > [] ? sched_clock+0x8/0xb > [] ? sched_clock_local+0x10/0x18b > [] ? ep_scan_ready_list+0x32/0x154 > [] lock_acquire+0xad/0xe4 > [] ? ep_scan_ready_list+0x32/0x154 > [] __mutex_lock_common+0x49/0x2ee > [] ? ep_scan_ready_list+0x32/0x154 > [] ? __might_sleep+0x29/0xfb > [] ? mark_lock+0x26/0x1f2 > [] mutex_lock_nested+0x43/0x49 > [] ? ep_scan_ready_list+0x32/0x154 > [] ep_scan_ready_list+0x32/0x154 > [] ? ep_remove+0x9b/0x9b > [] ep_poll_readyevents_proc+0x14/0x16 > [] ep_call_nested.constprop.2+0x6d/0x9a > [] ? ep_scan_ready_list+0x154/0x154 > [] ep_eventpoll_poll+0x45/0x55 > [] sys_epoll_ctl+0x1ff/0x481 > [] ? ep_send_events_proc+0xd5/0xd5 > [] syscall_call+0x7/0xb 1) It seems I just ran into that deadlock too (on a Fedora Rawhide system, running a vanilla 3.0-0.rc7). I tried to capture it with a small digital camera, but using that camera for screenshots is apparently beyond my skills. (I could try capturing this message over a serial line, if needed.) 2) Luckily, I also hit a related warning rebooting into v2.6.39, which I could just cut and paste from dmesg's output: ============================================= [ INFO: possible recursive locking detected ] 2.6.39-0.local9.fc16.i686 #1 --------------------------------------------- systemd-logind/807 is trying to acquire lock: (&ep->mtx){+.+.+.}, at: [] ep_scan_ready_list+0x32/0x154 but task is already holding lock: (&ep->mtx){+.+.+.}, at: [] sys_epoll_ctl+0x103/0x481 other info that might help us debug this: 2 locks held by systemd-logind/807: #0: (epmutex){+.+.+.}, at: [] sys_epoll_ctl+0xbe/0x481 #1: (&ep->mtx){+.+.+.}, at: [] sys_epoll_ctl+0x103/0x481 stack backtrace: Pid: 807, comm: systemd-logind Not tainted 2.6.39-0.local9.fc16.i686 #1 Call Trace: [] ? printk+0x2d/0x2f [] __lock_acquire+0x78f/0xae1 [] ? sched_clock+0x8/0xb [] ? sched_clock_local+0x10/0x18b [] ? ep_scan_ready_list+0x32/0x154 [] lock_acquire+0xbc/0xdc [] ? ep_scan_ready_list+0x32/0x154 [] __mutex_lock_common+0x4a/0x2f0 [] ? ep_scan_ready_list+0x32/0x154 [] ? __might_sleep+0x29/0xfb [] ? trace_hardirqs_off+0xb/0xd [] mutex_lock_nested+0x39/0x3e [] ? ep_scan_ready_list+0x32/0x154 [] ep_scan_ready_list+0x32/0x154 [] ? ep_remove+0x9b/0x9b [] ep_poll_readyevents_proc+0x14/0x16 [] ep_call_nested.constprop.2+0x6d/0x9a [] ? ep_scan_ready_list+0x154/0x154 [] ep_eventpoll_poll+0x45/0x55 [] sys_epoll_ctl+0x1ff/0x481 [] ? ep_send_events_proc+0xd5/0xd5 [] sysenter_do_call+0x12/0x38 3) Apparently this is something that is triggered by a brand new version of systemd (systemd-30-1.fc16.i686, compiled on July 13th, which I installed just yesterday, July 19th), as I do not recall seeing this before. 4) Feel free to prod me for more information. Paul Bolle