From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751988AbdFTHpV (ORCPT ); Tue, 20 Jun 2017 03:45:21 -0400 Received: from mout.gmx.net ([212.227.17.20]:54429 "EHLO mout.gmx.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750863AbdFTHpT (ORCPT ); Tue, 20 Jun 2017 03:45:19 -0400 Message-ID: <1497944706.5454.7.camel@gmx.de> Subject: Re: [ANNOUNCE] v4.11.5-rt1 From: Mike Galbraith To: Steven Rostedt , Sebastian Andrzej Siewior Cc: Thomas Gleixner , LKML , linux-rt-users Date: Tue, 20 Jun 2017 09:45:06 +0200 In-Reply-To: <1497889784.15817.17.camel@gmx.de> References: <20170616105610.rbc6itylcrsla56l@linutronix.de> <1497687277.6908.31.camel@gmx.de> <20170619085206.n2n22lpdfsoqbp5m@linutronix.de> <1497867291.19618.52.camel@gmx.de> <20170619100838.343faaee@gandalf.local.home> <20170619141341.m243ivutmwlzyhc4@linutronix.de> <20170619104131.05fdc76f@gandalf.local.home> <1497889784.15817.17.camel@gmx.de> Content-Type: text/plain; charset="UTF-8" X-Mailer: Evolution 3.20.5 Mime-Version: 1.0 Content-Transfer-Encoding: 7bit X-Provags-ID: V03:K0:D2OsZ1bAMYR1WmmTwjq0q7XjU3Mo12+iZnYgQLZYEhxzzgjGak5 BRH8/utyomEXINFhp844d1mmwdkkDA3W7/fmPXbjFQPXrs3Vy0MJTl9wAtOV05SSHA4ihqS 79Iq3qF0pGuuWvy32+Gm+RKfcJID91DcDWp7z8kNF5d1ggIQ/va3dOIOtvMLgm0jYjtYNdJ Er/ws3XKdzx6s2YQIP6AQ== X-UI-Out-Filterresults: notjunk:1;V01:K0:j8MJsydDDCs=:bI+9JaFT6K6G2ZjPLy0CoS n3GueZlBgf/UFwFeD9eSFfDf/cbyhhL3GfhN6Uu58b6BDf8ALJGyQv2laXZ/grJL1JGOXqQ+d DyI8uokafIW7PgYgaeG3vcHVouflW1Qt3oOIlLVZXOJYtbn9R99mdayqTTdy+YwCloe+l+nJf iLlfXxNiQciTRiEuUlfwmtFWKHrIAGFd0NOpK91Tt89gRUsr+0dabAdsEyRyq55LwpAbNsIzt 7VJezDRCA7knq5En2jg/Rjkvx39SWNaelZ3NW80axOTwvGe+dn+vR6dPEQXJ0aHUx/cYrYMU3 bnGg6AdmOl8AVHhl/lVsumtnyLMAaEscM3FYN56ZZQFoDjgSAlqci47/BzE73KYlWkdyu//sf SmCubY79FCECDunXmL3zRfoH++5Wrf2Dpo/5CnS6HNMZb0KkC7AdR3p7XKNzRL1JZQmXMhs4r UKf2hD3+EWLynrPPX4Iy/it3KTv2RVCZngHZXNhHBoH59bI8eR6hjSz332x2B6MsBDJ1DLD8m 38hTybkfK31lRvfi9d+IsGpIZ8B+9Bzgso9/Uu61tBXsIVR84qy+kXSHqagsJFEArv9imQJQS 6+IdNDkZvTZDA6y+fiA0UoHOOY5TBIbn/iZKCjwVA+1N1j3om5LU+Qf8xyLSwMyyjl1UnU1EN 6OwREWybrx8GX/VZbOGTXpxNNaCGrz4RwZbmLS2LJMLkurrHurQZa+KxEUwAE4W2wDT86MvnJ MmFxTd7JWwLDpUFmMUqtOabrEQN0M6ljTAMcZnSGmuOeXrgWwx5oucEdzj0Q7QqU5E9xqqdr3 ErHc7ua Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Mon, 2017-06-19 at 18:29 +0200, Mike Galbraith wrote: > On Mon, 2017-06-19 at 10:41 -0400, Steven Rostedt wrote: > > On Mon, 19 Jun 2017 16:13:41 +0200 > > Sebastian Andrzej Siewior wrote: > > > > > > > > Hmm, it shouldn't affect futexes, as it's only called by rtmutex when > > > > waiter->savestate is true. And that should always be false for futex. > > > > > > you still have sleeping locks like the hb-lock (which might matter in > > > case the task blocks on the lock and does not continue for some reason). > > > > But then I'd expect this to be an issue with any spinlock in the kernel. > > Thing to do is set a trap for the bugger. See ! and ? vogelweide:~/:[1]# grep MIKE trace MIKE 913.728104: start MIKE futex_wait-7496 [031] ....... 913.729160: sched_process_fork: comm=futex_wait pid=7496 child_comm=futex_wait child_pid=7497 MIKE futex_wait-7496 [031] ....... 913.729253: sched_process_fork: comm=futex_wait pid=7496 child_comm=futex_wait child_pid=7499 MIKE futex_wait-7496 [031] ....... 913.729307: sched_process_fork: comm=futex_wait pid=7496 child_comm=futex_wait child_pid=7500 MIKE futex_wait-7496 [031] ....... 913.729348: sched_process_fork: comm=futex_wait pid=7496 child_comm=futex_wait child_pid=7501 MIKE futex_wait-7496 [031] d...2.. 913.729430: sched_switch: prev_comm=futex_wait prev_pid=7496 prev_prio=120 prev_state=S ==> next_comm=swapper/31 next_pid=0 next_prio=120 MIKE--futex_wait-7500 [005] d...2.. 920.040320: sched_switch: prev_comm=futex_wait prev_pid=7500 prev_prio=120 prev_state=S ==> next_comm=swapper/5 next_pid=0 next_prio=120 MIKE futex_wait-7497 [058] d...211 920.060009: sched_waking: comm=futex_wait pid=7501 prio=120 target_cpu=044 MIKE futex_wait-7497 [058] d...311 920.060012: sched_wake_idle_without_ipi: cpu=44 MIKE futex_wait-7497 [058] d...311 920.060012: sched_wakeup: comm=futex_wait pid=7501 prio=120 target_cpu=044 MIKE--futex_wait-7497 [058] d...2.. 920.060035: sched_switch: prev_comm=futex_wait prev_pid=7497 prev_prio=120 prev_state=S ==> next_comm=swapper/58 next_pid=0 next_prio=120 MIKE futex_wait-7499 [043] dN..411 920.060035: sched_wakeup: comm=ktimersoftd/43 pid=438 prio=0 target_cpu=043 MIKE! futex_wait-7499 [043] .N..111 920.060037: wake_up_lock_sleeper: futex_wait:7497 state:1 saved_state:0 MIKE! futex_wait-7499 [043] dN..211 920.060037: try_to_wake_up: futex_wait:7497 WF_LOCK_SLEEPER !(p->state:1 & state:2) bailing MIKE 920.060037: futex_wait-7497 is never awakened again until ^C cleanup, 7499/7501 still standing MIKE futex_wait-7499 [043] ....111 920.060066: wake_up_lock_sleeper: futex_wait:7501 state:2 saved_state:0 MIKE futex_wait-7499 [043] d...211 920.060066: try_to_wake_up: futex_wait:7501 WF_LOCK_SLEEPER !(p->state:0 & state:2) bailing MIKE futex_wait-7499 [043] ....111 920.060606: wake_up_lock_sleeper: futex_wait:7501 state:2 saved_state:0 MIKE 920.355048: huh? wake_up_lock_sleeper sees state=2 but try_to_wake_up then sees state=0 and bails ?!? MIKE futex_wait-7501 [044] ....111 920.355048: wake_up_lock_sleeper: futex_wait:7499 state:2 saved_state:0 MIKE futex_wait-7501 [044] d...211 920.355049: try_to_wake_up: futex_wait:7499 WF_LOCK_SLEEPER !(p->state:0 & state:2) bailing MIKE futex_wait-7499 [048] d..h311 920.355060: sched_stat_runtime: comm=futex_wait pid=7499 runtime=168537 [ns] vruntime=4850005377 [ns] MIKE futex_wait-7499 [048] d...311 920.355061: sched_waking: comm=ksoftirqd/48 pid=489 prio=120 target_cpu=048 MIKE futex_wait-7499 [048] d...411 920.355062: sched_stat_runtime: comm=futex_wait pid=7499 runtime=2972 [ns] vruntime=4850008349 [ns] MIKE futex_wait-7499 [048] d.L.411 920.355063: sched_wakeup: comm=ksoftirqd/48 pid=489 prio=120 target_cpu=048 MIKE futex_wait-7499 [048] d.L.311 920.355064: sched_waking: comm=ktimersoftd/48 pid=488 prio=0 target_cpu=048 MIKE futex_wait-7499 [048] dNL.411 920.355065: sched_wakeup: comm=ktimersoftd/48 pid=488 prio=0 target_cpu=048 MIKE futex_wait-7499 [048] .NL.111 920.355066: wake_up_lock_sleeper: futex_wait:7501 state:0 saved_state:0 MIKE futex_wait-7499 [048] dNL.211 920.355067: try_to_wake_up: futex_wait:7501 WF_LOCK_SLEEPER !(p->state:0 & state:2) bailing MIKE futex_wait-7499 [048] dNL.211 920.355067: sched_stat_runtime: comm=futex_wait pid=7499 runtime=2011 [ns] vruntime=4850010360 [ns] MIKE futex_wait-7499 [048] d...211 920.355068: sched_switch: prev_comm=futex_wait prev_pid=7499 prev_prio=120 prev_state=R+ ==> next_comm=ktimersoftd/48 next_pid=488 next_prio=0 MIKE <...>-488 [048] d...2.. 920.355070: sched_switch: prev_comm=ktimersoftd/48 prev_pid=488 prev_prio=0 prev_state=S ==> next_comm=ksoftirqd/48 next_pid=489 next_prio=120 MIKE <...>-489 [048] d...2.. 920.355071: sched_stat_runtime: comm=ksoftirqd/48 pid=489 runtime=1925 [ns] vruntime=4838010274 [ns] MIKE <...>-489 [048] d...2.. 920.355072: sched_switch: prev_comm=ksoftirqd/48 prev_pid=489 prev_prio=120 prev_state=S ==> next_comm=futex_wait next_pid=7499 next_prio=120 MIKE futex_wait-7501 [044] d...2.. 920.355072: sched_stat_runtime: comm=futex_wait pid=7501 runtime=32398 [ns] vruntime=6632181410 [ns] MIKE--futex_wait-7501 [044] d...2.. 920.355074: sched_switch: prev_comm=futex_wait prev_pid=7501 prev_prio=120 prev_state=S ==> next_comm=swapper/44 next_pid=0 next_prio=120 MIKE 920.355074: 7499 is last man standing, but bored, just waking ktimersoftd MIKE futex_wait-7499 [048] d..h1.. 920.356060: sched_stat_runtime: comm=futex_wait pid=7499 runtime=988793 [ns] vruntime=4850999153 [ns] MIKE futex_wait-7499 [048] d...1.. 920.356061: sched_waking: comm=ktimersoftd/48 pid=488 prio=0 target_cpu=048 MIKE futex_wait-7499 [048] dN..2.. 920.356063: sched_wakeup: comm=ktimersoftd/48 pid=488 prio=0 target_cpu=048 MIKE futex_wait-7499 [048] dN..2.. 920.356063: sched_stat_runtime: comm=futex_wait pid=7499 runtime=1854 [ns] vruntime=4851001007 [ns] MIKE futex_wait-7499 [048] d...2.. 920.356064: sched_switch: prev_comm=futex_wait prev_pid=7499 prev_prio=120 prev_state=R ==> next_comm=ktimersoftd/48 next_pid=488 next_prio=0 MIKE <...>-488 [048] d...2.. 920.356065: sched_switch: prev_comm=ktimersoftd/48 prev_pid=488 prev_prio=0 prev_state=S ==> next_comm=futex_wait next_pid=7499 next_prio=120 MIKE futex_wait-7499 [048] d..h1.. 920.384055: sched_stat_runtime: comm=futex_wait pid=7499 runtime=997267 [ns] vruntime=4878950744 [ns] MIKE futex_wait-7499 [048] d...1.. 920.384056: sched_waking: comm=ktimersoftd/48 pid=488 prio=0 target_cpu=048 MIKE futex_wait-7499 [048] dN..2.. 920.384056: sched_wakeup: comm=ktimersoftd/48 pid=488 prio=0 target_cpu=048 MIKE futex_wait-7499 [048] dN..2.. 920.384057: sched_stat_runtime: comm=futex_wait pid=7499 runtime=1161 [ns] vruntime=4878951905 [ns] MIKE futex_wait-7499 [048] d...2.. 920.384057: sched_switch: prev_comm=futex_wait prev_pid=7499 prev_prio=120 prev_state=R ==> next_comm=ktimersoftd/48 next_pid=488 next_prio=0 MIKE <...>-488 [048] d...2.. 920.384058: sched_switch: prev_comm=ktimersoftd/48 prev_pid=488 prev_prio=0 prev_state=S ==> next_comm=futex_wait next_pid=7499 next_prio=120 MIKE futex_wait-7499 [048] d...2.. 920.384271: sched_stat_runtime: comm=futex_wait pid=7499 runtime=213243 [ns] vruntime=4879165148 [ns] MIKE futex_wait-7499 [048] d...2.. 920.384271: sched_switch: prev_comm=futex_wait prev_pid=7499 prev_prio=120 prev_state=S ==> next_comm=swapper/48 next_pid=0 next_prio=120 MIKE 920.384271: we're stalled, all futex_wait have scheduled off, elide gap MIKE 981.447247: nothing to see above /me poking ^C, elide to EOF