[lttng-dev] might_sleep warnings in overwrite mode

[Nathan Lynch]

On 11/14/2013 08:34 PM, Mathieu Desnoyers wrote:
> ----- Original Message -----
>> From: "Nathan Lynch" <Nathan_Lynch at mentor.com>
>> To: lttng-dev at lists.lttng.org
>> Sent: Thursday, November 14, 2013 1:16:53 PM
>> Subject: Re: [lttng-dev] might_sleep warnings in overwrite mode
>>
>> On 11/10/2013 08:18 PM, Nathan Lynch wrote:
>>> At this point I cannot trigger the issue without overwrite mode on
>>> 3.11.6, but on a 3.8-based vendor kernel I can recreate it regardless of
>>> the mode.
>>
>> Some updates on this:
>> - It's not specific to overwrite mode; I was able to provoke it on
>> 3.11.6 without --overwrite.  Overwrite mode does seem to recreate the
>> issue more readily.
>> - It seems to be GCC version-dependent.  4.8.1 and 4.8.2 produce code
>> which warns/bugs; 4.7.3 does not.
> 
> Looking at:
> 
> fs/ext3/incode.c:
> 
> __ext3_get_inode_loc()
> 
> we can see that a use of the inlined sb_getblk() appears close to a tracepoint.
> 
> The tracepoint includes preempt disable/enable, exactly those:
> 
> include/linux/preempt.h:
> 
> #define preempt_disable_notrace() \
> do { \
>         inc_preempt_count_notrace(); \
>         barrier(); \
> } while (0)
> 
> #define preempt_enable_notrace() \
> do { \
>         preempt_enable_no_resched_notrace(); \
>         barrier(); \
>         preempt_check_resched_context(); \
> } while (0)
> 
> 
> Can you try wrapping the _outside_ of those macros with barrier(), e.g.
> 
> 
> #define preempt_disable_notrace() \
> do { \
>         barrier(); \
>         inc_preempt_count_notrace(); \
>         barrier(); \
> } while (0)
> 
> #define preempt_enable_notrace() \
> do { \
>         preempt_enable_no_resched_notrace(); \
>         barrier(); \
>         preempt_check_resched_context(); \
>         barrier(); \
> } while (0)
> 
> and try it out with the apparently buggy compiler to see if it helps ?

I did this, and I think I'm pretty satisfied that it works around the
issue.  I haven't been able to provoke might_sleep or preempt count
warnings with multiple runs.  Complicating matters is that I keep
hitting a null pointer dereference in the mmc code which I wasn't seeing
before (and sorry about the line wrapping, I cannot make Thunderbird
behave well here):

Unable to handle kernel NULL pointer dereference at virtual address 00000000
pgd = 80004000
[00000000] *pgd=00000000
Internal error: Oops: 17 [#1] PREEMPT SMP ARM
Modules linked in: lttng_probe_writeback(O) lttng_probe_workqueue(O)
lttng_probe_vmscan(O) lttng_probe_udp(O) lttng_probe_timer(O)
lttng_probe_sunrpc(O) lttng_probe_statedump(O) lttng_probe_sock(O)
lttng_probe_skb(O) lttng_probe_signal(O) lttng_probe_scsi(O)
lttng_probe_sched(O) lttng_probe_rpm(O) lttng_probe_regulator(O)
lttng_probe_regmap(O) lttng_probe_rcu(O) lttng_probe_random(O)
lttng_probe_printk(O) lttng_probe_power(O) lttng_probe_net(O)
lttng_probe_napi(O) lttng_probe_module(O) lttng_probe_kmem(O)
lttng_probe_jbd2(O) lttng_probe_jbd(O) lttng_probe_irq(O)
lttng_probe_gpio(O) lttng_probe_ext4(O) lttng_probe_ext3(O)
lttng_probe_compaction(O) lttng_probe_block(O) lttng_probe_asoc(O)
lttng_types(O) lttng_ring_buffer_metadata_mmap_client(O)
lttng_ring_buffer_client_mmap_overwrite(O)
lttng_ring_buffer_client_mmap_discard(O)
lttng_ring_buffer_metadata_client(O)
lttng_ring_buffer_client_overwrite(O)
lttng_ring_buffer_client_discard(O) lttng_tracer(O) lttng_statedump(O)
lttng_ftrace(O) lttng_kprobes(O) lttng_lib_ring_buffer(O)
lttng_kretprobes(O)
CPU: 0 PID: 143 Comm: mmcqd/0 Tainted: G           O 3.11.6 #1
task: bf0d0900 ti: bf0be000 task.ti: bf0be000
PC is at sdhci_send_command+0x3fc/0xc58
LR is at sdhci_send_command+0x424/0xc58
pc : [<804371d0>]    lr : [<804371f8>]    psr: 80000093
sp : bf0bfd50  ip : bf0bfd50  fp : bf0bfdac
r10: 60000013  r9 : bfb7c440  r8 : 0000000f
r7 : 808da22c  r6 : bb39c000  r5 : bb3ebe18  r4 : bb3ebe80
r3 : 87654321  r2 : bfa12c10  r1 : 81802b22  r0 : 00000000
Flags: Nzcv  IRQs off  FIQs on  Mode SVC_32  ISA ARM  Segment kernel
Control: 10c53c7d  Table: 4ecb404a  DAC: 00000017
Process mmcqd/0 (pid: 143, stack limit = 0xbf0be238)
Stack: (0xbf0bfd50 to 0xbf0c0000)
fd40:                                     00000001 00000000 bf0bfd84
87654321
fd60: bfa12c10 7f0b700c bfb7c000 bb3ebda0 bfb7c440 00000001 bf0bfd94
bf0bfd88
fd80: 802d1af8 bfb7c000 bb3ebda0 bfb7c440 bfb7c518 40000013 00000001
bfb7c000
fda0: bf0bfdd4 bf0bfdb0 80438194 80436de0 bb3ebda0 bfb7c000 bb3ebd8c
00000000
fdc0: 00000001 00000001 bf0bfdec bf0bfdd8 804248d4 80437fd8 bb3ebec0
bf0bfe74
fde0: bf0bfe44 bf0bfdf0 804261b8 80424800 bf0be000 bf0be000 bf0be030
bb3ebc6c
fe00: bf0bfe44 00000000 bf0d0900 80047430 bf0bfe10 bf0bfe10 3aee2e82
bb368618
fe20: bb3ebc24 bb3c6000 bb317438 bb317438 bb3ebd9c bb3ebc00 bf0bfea4
bf0bfe48
fe40: 80433ba8 80425ef8 7f08d740 7f066a08 00000000 00000000 bf026000
00000000
fe60: bb3ebda0 00000000 bb3ebc00 00000000 00000038 cec07c38 cec07c00
bb317438
fe80: bb3c6000 bb3ebc24 bb368618 bfb7c000 bb3ebc00 bb3ebc00 bf0bfeec
bf0bfea8
fea0: 804342a4 80433800 bb3ebd9c bb3ebc00 bb317438 bb3ebc2c bb368618
5e565e55
fec0: bb3ebc00 bb3ebc24 bb317438 bb3ebc2c bb368618 bf0be030 bf0be000
00000001
fee0: bf0bff24 bf0bfef0 80434cb4 804341a4 00000000 122c8001 80434bec
bfa87bc4
ff00: 00000000 bb3ebc24 80434bec 00000000 00000000 00000000 bf0bffac
bf0bff28
ff20: 80046520 80434bf8 8182be80 00000000 8182be80 bb3ebc24 00000000
00000000
ff40: dead4ead ffffffff ffffffff 80942bfc 00000000 00000000 807877a5
bf0bff5c
ff60: bf0bff5c 00000000 00000000 dead4ead ffffffff ffffffff 80942bfc
00000000
ff80: 00000000 807877a5 bf0bff88 bf0bff88 bfa87bc4 80046464 00000000
00000000
ffa0: 00000000 bf0bffb0 8000e438 80046470 00000000 00000000 00000000
00000000
ffc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000
00000000
ffe0: 00000000 00000000 00000000 00000000 00000013 00000000 00000000
00000000
Backtrace:
[<80436dd4>] (sdhci_send_command+0x0/0xc58) from [<80438194>]
(sdhci_request+0x1c8/0x1e0)
[<80437fcc>] (sdhci_request+0x0/0x1e0) from [<804248d4>]
(mmc_start_request+0xe0/0xe8)
 r9:00000001 r8:00000001 r7:00000000 r6:bb3ebd8c r5:bfb7c000

[<804247f4>] (mmc_start_request+0x0/0xe8) from [<804261b8>]
(mmc_start_req+0x2cc/0x360)
 r5:bf0bfe74 r4:bb3ebec0
[<80425eec>] (mmc_start_req+0x0/0x360) from [<80433ba8>]
(mmc_blk_issue_rw_rq+0x3b4/0x9a4)
[<804337f4>] (mmc_blk_issue_rw_rq+0x0/0x9a4) from [<804342a4>]
(mmc_blk_issue_rq+0x10c/0x450)
[<80434198>] (mmc_blk_issue_rq+0x0/0x450) from [<80434cb4>]
(mmc_queue_thread+0xc8/0x164)
[<80434bec>] (mmc_queue_thread+0x0/0x164) from [<80046520>]
(kthread+0xbc/0xc8)
[<80046464>] (kthread+0x0/0xc8) from [<8000e438>] (ret_from_fork+0x14/0x20)
 r7:00000000 r6:00000000 r5:80046464 r4:bfa87bc4
Code: e1a00006 e3a08000 e158000a aa00000c (e5901000)

I've narrowed this down to sdhci_adma_table_pre() which is inlined, but
haven't gotten much further.  Anyway, I think it's probably unrelated --
surely it wouldn't be _caused_ by adding the barriers -- and I'll have
to figure out some way to work around it (perhaps it's fixed in 3.12).


> It does look like the preempt inc or dec is slipping out and somehow
> triggers the might_sleep() warning. I don't see clearly how this
> could happen yet, since each of the inc/dec and the test are touching
> preempt_count(), but it's worth a try.
> 
> Maybe on ARM the current_thread_info() macro somehow hides important
> info from the compiler and it mistakenly reorders inc/dec vs the
> test. Another thing to try out (in addition to the first one) would
> be to try changing current_thread_info(), e.g., by turning asm ("sp")
> into a volatile inline assembly, and by adding "memory" clobbers to
> it.

Haven't tried this yet.