From mboxrd@z Thu Jan 1 00:00:00 1970 From: Li Zefan Subject: Re: 3.10.16 cgroup_mutex deadlock Date: Tue, 12 Nov 2013 18:17:20 +0800 Message-ID: <52820030.6000806@huawei.com> References: <20131111220626.GA7509@sbohrermbp13-local.rgmadvisors.com> Mime-Version: 1.0 Content-Transfer-Encoding: 7bit Return-path: In-Reply-To: <20131111220626.GA7509-/vebjAlq/uFE7V8Yqttd03bhEEblAqRIDbRjUBewulXQT0dZR+AlfA@public.gmane.org> Sender: cgroups-owner-u79uwXL29TY76Z2rM5mHXA@public.gmane.org List-ID: Content-Type: text/plain; charset="us-ascii" To: Shawn Bohrer Cc: cgroups-u79uwXL29TY76Z2rM5mHXA@public.gmane.org, linux-kernel-u79uwXL29TY76Z2rM5mHXA@public.gmane.org, tj-DgEjT+Ai2ygdnm+yROfE0A@public.gmane.org, Hugh Dickins , Michal Hocko , Johannes Weiner , Markus Blank-Burian Cc more people On 2013/11/12 6:06, Shawn Bohrer wrote: > Hello, > > This morning I had a machine running 3.10.16 go unresponsive but > before we killed it we were able to get the information below. I'm > not an expert here but it looks like most of the tasks below are > blocking waiting on the cgroup_mutex. You can see that the > resource_alloca:16502 task is holding the cgroup_mutex and that task > appears to be waiting on a lru_add_drain_all() to complete. Ouch, another bug report! This looks like the same bug that Hugh saw. (http://permalink.gmane.org/gmane.linux.kernel.cgroups/9351) What's new in your report is, the lru_add_drain_all() comes from cpuset_attach() instead of memcg. Morever I thought it was a 3.11 specific bug. > > Initially I thought the deadlock might simply be that the per cpu > workqueue work from lru_add_drain_all() is stuck waiting on the > cgroup_free_fn to complete. However I've read > Documentation/workqueue.txt and it sounds like the current workqueue > has multiple kworker threads per cpu and thus this should not happen. > Both the cgroup_free_fn work and lru_add_dran_all() work run on the > system_wq which has max_active set to 0 so I believe multiple kworker > threads should run. This also appears to be true since all of the > cgroup_free_fn are running on kworker/12 thread and there are multiple > blocked. > > Perhaps someone with more experience in the cgroup and workqueue code > can look at the stacks below and identify the problem, or explain why > the lru_add_drain_all() work has not completed: > > > [694702.013850] INFO: task systemd:1 blocked for more than 120 seconds. > [694702.015794] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694702.018217] systemd D ffffffff81607820 0 1 0 0x00000000 > [694702.020505] ffff88041dcc1d78 0000000000000086 ffff88041dc7f100 ffffffff8110ad54 > [694702.023006] 0000000000000001 ffff88041dc78000 ffff88041dcc1fd8 ffff88041dcc1fd8 > [694702.025508] ffff88041dcc1fd8 ffff88041dc78000 ffff88041a1e8698 ffffffff81a417c0 > [694702.028011] Call Trace: > [694702.028788] [] ? vma_merge+0x124/0x330 > [694702.030468] [] schedule+0x29/0x70 > [694702.032011] [] schedule_preempt_disabled+0xe/0x10 > [694702.033982] [] __mutex_lock_slowpath+0x112/0x1b0 > [694702.035926] [] ? kmem_cache_alloc_trace+0x12d/0x160 > [694702.037948] [] mutex_lock+0x2a/0x50 > [694702.039546] [] proc_cgroup_show+0x67/0x1d0 > [694702.041330] [] seq_read+0x16b/0x3e0 > [694702.042927] [] vfs_read+0xb0/0x180 > [694702.044498] [] SyS_read+0x52/0xa0 > [694702.046042] [] system_call_fastpath+0x16/0x1b > [694702.047917] INFO: task kworker/12:1:203 blocked for more than 120 seconds. > [694702.050044] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694702.052467] kworker/12:1 D 0000000000000000 0 203 2 0x00000000 > [694702.054756] Workqueue: events cgroup_free_fn > [694702.056139] ffff88041bc1fcf8 0000000000000046 ffff88038e7b46a0 0000000300000001 > [694702.058642] ffff88041bc1fd84 ffff88041da6e9f0 ffff88041bc1ffd8 ffff88041bc1ffd8 > [694702.061144] ffff88041bc1ffd8 ffff88041da6e9f0 0000000000000087 ffffffff81a417c0 > [694702.063647] Call Trace: > [694702.064423] [] schedule+0x29/0x70 > [694702.065966] [] schedule_preempt_disabled+0xe/0x10 > [694702.067936] [] __mutex_lock_slowpath+0x112/0x1b0 > [694702.069879] [] mutex_lock+0x2a/0x50 > [694702.071476] [] cgroup_free_fn+0x2c/0x120 > [694702.073209] [] process_one_work+0x174/0x490 > [694702.075019] [] worker_thread+0x11c/0x370 > [694702.076748] [] ? manage_workers+0x2c0/0x2c0 > [694702.078560] [] kthread+0xc0/0xd0 > [694702.080078] [] ? flush_kthread_worker+0xb0/0xb0 > [694702.081995] [] ret_from_fork+0x7c/0xb0 > [694702.083671] [] ? flush_kthread_worker+0xb0/0xb0 > [694702.085595] INFO: task systemd-logind:2885 blocked for more than 120 seconds. > [694702.087801] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694702.090225] systemd-logind D ffffffff81607820 0 2885 1 0x00000000 > [694702.092513] ffff88041ac6fd88 0000000000000082 ffff88041dd8aa60 ffff88041d9bc1a8 > [694702.095014] ffff88041ac6fda0 ffff88041cac9530 ffff88041ac6ffd8 ffff88041ac6ffd8 > [694702.097517] ffff88041ac6ffd8 ffff88041cac9530 0000000000000c36 ffffffff81a417c0 > [694702.100019] Call Trace: > [694702.100793] [] schedule+0x29/0x70 > [694702.102338] [] schedule_preempt_disabled+0xe/0x10 > [694702.104309] [] __mutex_lock_slowpath+0x112/0x1b0 > [694702.198316] [] mutex_lock+0x2a/0x50 > [694702.292456] [] cgroup_lock_live_group+0x1d/0x40 > [694702.386833] [] cgroup_mkdir+0xa8/0x4b0 > [694702.480679] [] vfs_mkdir+0x84/0xd0 > [694702.574124] [] SyS_mkdirat+0x5e/0xe0 > [694702.666986] [] SyS_mkdir+0x19/0x20 > [694702.758969] [] system_call_fastpath+0x16/0x1b > [694702.848295] INFO: task kworker/12:2:11512 blocked for more than 120 seconds. > [694702.935749] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694703.023603] kworker/12:2 D ffffffff816079c0 0 11512 2 0x00000000 > [694703.109993] Workqueue: events cgroup_free_fn > [694703.193213] ffff88041b9dfcf8 0000000000000046 ffff88041da6e9f0 ffffea00106fd240 > [694703.278353] ffff88041f803c00 ffff8803824254c0 ffff88041b9dffd8 ffff88041b9dffd8 > [694703.363757] ffff88041b9dffd8 ffff8803824254c0 0000001f17887bb1 ffffffff81a417c0 > [694703.448550] Call Trace: > [694703.531773] [] schedule+0x29/0x70 > [694703.615316] [] schedule_preempt_disabled+0xe/0x10 > [694703.698298] [] __mutex_lock_slowpath+0x112/0x1b0 > [694703.780456] [] ? cgroup_free_fn+0x10c/0x120 > [694703.861813] [] mutex_lock+0x2a/0x50 > [694703.942719] [] cgroup_free_fn+0x2c/0x120 > [694704.023785] [] process_one_work+0x174/0x490 > [694704.104080] [] worker_thread+0x11c/0x370 > [694704.184000] [] ? manage_workers+0x2c0/0x2c0 > [694704.264027] [] kthread+0xc0/0xd0 > [694704.343761] [] ? flush_kthread_worker+0xb0/0xb0 > [694704.423868] [] ret_from_fork+0x7c/0xb0 > [694704.503734] [] ? flush_kthread_worker+0xb0/0xb0 > [694704.583766] INFO: task resource_alloca:16502 blocked for more than 120 seconds. > [694704.664964] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694704.747361] resource_alloca D ffffffff81607820 0 16502 16467 0x00000000 > [694704.831088] ffff8803a43cda18 0000000000000086 ffffffff81a10440 ffffffff810287fe > [694704.916440] ffff8803a43cd9c8 ffff88041ba9b170 ffff8803a43cdfd8 ffff8803a43cdfd8 > [694705.002030] ffff8803a43cdfd8 ffff88041ba9b170 ffff8803a43cda38 ffff8803a43cdb50 > [694705.086265] Call Trace: > [694705.168664] [] ? physflat_send_IPI_mask+0xe/0x10 > [694705.251780] [] schedule+0x29/0x70 > [694705.334283] [] schedule_timeout+0x195/0x1f0 > [694705.415962] [] ? __schedule+0x2a2/0x740 > [694705.497267] [] wait_for_completion+0xa5/0x110 > [694705.578786] [] ? try_to_wake_up+0x270/0x270 > [694705.659533] [] flush_work+0xe3/0x150 > [694705.739934] [] ? pool_mayday_timeout+0x100/0x100 > [694705.820840] [] ? __pagevec_release+0x40/0x40 > [694705.901615] [] schedule_on_each_cpu+0xc3/0x110 > [694705.982441] [] lru_add_drain_all+0x15/0x20 > [694706.063268] [] migrate_prep+0xe/0x20 > [694706.143986] [] do_migrate_pages+0x2b/0x220 > [694706.224840] [] ? task_rq_lock+0x5b/0xa0 > [694706.305695] [] ? cpumask_next_and+0x36/0x50 > [694706.386735] [] cpuset_migrate_mm+0x78/0xa0 > [694706.467666] [] cpuset_attach+0x296/0x310 > [694706.548253] [] cgroup_attach_task+0x47e/0x7a0 > [694706.628732] [] ? mutex_lock+0x1d/0x50 > [694706.708308] [] attach_task_by_pid+0x167/0x1a0 > [694706.787271] [] cgroup_tasks_write+0x13/0x20 > [694706.864902] [] cgroup_file_write+0x143/0x2e0 > [694706.941469] [] ? __sb_start_write+0x53/0x110 > [694707.018036] [] ? vm_mmap_pgoff+0x7d/0xb0 > [694707.094629] [] vfs_write+0xce/0x1e0 > [694707.170158] [] SyS_write+0x52/0xa0 > [694707.244994] [] ? do_page_fault+0xe/0x10 > [694707.319991] [] system_call_fastpath+0x16/0x1b > [694707.395118] INFO: task kworker/12:0:24144 blocked for more than 120 seconds. > [694707.471258] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694707.548490] kworker/12:0 D 0000000000000000 0 24144 2 0x00000000 > [694707.626683] Workqueue: events cgroup_free_fn > [694707.704578] ffff88040d8a5cf8 0000000000000046 ffff88038e7b4db0 0000000000012c80 > [694707.784819] 0000000000002e7b ffff88038e7b46a0 ffff88040d8a5fd8 ffff88040d8a5fd8 > [694707.866017] ffff88040d8a5fd8 ffff88038e7b46a0 000000000000000c ffffffff81a417c0 > [694707.947350] Call Trace: > [694708.027061] [] schedule+0x29/0x70 > [694708.106747] [] schedule_preempt_disabled+0xe/0x10 > [694708.185737] [] __mutex_lock_slowpath+0x112/0x1b0 > [694708.264354] [] mutex_lock+0x2a/0x50 > [694708.341905] [] cgroup_free_fn+0x2c/0x120 > [694708.419431] [] process_one_work+0x174/0x490 > [694708.496983] [] worker_thread+0x11c/0x370 > [694708.573522] [] ? manage_workers+0x2c0/0x2c0 > [694708.649929] [] kthread+0xc0/0xd0 > [694708.726017] [] ? flush_kthread_worker+0xb0/0xb0 > [694708.802451] [] ret_from_fork+0x7c/0xb0 > [694708.878645] [] ? flush_kthread_worker+0xb0/0xb0 > [694708.955132] INFO: task kworker/12:3:24145 blocked for more than 120 seconds. > [694709.032683] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694709.111511] kworker/12:3 D 0000000000000000 0 24145 2 0x00000000 > [694709.191327] Workqueue: events cgroup_free_fn > [694709.270794] ffff880399e6fcf8 0000000000000046 ffff88038e7b54c0 0000000000012c80 > [694709.352338] 0000000000002e7b ffff88038e7b4db0 ffff880399e6ffd8 ffff880399e6ffd8 > [694709.434361] ffff880399e6ffd8 ffff88038e7b4db0 000000000000000c ffffffff81a417c0 > [694709.516544] Call Trace: > [694709.597775] [] schedule+0x29/0x70 > [694709.679168] [] schedule_preempt_disabled+0xe/0x10 > [694709.759888] [] __mutex_lock_slowpath+0x112/0x1b0 > [694709.839675] [] mutex_lock+0x2a/0x50 > [694709.918397] [] cgroup_free_fn+0x2c/0x120 > [694709.996989] [] process_one_work+0x174/0x490 > [694710.076272] [] worker_thread+0x11c/0x370 > [694710.154597] [] ? manage_workers+0x2c0/0x2c0 > [694710.232443] [] kthread+0xc0/0xd0 > [694710.309787] [] ? flush_kthread_worker+0xb0/0xb0 > [694710.387874] [] ret_from_fork+0x7c/0xb0 > [694710.465882] [] ? flush_kthread_worker+0xb0/0xb0 > [694710.544284] INFO: task kworker/12:4:24146 blocked for more than 120 seconds. > [694710.623592] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694710.704151] kworker/12:4 D 0000000000000000 0 24146 2 0x00000000 > [694710.785538] Workqueue: events cgroup_free_fn > [694710.866442] ffff88041ce81cf8 0000000000000046 ffff88038e7b5bd0 0000000000012c80 > [694710.949265] 0000000000002e7b ffff88038e7b54c0 ffff88041ce81fd8 ffff88041ce81fd8 > [694711.032620] ffff88041ce81fd8 ffff88038e7b54c0 000000000000000c ffffffff81a417c0 > [694711.116268] Call Trace: > [694711.199224] [] schedule+0x29/0x70 > [694711.283085] [] schedule_preempt_disabled+0xe/0x10 > [694711.367344] [] __mutex_lock_slowpath+0x112/0x1b0 > [694711.451765] [] mutex_lock+0x2a/0x50 > [694711.536157] [] cgroup_free_fn+0x2c/0x120 > [694711.620825] [] process_one_work+0x174/0x490 > [694711.705459] [] worker_thread+0x11c/0x370 > [694711.789879] [] ? manage_workers+0x2c0/0x2c0 > [694711.874566] [] kthread+0xc0/0xd0 > [694711.959229] [] ? flush_kthread_worker+0xb0/0xb0 > [694712.044502] [] ret_from_fork+0x7c/0xb0 > [694712.129694] [] ? flush_kthread_worker+0xb0/0xb0 > [694712.215339] INFO: task kworker/12:5:24147 blocked for more than 120 seconds. > [694712.302557] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694712.391077] kworker/12:5 D 0000000000000000 0 24147 2 0x00000000 > [694712.480423] Workqueue: events cgroup_free_fn > [694712.568568] ffff88040fc3fcf8 0000000000000046 ffff88038e7b62e0 0000000000012c80 > [694712.657755] 0000000000002e7b ffff88038e7b5bd0 ffff88040fc3ffd8 ffff88040fc3ffd8 > [694712.746434] ffff88040fc3ffd8 ffff88038e7b5bd0 000000000000000c ffffffff81a417c0 > [694712.834847] Call Trace: > [694712.921531] [] schedule+0x29/0x70 > [694713.008695] [] schedule_preempt_disabled+0xe/0x10 > [694713.096069] [] __mutex_lock_slowpath+0x112/0x1b0 > [694713.182672] [] mutex_lock+0x2a/0x50 > [694713.268848] [] cgroup_free_fn+0x2c/0x120 > [694713.355186] [] process_one_work+0x174/0x490 > [694713.441498] [] worker_thread+0x11c/0x370 > [694713.527569] [] ? manage_workers+0x2c0/0x2c0 > [694713.613723] [] kthread+0xc0/0xd0 > [694713.699558] [] ? flush_kthread_worker+0xb0/0xb0 > [694713.785921] [] ret_from_fork+0x7c/0xb0 > [694713.872205] [] ? flush_kthread_worker+0xb0/0xb0 > [694713.958940] INFO: task kworker/12:6:24148 blocked for more than 120 seconds. > [694714.046607] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [694714.135393] kworker/12:6 D 0000000000000000 0 24148 2 0x00000000 > [694714.224979] Workqueue: events cgroup_free_fn > [694714.313390] ffff88040cf13cf8 0000000000000046 ffff88038e7b69f0 0000000000012c80 > [694714.402790] 0000000000002e7b ffff88038e7b62e0 ffff88040cf13fd8 ffff88040cf13fd8 > [694714.491601] ffff88040cf13fd8 ffff88038e7b62e0 000000000000000c ffffffff81a417c0 > [694714.580174] Call Trace: > [694714.667046] [] schedule+0x29/0x70 > [694714.754314] [] schedule_preempt_disabled+0xe/0x10 > [694714.841716] [] __mutex_lock_slowpath+0x112/0x1b0 > [694714.928347] [] mutex_lock+0x2a/0x50 > [694715.014577] [] cgroup_free_fn+0x2c/0x120 > [694715.100968] [] process_one_work+0x174/0x490 > [694715.187306] [] worker_thread+0x11c/0x370 > [694715.273404] [] ? manage_workers+0x2c0/0x2c0 > [694715.359553] [] kthread+0xc0/0xd0 > [694715.445411] [] ? flush_kthread_worker+0xb0/0xb0 > [694715.531773] [] ret_from_fork+0x7c/0xb0 > [694715.618058] [] ? flush_kthread_worker+0xb0/0xb0 > > . >