__might_sleep() warnings on v3.19-rc6

__might_sleep() warnings on v3.19-rc6

[Fengguang Wu]

Hi all,

I see 2 __might_sleep() warnings on when running LKP tests on
v3.19-rc6, one related to raid5 and another related to btrfs.

They might be exposed by this patch.

commit 8eb23b9f35aae413140d3fda766a98092c21e9b0
Author:     Peter Zijlstra <peterz@infradead.org>

    sched: Debug nested sleeps
    
    Validate we call might_sleep() with TASK_RUNNING, which catches places
    where we nest blocking primitives, eg. mutex usage in a wait loop.
    
    Since all blocking is arranged through task_struct::state, nesting
    this will cause the inner primitive to set TASK_RUNNING and the outer
    will thus not block.
    
    Another observed problem is calling a blocking function from
    schedule()->sched_submit_work()->blk_schedule_flush_plug() which will
    then destroy the task state for the actual __schedule() call that
    comes after it.


dmesg-ivb44:20150129001242:x86_64-rhel:3.19.0-rc6-g26bc420b:1


FSUse%        Count         Size    Files/sec     App Overhead
[   60.691525] ------------[ cut here ]------------
[   60.697499] WARNING: CPU: 0 PID: 1065 at kernel/sched/core.c:7300 __might_sleep+0xbd/0xd0()
[   60.709010] do not call blocking ops when !TASK_RUNNING; state=2 set at [<ffffffff810b63ff>] prepare_to_wait+0x2f/0x90
[   60.721646] Modules linked in: f2fs raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx raid6_pq ipmi_watchdog netconsole sg sd_mod mgag200 syscopyarea sysfillrect isci sysimgblt libsas ttm snd_pcm ahci snd_timer drm_kms_helper scsi_transport_sas libahci snd sb_edac soundcore drm libata edac_core i2c_i801 pcspkr wmi ipmi_si ipmi_msghandler
[   60.759585] CPU: 0 PID: 1065 Comm: kworker/u481:6 Not tainted 3.19.0-rc6-g26bc420b #1
[   60.769025] Hardware name: Intel Corporation S2600WP/S2600WP, BIOS SE5C600.86B.02.02.0002.122320131210 12/23/2013
[   60.781193] Workqueue: writeback bdi_writeback_workfn (flush-9:0)
[   60.788725]  ffffffff81b75d50 ffff88080979b3e8 ffffffff818a38f0 ffff88081ee100f8
[   60.797820]  ffff88080979b438 ffff88080979b428 ffffffff8107260a ffff88080979b428
[   60.806879]  ffffffff81b8c759 00000000000004d9 0000000000000000 0000000063fbe018
[   60.815935] Call Trace:
[   60.819368]  [<ffffffff818a38f0>] dump_stack+0x4c/0x65
[   60.825817]  [<ffffffff8107260a>] warn_slowpath_common+0x8a/0xc0
[   60.833269]  [<ffffffff81072686>] warn_slowpath_fmt+0x46/0x50
[   60.840379]  [<ffffffff810afe95>] ? pick_next_task_fair+0x1b5/0x8d0
[   60.848104]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
[   60.855215]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
[   60.862337]  [<ffffffff8109874d>] __might_sleep+0xbd/0xd0
[   60.869044]  [<ffffffff811c7cd7>] kmem_cache_alloc_trace+0x1d7/0x250
[   60.876830]  [<ffffffff817175d7>] ? bitmap_get_counter+0x117/0x280
[   60.884429]  [<ffffffff817175d7>] bitmap_get_counter+0x117/0x280
[   60.891807]  [<ffffffff810f6d02>] ? __module_text_address+0x12/0x70
[   60.899452]  [<ffffffff81717f54>] bitmap_startwrite+0x74/0x300
[   60.906601]  [<ffffffffa017659a>] add_stripe_bio+0x2aa/0x350 [raid456]
[   60.914518]  [<ffffffffa017d20d>] make_request+0x1dd/0xf30 [raid456]
[   60.922211]  [<ffffffff818aae00>] ? __account_scheduler_latency+0x150/0x370
[   60.930581]  [<ffffffff810b67e0>] ? wait_woken+0xc0/0xc0
[   60.937100]  [<ffffffff8109201f>] ? kthread+0xef/0x110
[   60.943404]  [<ffffffff8170b8c4>] md_make_request+0xf4/0x190
[   60.950277]  [<ffffffff8140fa3d>] ? radix_tree_lookup+0xd/0x10
[   60.957392]  [<ffffffffa027829c>] ? get_node_info+0x8c/0x2b0 [f2fs]
[   60.964937]  [<ffffffff813db848>] generic_make_request+0xd8/0x130
[   60.972291]  [<ffffffff813db908>] submit_bio+0x68/0x160
[   60.978677]  [<ffffffffa0273d58>] __submit_merged_bio+0x48/0x110 [f2fs]
[   60.986622]  [<ffffffffa0274b48>] f2fs_submit_page_mbio+0xa8/0x1f0 [f2fs]
[   60.994817]  [<ffffffffa027f7c0>] write_data_page+0x90/0xc0 [f2fs]
[   61.002272]  [<ffffffffa0276adf>] do_write_data_page+0xdf/0x310 [f2fs]
[   61.010119]  [<ffffffffa0276ee6>] f2fs_write_data_page+0x1d6/0x3e0 [f2fs]
[   61.018275]  [<ffffffffa0273e37>] __f2fs_writepage+0x17/0x50 [f2fs]
[   61.025831]  [<ffffffff811758cc>] write_cache_pages+0x21c/0x4e0
[   61.033003]  [<ffffffff813db848>] ? generic_make_request+0xd8/0x130
[   61.040543]  [<ffffffffa0273e20>] ? __submit_merged_bio+0x110/0x110 [f2fs]
[   61.048843]  [<ffffffffa027481c>] f2fs_write_data_pages+0xac/0x200 [f2fs]
[   61.056969]  [<ffffffff8117777e>] do_writepages+0x1e/0x30
[   61.063506]  [<ffffffff812108f0>] __writeback_single_inode+0x40/0x280
[   61.071217]  [<ffffffff810b6385>] ? wake_up_bit+0x25/0x30
[   61.077763]  [<ffffffff81211b03>] writeback_sb_inodes+0x263/0x410
[   61.085114]  [<ffffffff81211d4f>] __writeback_inodes_wb+0x9f/0xd0
[   61.092423]  [<ffffffff8121220b>] wb_writeback+0x24b/0x300
[   61.099030]  [<ffffffff81214194>] bdi_writeback_workfn+0x1d4/0x470
[   61.106400]  [<ffffffff8108bcc8>] process_one_work+0x158/0x4b0
[   61.113383]  [<ffffffff8108c08b>] worker_thread+0x6b/0x5e0
[   61.119967]  [<ffffffff8108c020>] ? process_one_work+0x4b0/0x4b0
[   61.127117]  [<ffffffff8109201f>] kthread+0xef/0x110
[   61.133102]  [<ffffffff81091f30>] ? kthread_create_on_node+0x180/0x180
[   61.140805]  [<ffffffff818abf7c>] ret_from_fork+0x7c/0xb0
[   61.147269]  [<ffffffff81091f30>] ? kthread_create_on_node+0x180/0x180
[   61.154973] ---[ end trace 2db29906e8050768 ]---
    17        51200      4194304         32.0          2701319

dmesg-lkp-ne04:20150128110549:x86_64-rhel:3.19.0-rc6-g26bc420b:1


FSUse%        Count         Size    Files/sec     App Overhead
[  101.678419] ------------[ cut here ]------------
[  101.684612] WARNING: CPU: 4 PID: 2153 at kernel/sched/core.c:7300 __might_sleep+0xbd/0xd0()
[  101.696412] do not call blocking ops when !TASK_RUNNING; state=2 set at [<ffffffff810b63ff>] prepare_to_wait+0x2f/0x90
[  101.709259] Modules linked in: ipmi_watchdog btrfs sr_mod cdrom xor raid6_pq sg sd_mod snd_pcm snd_timer snd soundcore pcspkr mgag200 syscopyarea sysfillrect sysimgblt ttm ahci drm_kms_helper libahci drm libata usb_storage i2c_i801 ipmi_si ipmi_msghandler i7core_edac edac_core acpi_cpufreq
[  101.741823] CPU: 4 PID: 2153 Comm: fs_mark Not tainted 3.19.0-rc6-g26bc420b #1
[  101.750851] Hardware name: Intel Corporation S5520UR/S5520UR, BIOS S5500.86B.01.00.0050.050620101605 05/06/2010
[  101.763101]  ffffffff81b75d50 ffff8801dd947c78 ffffffff818a38f0 ffff8801e9c500f8
[  101.772473]  ffff8801dd947cc8 ffff8801dd947cb8 ffffffff8107260a 0000000000000004
[  101.781793]  ffffffff81b76780 0000000000000061 0000000000000000 ffff8801e8438000
[  101.791140] Call Trace:
[  101.794751]  [<ffffffff818a38f0>] dump_stack+0x4c/0x65
[  101.801386]  [<ffffffff8107260a>] warn_slowpath_common+0x8a/0xc0
[  101.809003]  [<ffffffff81072686>] warn_slowpath_fmt+0x46/0x50
[  101.816335]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
[  101.823616]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
[  101.830875]  [<ffffffff8109874d>] __might_sleep+0xbd/0xd0
[  101.837766]  [<ffffffff818a9364>] mutex_lock+0x24/0x50
[  101.844399]  [<ffffffffa0285e88>] wait_for_writer+0x68/0xc0 [btrfs]
[  101.853029]  [<ffffffff810b67e0>] ? wait_woken+0xc0/0xc0
[  101.859849]  [<ffffffffa028b918>] btrfs_sync_log+0xf8/0xa70 [btrfs]
[  101.867740]  [<ffffffffa028c7bd>] ? btrfs_log_dentry_safe+0x6d/0x80 [btrfs]
[  101.876395]  [<ffffffffa02605d2>] btrfs_sync_file+0x2f2/0x330 [btrfs]
[  101.884375]  [<ffffffff81218101>] do_fsync+0x51/0x80
[  101.890737]  [<ffffffff81197977>] ? might_fault+0x47/0x50
[  101.897610]  [<ffffffff812183a0>] SyS_fsync+0x10/0x20
[  101.904096]  [<ffffffff818ac029>] system_call_fastpath+0x12/0x17
[  101.911647] ---[ end trace 77681997f1c4e23f ]---
     1        51200         8192        365.3          2076332

Thanks,
Fengguang

Re: __might_sleep() warnings on v3.19-rc6

[NeilBrown]

[-- Attachment #1: Type: text/plain, Size: 4150 bytes --]

On Sat, 31 Jan 2015 19:43:15 -0800 Fengguang Wu <fengguang.wu@intel.com>
wrote:

> Hi all,
> 
> I see 2 __might_sleep() warnings on when running LKP tests on
> v3.19-rc6, one related to raid5 and another related to btrfs.
> 
> They might be exposed by this patch.
> 
> commit 8eb23b9f35aae413140d3fda766a98092c21e9b0
> Author:     Peter Zijlstra <peterz@infradead.org>
> 
>     sched: Debug nested sleeps
>     
>     Validate we call might_sleep() with TASK_RUNNING, which catches places
>     where we nest blocking primitives, eg. mutex usage in a wait loop.
>     
>     Since all blocking is arranged through task_struct::state, nesting
>     this will cause the inner primitive to set TASK_RUNNING and the outer
>     will thus not block.
>     
>     Another observed problem is calling a blocking function from
>     schedule()->sched_submit_work()->blk_schedule_flush_plug() which will
>     then destroy the task state for the actual __schedule() call that
>     comes after it.
> 
> 
> dmesg-ivb44:20150129001242:x86_64-rhel:3.19.0-rc6-g26bc420b:1
> 
> 
> FSUse%        Count         Size    Files/sec     App Overhead
> [   60.691525] ------------[ cut here ]------------
> [   60.697499] WARNING: CPU: 0 PID: 1065 at kernel/sched/core.c:7300 __might_sleep+0xbd/0xd0()
> [   60.709010] do not call blocking ops when !TASK_RUNNING; state=2 set at [<ffffffff810b63ff>] prepare_to_wait+0x2f/0x90
> [   60.721646] Modules linked in: f2fs raid456 async_raid6_recov async_memcpy async_pq async_xor xor async_tx raid6_pq ipmi_watchdog netconsole sg sd_mod mgag200 syscopyarea sysfillrect isci sysimgblt libsas ttm snd_pcm ahci snd_timer drm_kms_helper scsi_transport_sas libahci snd sb_edac soundcore drm libata edac_core i2c_i801 pcspkr wmi ipmi_si ipmi_msghandler
> [   60.759585] CPU: 0 PID: 1065 Comm: kworker/u481:6 Not tainted 3.19.0-rc6-g26bc420b #1
> [   60.769025] Hardware name: Intel Corporation S2600WP/S2600WP, BIOS SE5C600.86B.02.02.0002.122320131210 12/23/2013
> [   60.781193] Workqueue: writeback bdi_writeback_workfn (flush-9:0)
> [   60.788725]  ffffffff81b75d50 ffff88080979b3e8 ffffffff818a38f0 ffff88081ee100f8
> [   60.797820]  ffff88080979b438 ffff88080979b428 ffffffff8107260a ffff88080979b428
> [   60.806879]  ffffffff81b8c759 00000000000004d9 0000000000000000 0000000063fbe018
> [   60.815935] Call Trace:
> [   60.819368]  [<ffffffff818a38f0>] dump_stack+0x4c/0x65
> [   60.825817]  [<ffffffff8107260a>] warn_slowpath_common+0x8a/0xc0
> [   60.833269]  [<ffffffff81072686>] warn_slowpath_fmt+0x46/0x50
> [   60.840379]  [<ffffffff810afe95>] ? pick_next_task_fair+0x1b5/0x8d0
> [   60.848104]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
> [   60.855215]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
> [   60.862337]  [<ffffffff8109874d>] __might_sleep+0xbd/0xd0
> [   60.869044]  [<ffffffff811c7cd7>] kmem_cache_alloc_trace+0x1d7/0x250
> [   60.876830]  [<ffffffff817175d7>] ? bitmap_get_counter+0x117/0x280
> [   60.884429]  [<ffffffff817175d7>] bitmap_get_counter+0x117/0x280
> [   60.891807]  [<ffffffff810f6d02>] ? __module_text_address+0x12/0x70
> [   60.899452]  [<ffffffff81717f54>] bitmap_startwrite+0x74/0x300
> [   60.906601]  [<ffffffffa017659a>] add_stripe_bio+0x2aa/0x350 [raid456]
> [   60.914518]  [<ffffffffa017d20d>] make_request+0x1dd/0xf30 [raid456]


This one is a false-positive - I think.

It is certainly true that if the inner primitive needs to block, then the
outer loop will not wait.  However that case is the exception.  Most of the
time the inner blocking primitive isn't called and the outer loop will wait as
expected.  Certainly the inner blocking primitive (a kmalloc) wouldn't be
called more than once without the outer loop making real progress.

If the outer loop sometime runs around the loop and extra time, that is no great cost.

However I see the value in having these warnings, even if they don't work for
me.
I guess I could
      __set_current_state(TASK_RUNNING);
somewhere to defeat the warning, and add a comment explaining why.

Would that be a good thing?

Thanks,
NeilBrown


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: __might_sleep() warnings on v3.19-rc6

[NeilBrown]

[-- Attachment #1: Type: text/plain, Size: 1484 bytes --]


(high-jacking the thread a bit... I don't have the patch that I want to reply
to still in my mail box:  the subject still matches...)

I just got a might-sleep warning in my own testing.
This was introduced by 

commit e22b886a8a43b147e1994a9f970f678fc0df2033
Author: Peter Zijlstra <peterz@infradead.org>
Date:   Wed Sep 24 10:18:48 2014 +0200

    sched/wait: Add might_sleep() checks


In particular:

@@ -318,6 +320,7 @@ do {                                                        
  */
 #define wait_event_cmd(wq, condition, cmd1, cmd2)                      \
 do {                                                                   \
+       might_sleep();                                                  \
        if (condition)                                                  \
                break;                                                  \
        __wait_event_cmd(wq, condition, cmd1, cmd2);                    \


Where I call this in raid5_quiesce(), 'cmd1' releases a lock and enables
interrupts and  cmd2 takes the lock and disables interrupts.

So it is perfectly OK to sleep at the point where schedule is called, but not
at the point where wait_event_cmd is called.

I can't use wait_event_lock_irq_cmd() as there are actually several spinlocks
I need to manipulate.

So I'm hoping that this part of the patch (at least) can be reverted.

Otherwise I guess I'll need to use __wait_event_cmd().

Thanks,
NeilBrown

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: __might_sleep() warnings on v3.19-rc6

[Linus Torvalds]

On Sun, Feb 1, 2015 at 3:03 PM, NeilBrown <neilb@suse.de> wrote:
>
> I guess I could
>       __set_current_state(TASK_RUNNING);
> somewhere to defeat the warning, and add a comment explaining why.
>
> Would that be a good thing?

Use "sched_annotate_sleep()" instead, but yes, add a comment about why it's ok.

                        Linus

Re: __might_sleep() warnings on v3.19-rc6

[NeilBrown]

[-- Attachment #1: Type: text/plain, Size: 2273 bytes --]

On Sun, 1 Feb 2015 21:08:12 -0800 Linus Torvalds
<torvalds@linux-foundation.org> wrote:

> On Sun, Feb 1, 2015 at 3:03 PM, NeilBrown <neilb@suse.de> wrote:
> >
> > I guess I could
> >       __set_current_state(TASK_RUNNING);
> > somewhere to defeat the warning, and add a comment explaining why.
> >
> > Would that be a good thing?
> 
> Use "sched_annotate_sleep()" instead, but yes, add a comment about why it's ok.
> 
>                         Linus
> --
> 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/

OK - following patch is queued to appear in a pull request tomorrow  (I hope).

Thanks,
NeilBrown

From: NeilBrown <neilb@suse.de>
Date: Mon, 2 Feb 2015 17:08:03 +1100
Subject: [PATCH] md/bitmap: fix a might_sleep() warning.

commit 8eb23b9f35aae413140d3fda766a98092c21e9b0
    sched: Debug nested sleeps

causes false-positive warnings in RAID5 code.

This annotation removes them and adds a comment
explaining why there is no real problem.

Reported-by: Fengguang Wu <fengguang.wu@intel.com>
Signed-off-by: NeilBrown <neilb@suse.de>

diff --git a/drivers/md/bitmap.c b/drivers/md/bitmap.c
index da3604e73e8a..1695ee5f3ffc 100644
--- a/drivers/md/bitmap.c
+++ b/drivers/md/bitmap.c
@@ -72,6 +72,19 @@ __acquires(bitmap->lock)
 	/* this page has not been allocated yet */
 
 	spin_unlock_irq(&bitmap->lock);
+	/* It is possible that this is being called inside a
+	 * prepare_to_wait/finish_wait loop from raid5c:make_request().
+	 * In general it is not permitted to sleep in that context as it
+	 * can cause the loop to spin freely.
+	 * That doesn't apply here as we can only reach this point
+	 * once with any loop.
+	 * When this function completes, either bp[page].map or
+	 * bp[page].hijacked.  In either case, this function will
+	 * abort before getting to this point again.  So there is
+	 * no risk of a free-spin, and so it is safe to assert
+	 * that sleeping here is allowed.
+	 */
+	sched_annotate_sleep();
 	mappage = kzalloc(PAGE_SIZE, GFP_NOIO);
 	spin_lock_irq(&bitmap->lock);
 

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 811 bytes --]

Re: __might_sleep() warnings on v3.19-rc6

[Chris Mason]

On Sat, Jan 31, 2015 at 07:43:15PM -0800, Fengguang Wu wrote:
> Hi all,
> 
> I see 2 __might_sleep() warnings on when running LKP tests on
> v3.19-rc6, one related to raid5 and another related to btrfs.
> 
> They might be exposed by this patch.
> FSUse%        Count         Size    Files/sec     App Overhead
> [  101.678419] ------------[ cut here ]------------
> [  101.684612] WARNING: CPU: 4 PID: 2153 at kernel/sched/core.c:7300 __might_sleep+0xbd/0xd0()
> [  101.696412] do not call blocking ops when !TASK_RUNNING; state=2 set at [<ffffffff810b63ff>] prepare_to_wait+0x2f/0x90
> [  101.709259] Modules linked in: ipmi_watchdog btrfs sr_mod cdrom xor raid6_pq sg sd_mod snd_pcm snd_timer snd soundcore pcspkr mgag200 syscopyarea sysfillrect sysimgblt ttm ahci drm_kms_helper libahci drm libata usb_storage i2c_i801 ipmi_si ipmi_msghandler i7core_edac edac_core acpi_cpufreq
> [  101.741823] CPU: 4 PID: 2153 Comm: fs_mark Not tainted 3.19.0-rc6-g26bc420b #1
> [  101.750851] Hardware name: Intel Corporation S5520UR/S5520UR, BIOS S5500.86B.01.00.0050.050620101605 05/06/2010
> [  101.763101]  ffffffff81b75d50 ffff8801dd947c78 ffffffff818a38f0 ffff8801e9c500f8
> [  101.772473]  ffff8801dd947cc8 ffff8801dd947cb8 ffffffff8107260a 0000000000000004
> [  101.781793]  ffffffff81b76780 0000000000000061 0000000000000000 ffff8801e8438000
> [  101.791140] Call Trace:
> [  101.794751]  [<ffffffff818a38f0>] dump_stack+0x4c/0x65
> [  101.801386]  [<ffffffff8107260a>] warn_slowpath_common+0x8a/0xc0
> [  101.809003]  [<ffffffff81072686>] warn_slowpath_fmt+0x46/0x50
> [  101.816335]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
> [  101.823616]  [<ffffffff810b63ff>] ? prepare_to_wait+0x2f/0x90
> [  101.830875]  [<ffffffff8109874d>] __might_sleep+0xbd/0xd0
> [  101.837766]  [<ffffffff818a9364>] mutex_lock+0x24/0x50
> [  101.844399]  [<ffffffffa0285e88>] wait_for_writer+0x68/0xc0 [btrfs]
> [  101.853029]  [<ffffffff810b67e0>] ? wait_woken+0xc0/0xc0
> [  101.859849]  [<ffffffffa028b918>] btrfs_sync_log+0xf8/0xa70 [btrfs]
> [  101.867740]  [<ffffffffa028c7bd>] ? btrfs_log_dentry_safe+0x6d/0x80 [btrfs]
> [  101.876395]  [<ffffffffa02605d2>] btrfs_sync_file+0x2f2/0x330 [btrfs]
> [  101.884375]  [<ffffffff81218101>] do_fsync+0x51/0x80
> [  101.890737]  [<ffffffff81197977>] ? might_fault+0x47/0x50
> [  101.897610]  [<ffffffff812183a0>] SyS_fsync+0x10/0x20
> [  101.904096]  [<ffffffff818ac029>] system_call_fastpath+0x12/0x17
> [  101.911647] ---[ end trace 77681997f1c4e23f ]---
>      1        51200         8192        365.3          2076332

The btrfs one will only trigger when we don't actually schedule:

        while (atomic_read(&root->log_writers)) {
                prepare_to_wait(&root->log_writer_wait,
                                &wait, TASK_UNINTERRUPTIBLE);
                mutex_unlock(&root->log_mutex);
                if (atomic_read(&root->log_writers))
                        schedule();
                mutex_lock(&root->log_mutex);
                finish_wait(&root->log_writer_wait, &wait);
        }

I'll switch things around.

-chris