Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1231929 > unrolled thread

Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function called from invalid context at kernel/workqueue.c:2680

Started byJiri Kosina <jikos@kernel.org>
First post2015-09-24 10:00 +0200
Last post2015-09-24 10:10 +0200
Articles 15 — 2 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Jiri Kosina <jikos@kernel.org> - 2015-09-24 10:00 +0200
    Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Jiri Kosina <jikos@kernel.org> - 2015-09-24 10:10 +0200
      Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-24 10:20 +0200
        Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Jiri Kosina <jikos@kernel.org> - 2015-09-24 10:30 +0200
          Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-25 08:50 +0200
          Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Jiri Kosina <jikos@kernel.org> - 2015-09-25 14:10 +0200
            Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-25 14:20 +0200
              Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Jiri Kosina <jikos@kernel.org> - 2015-09-25 14:20 +0200
                Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Jiri Kosina <jikos@kernel.org> - 2015-09-25 14:50 +0200
                  Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-25 14:50 +0200
                    Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Jiri Kosina <jikos@kernel.org> - 2015-09-25 15:20 +0200
                      Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-25 15:20 +0200
                      Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-27 10:40 +0200
            Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-25 14:40 +0200
    Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function  called from invalid context at kernel/workqueue.c:2680 Sedat Dilek <sedat.dilek@gmail.com> - 2015-09-24 10:10 +0200

#1231929 — Re: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function called from invalid context at kernel/workqueue.c:2680

FromJiri Kosina <jikos@kernel.org>
Date2015-09-24 10:00 +0200
SubjectRe: [Linux v4.2] workqueue: llvmlinux: acpid: BUG: sleeping function called from invalid context at kernel/workqueue.c:2680
Message-ID<qc9BE-5cV-9@gated-at.bofh.it>
On Thu, 24 Sep 2015, Sedat Dilek wrote:

> I am seeing this call-trace when compiling a Linux v4.2.y or Linux
> v4.3-rcN kernel with my llvm-toolchain and llvmlinux-amd64 patchset.
> CLANG sometimes catches things which GCC does not.
> 
> Not sure if this is a workqueue or hid issue...
> 
> [   24.824396] BUG: sleeping function called from invalid context at
> kernel/workqueue.c:2767
> [   24.824511] in_atomic(): 0, irqs_disabled(): 1, pid: 1485, name: acpid
> [   24.824596] 3 locks held by acpid/1485:
> [   24.824599]  #0:  (&evdev->mutex){+.+...}, at: [<ffffffff8174a2bc>]
> evdev_release+0xbc/0xf0
> [   24.824612]  #1:  (&dev->mutex#2){+.+...}, at: [<ffffffff817419d7>]
> input_close_device+0x27/0x70
> [   24.824624]  #2:  (hid_open_mut){+.+...}, at: [<ffffffffa0056388>]
> usbhid_close+0x28/0xb0 [usbhid]
> [   24.824636] irq event stamp: 7914
> [   24.824639] hardirqs last  enabled at (7913): [<ffffffff8192a2b2>]
> _raw_spin_unlock_irq+0x32/0x60
> [   24.824646] hardirqs last disabled at (7914): [<ffffffff81120e37>]
> del_timer_sync+0x37/0x110
> [   24.824652] softirqs last  enabled at (7220): [<ffffffff818b06a9>]
> local_bh_enable+0x9/0x20
> [   24.824659] softirqs last disabled at (7218): [<ffffffff818b0689>]
> local_bh_disable+0x9/0x20
> [   24.824666] CPU: 1 PID: 1485 Comm: acpid Not tainted
> 4.3.0-rc2-3-llvmlinux-amd64 #2
> [   24.824670] Hardware name: SAMSUNG ELECTRONICS CO., LTD.
> 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013
> [   24.824673]  ffff8800d4806948 0000000000000096 0000000000000000
> ffff8800b8933bf8
> [   24.824680]  ffffffff8149a4ad ffff8800b8933c28 ffffffff810cd53a
> ffffffff81c56fcc
> [   24.824686]  ffff8801185f4240 0000000000000000 0000000000000acf
> ffff8800b8933c68
> [   24.824693] Call Trace:
> [   24.824699]  [<ffffffff8149a4ad>] dump_stack+0x7d/0xa0
> [   24.824705]  [<ffffffff810cd53a>] ___might_sleep+0x28a/0x2a0
> [   24.824709]  [<ffffffff810cd23f>] __might_sleep+0x4f/0xc0
> [   24.824715]  [<ffffffff810b01de>] __cancel_work_timer+0x2e/0x270
> [   24.824720]  [<ffffffff8192a252>] ? _raw_spin_unlock_irqrestore+0x52/0x80
> [   24.824725]  [<ffffffff81120ded>] ? try_to_del_timer_sync+0xad/0xc0
> [   24.824730]  [<ffffffff810b01a8>] cancel_work_sync+0x18/0x20

Could you please (on a kernel compiled with debuginfo) resolve (using 
addr2line) those offsets to source code lines? Especially 
__cancel_work_timer+0x2e will be interesting in this case.

__cancel_work_timer() calls try_to_grab_pending() which disabled IRQs, but 
as far as I can see, the only way it goes to sleep then is when 
try_to_grab_pending() returned -ENOENT, but in such case it reenabled IRQs 
explicitly before.

Also the fact that "hardirqs last disabled at (7914): [<ffffffff81120e37>] 
del_timer_sync+0x37/0x110" is a bit puzzling as well, but AFAICS 
del_timer_sync is complete outside the codepath that's on stack.

[ ... snip ... ]
> >> [   24.705463] BUG: sleeping function called from invalid context at
> >> kernel/workqueue.c:2680
> >> [   24.705576] in_atomic(): 0, irqs_disabled(): 1, pid: 1447, name: acpid
> >> [   24.705662] 3 locks held by acpid/1447:
> >> [   24.705664]  #0:  (&evdev->mutex){+.+...}, at: [<ffffffff8173b9ac>]
> >> evdev_release+0xbc/0xf0
> >> [   24.705678]  #1:  (&dev->mutex#2){+.+...}, at: [<ffffffff81733117>]
> >> input_close_device+0x27/0x70
> >> [   24.705691]  #2:  (hid_open_mut){+.+...}, at: [<ffffffffa0056378>]
> >> usbhid_close+0x28/0xb0 [usbhid]
> >> [   24.705704] irq event stamp: 19968
> >> [   24.705706] hardirqs last  enabled at (19967): [<ffffffff81917ff2>]
> >> _raw_spin_unlock_irq+0x32/0x60
> >> [   24.705713] hardirqs last disabled at (19968): [<ffffffff81120477>]
> >> del_timer_sync+0x37/0x110
> >> [   24.705720] softirqs last  enabled at (18890): [<ffffffff8189e7c9>]
> >> local_bh_enable+0x9/0x20
> >> [   24.705726] softirqs last disabled at (18888): [<ffffffff8189e7a9>]
> >> local_bh_disable+0x9/0x20
> >> [   24.705734] CPU: 2 PID: 1447 Comm: acpid Not tainted
> >> 4.2.0-2-llvmlinux-small #2
> >> [   24.705737] Hardware name: SAMSUNG ELECTRONICS CO., LTD.
> >> 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013
> >> [   24.705741]  ffff8800d57ea948 0000000000000092 0000000000000000
> >> ffff8800bb3e3aa8
> >> [   24.705748]  ffffffff8149287d ffff8800bb3e3ad8 ffffffff810cbf7a
> >> ffffffff81c51a34
> >> [   24.705754]  ffff8800d3095000 0000000000000000 0000000000000a78
> >> ffff8800bb3e3b18
> >> [   24.705761] Call Trace:
> >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
> >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
> >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
> >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
> >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
> >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
> >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
> >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
> >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
> >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260

This one is even more strange. It says that flush_work() is being called 
from __cancel_work_timer() with IRQs disabled, but flags are explicitly 
restored just one statement before that, and usbhid_close() explicitly 
calls cancel_work_sync() after unconditionally enabling interrupts.

So I am not able to make any sense of either of the traces really.

Are you seeing this with the same .config with GCC-compiled kernel as 
well?

-- 
Jiri Kosina
SUSE Labs

--
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/

[toc] | [next] | [standalone]

#1231931

FromJiri Kosina <jikos@kernel.org>
Date2015-09-24 10:10 +0200
Message-ID<qc9Lj-5Dv-3@gated-at.bofh.it>
In reply to#1231929
On Thu, 24 Sep 2015, Jiri Kosina wrote:

> > >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
> > >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
> > >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
> > >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
> > >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
> > >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
> > >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
> > >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
> > >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
> > >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
> 
> This one is even more strange. It says that flush_work() is being called 
> from __cancel_work_timer() with IRQs disabled, but flags are explicitly 
> restored just one statement before that, and usbhid_close() explicitly 
> calls cancel_work_sync() after unconditionally enabling interrupts.
> 
> So I am not able to make any sense of either of the traces really.
> 
> Are you seeing this with the same .config with GCC-compiled kernel as 
> well?

Actually could you please provide disassembly of your 
__cancel_work_timer()?

One explanation would be LLVM not considering local_irq_restore() a 
compiler memory barrier, but I am pretty sure it'll expose much more 
breakage if that'd be the case.

-- 
Jiri Kosina
SUSE Labs
--
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/

[toc] | [prev] | [next] | [standalone]

#1231936

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-24 10:20 +0200
Message-ID<qc9V0-5OU-5@gated-at.bofh.it>
In reply to#1231931
On Thu, Sep 24, 2015 at 10:03 AM, Jiri Kosina <jikos@kernel.org> wrote:
> On Thu, 24 Sep 2015, Jiri Kosina wrote:
>
>> > >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
>> > >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
>> > >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
>> > >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
>> > >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
>> > >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
>> > >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
>> > >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
>> > >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
>> > >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
>>
>> This one is even more strange. It says that flush_work() is being called
>> from __cancel_work_timer() with IRQs disabled, but flags are explicitly
>> restored just one statement before that, and usbhid_close() explicitly
>> calls cancel_work_sync() after unconditionally enabling interrupts.
>>
>> So I am not able to make any sense of either of the traces really.
>>
>> Are you seeing this with the same .config with GCC-compiled kernel as
>> well?
>
> Actually could you please provide disassembly of your
> __cancel_work_timer()?
>

Disassembly of which file - corresponding workqueue or hid file?

> One explanation would be LLVM not considering local_irq_restore() a
> compiler memory barrier, but I am pretty sure it'll expose much more
> breakage if that'd be the case.
>

Can you point me where I can find more informations about "compiler
memory barrier" or explain in a few words if possible?

Thanks.

I can provide the files this evening...

/me in front of a Windows machine.

- Sedat -
--
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/

[toc] | [prev] | [next] | [standalone]

#1231947

FromJiri Kosina <jikos@kernel.org>
Date2015-09-24 10:30 +0200
Message-ID<qca4G-60q-31@gated-at.bofh.it>
In reply to#1231936
On Thu, 24 Sep 2015, Sedat Dilek wrote:

> >> > >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
> >> > >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
> >> > >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
> >> > >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
> >> > >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
> >> > >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
> >> > >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
> >> > >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
> >> > >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
> >> > >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
> >>
> >> This one is even more strange. It says that flush_work() is being called
> >> from __cancel_work_timer() with IRQs disabled, but flags are explicitly
> >> restored just one statement before that, and usbhid_close() explicitly
> >> calls cancel_work_sync() after unconditionally enabling interrupts.
> >>
> >> So I am not able to make any sense of either of the traces really.
> >>
> >> Are you seeing this with the same .config with GCC-compiled kernel as
> >> well?
> >
> > Actually could you please provide disassembly of your
> > __cancel_work_timer()?
> >
> 
> Disassembly of which file - corresponding workqueue or hid file?

	make kernel/workqueue.o
	objdump -Dr kernel/workqueue.o

and copy/paste output for __cancel_work_timer function.

> > One explanation would be LLVM not considering local_irq_restore() a
> > compiler memory barrier, but I am pretty sure it'll expose much more
> > breakage if that'd be the case.
> 
> Can you point me where I can find more informations about "compiler
> memory barrier" or explain in a few words if possible?

If compiler would not take "memory" clobber (while disabling IRQs) as a 
reordering barrier, it wouldn't see any data dependency between 
local_irq_restore(flags) and flush_work(data) and could reorder them, 
resulting in flush_work() being called with IRQs disabled.

-- 
Jiri Kosina
SUSE Labs

--
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/

[toc] | [prev] | [next] | [standalone]

#1232608

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-25 08:50 +0200
Message-ID<qcuZs-23t-35@gated-at.bofh.it>
In reply to#1231947
On Thu, Sep 24, 2015 at 10:21 AM, Jiri Kosina <jikos@kernel.org> wrote:
> On Thu, 24 Sep 2015, Sedat Dilek wrote:
>
>> >> > >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
>> >> > >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
>> >> > >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
>> >> > >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
>> >> > >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
>> >> > >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
>> >> > >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
>> >> > >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
>> >> > >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
>> >> > >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
>> >>
>> >> This one is even more strange. It says that flush_work() is being called
>> >> from __cancel_work_timer() with IRQs disabled, but flags are explicitly
>> >> restored just one statement before that, and usbhid_close() explicitly
>> >> calls cancel_work_sync() after unconditionally enabling interrupts.
>> >>
>> >> So I am not able to make any sense of either of the traces really.
>> >>
>> >> Are you seeing this with the same .config with GCC-compiled kernel as
>> >> well?
>> >
>> > Actually could you please provide disassembly of your
>> > __cancel_work_timer()?
>> >
>>
>> Disassembly of which file - corresponding workqueue or hid file?
>
>         make kernel/workqueue.o
>         objdump -Dr kernel/workqueue.o
>
> and copy/paste output for __cancel_work_timer function.
>
>> > One explanation would be LLVM not considering local_irq_restore() a
>> > compiler memory barrier, but I am pretty sure it'll expose much more
>> > breakage if that'd be the case.
>>
>> Can you point me where I can find more informations about "compiler
>> memory barrier" or explain in a few words if possible?
>
> If compiler would not take "memory" clobber (while disabling IRQs) as a
> reordering barrier, it wouldn't see any data dependency between
> local_irq_restore(flags) and flush_work(data) and could reorder them,
> resulting in flush_work() being called with IRQs disabled.
>

BTW, is membarrier_test helpful in this case?

I asked parallelly on LTP ML is there exists something similiar.

- Sedat -

[1] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/tools/testing/selftests/membarrier
[2] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/plain/tools/testing/selftests/membarrier/membarrier_test.c
--
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/

[toc] | [prev] | [next] | [standalone]

#1232742

FromJiri Kosina <jikos@kernel.org>
Date2015-09-25 14:10 +0200
Message-ID<qczZ8-T1-13@gated-at.bofh.it>
In reply to#1231947
On Thu, 24 Sep 2015, Sedat Dilek wrote:

> >> >> > >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
> >> >> > >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
> >> >> > >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
> >> >> > >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
> >> >> > >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
> >> >> > >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
> >> >> > >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
> >> >> > >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
> >> >> > >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
> >> >> > >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
> >> >>
> >> >> This one is even more strange. It says that flush_work() is being called
> >> >> from __cancel_work_timer() with IRQs disabled, but flags are explicitly
> >> >> restored just one statement before that, and usbhid_close() explicitly
> >> >> calls cancel_work_sync() after unconditionally enabling interrupts.
> >> >>
> >> >> So I am not able to make any sense of either of the traces really.
> >> >>
> >> >> Are you seeing this with the same .config with GCC-compiled kernel as
> >> >> well?
> >> >
> >> > Actually could you please provide disassembly of your
> >> > __cancel_work_timer()?
> >> >
> >>
> >> Disassembly of which file - corresponding workqueue or hid file?
> >
> >         make kernel/workqueue.o
> >         objdump -Dr kernel/workqueue.o
> >
> > and copy/paste output for __cancel_work_timer function.
> >
> 
> It was a bit long, so I attached the full output.

    216a:       ff 14 25 00 00 00 00    callq  *0x0
                        216d: R_X86_64_32S      pv_irq_ops+0x8
    2171:       4c 89 ef                mov    %r13,%rdi
    2174:       e8 00 00 00 00          callq  2179 <__cancel_work_timer+0x189>
                        2175: R_X86_64_PC32     flush_work-0x4

So the ordering generated by compiler is correct here.

This however:

[   24.824639] hardirqs last  enabled at (7913): [<ffffffff8192a2b2>] _raw_spin_unlock_irq+0x32/0x60
[   24.824646] hardirqs last disabled at (7914): [<ffffffff81120e37>] del_timer_sync+0x37/0x110

combined with the stacktrace above, doesn't still make too much sense; IRQ 
disable/enable is properly paired in del_timer_sync() and timer base lock 
locking.

Could you look into the generated assembly whether the sequence

        local_irq_save(flags);
        lock_map_acquire(&timer->lockdep_map);
        lock_map_release(&timer->lockdep_map);
        local_irq_restore(flags);

in del_timer_sync() hasn't been optimized in some damaging way?

-- 
Jiri Kosina
SUSE Labs

--
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/

[toc] | [prev] | [next] | [standalone]

#1232751

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-25 14:20 +0200
Message-ID<qcA8P-14l-31@gated-at.bofh.it>
In reply to#1232742
On Fri, Sep 25, 2015 at 2:00 PM, Jiri Kosina <jikos@kernel.org> wrote:
> On Thu, 24 Sep 2015, Sedat Dilek wrote:
>
>> >> >> > >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
>> >> >> > >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
>> >> >> > >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
>> >> >> > >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
>> >> >> > >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
>> >> >> > >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
>> >> >> > >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
>> >> >> > >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
>> >> >> > >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
>> >> >> > >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
>> >> >>
>> >> >> This one is even more strange. It says that flush_work() is being called
>> >> >> from __cancel_work_timer() with IRQs disabled, but flags are explicitly
>> >> >> restored just one statement before that, and usbhid_close() explicitly
>> >> >> calls cancel_work_sync() after unconditionally enabling interrupts.
>> >> >>
>> >> >> So I am not able to make any sense of either of the traces really.
>> >> >>
>> >> >> Are you seeing this with the same .config with GCC-compiled kernel as
>> >> >> well?
>> >> >
>> >> > Actually could you please provide disassembly of your
>> >> > __cancel_work_timer()?
>> >> >
>> >>
>> >> Disassembly of which file - corresponding workqueue or hid file?
>> >
>> >         make kernel/workqueue.o
>> >         objdump -Dr kernel/workqueue.o
>> >
>> > and copy/paste output for __cancel_work_timer function.
>> >
>>
>> It was a bit long, so I attached the full output.
>
>     216a:       ff 14 25 00 00 00 00    callq  *0x0
>                         216d: R_X86_64_32S      pv_irq_ops+0x8
>     2171:       4c 89 ef                mov    %r13,%rdi
>     2174:       e8 00 00 00 00          callq  2179 <__cancel_work_timer+0x189>
>                         2175: R_X86_64_PC32     flush_work-0x4
>
> So the ordering generated by compiler is correct here.
>
> This however:
>
> [   24.824639] hardirqs last  enabled at (7913): [<ffffffff8192a2b2>] _raw_spin_unlock_irq+0x32/0x60
> [   24.824646] hardirqs last disabled at (7914): [<ffffffff81120e37>] del_timer_sync+0x37/0x110
>
> combined with the stacktrace above, doesn't still make too much sense; IRQ
> disable/enable is properly paired in del_timer_sync() and timer base lock
> locking.
>
> Could you look into the generated assembly whether the sequence
>
>         local_irq_save(flags);
>         lock_map_acquire(&timer->lockdep_map);
>         lock_map_release(&timer->lockdep_map);
>         local_irq_restore(flags);
>
> in del_timer_sync() hasn't been optimized in some damaging way?
>

I am looking into my CLANG objdump...

$ egrep -nr 'save|restore|acquire|release'
objdump-Dr_kernel-workqueue_o_CLANG-3-7.txt | egrep 'irq|map'
5718:                   4601: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4
5766:                   4699: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
6173:                   4bd9: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
6265:                   4d05: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4

...this is what I have.

Does that help?

- Sedat -
--
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/

[toc] | [prev] | [next] | [standalone]

#1232752

FromJiri Kosina <jikos@kernel.org>
Date2015-09-25 14:20 +0200
Message-ID<qcA8P-14l-33@gated-at.bofh.it>
In reply to#1232751
On Fri, 25 Sep 2015, Sedat Dilek wrote:

> > This however:
> >
> > [   24.824639] hardirqs last  enabled at (7913): [<ffffffff8192a2b2>] _raw_spin_unlock_irq+0x32/0x60
> > [   24.824646] hardirqs last disabled at (7914): [<ffffffff81120e37>] del_timer_sync+0x37/0x110
> >
> > combined with the stacktrace above, doesn't still make too much sense; IRQ
> > disable/enable is properly paired in del_timer_sync() and timer base lock
> > locking.
> >
> > Could you look into the generated assembly whether the sequence
> >
> >         local_irq_save(flags);
> >         lock_map_acquire(&timer->lockdep_map);
> >         lock_map_release(&timer->lockdep_map);
> >         local_irq_restore(flags);
> >
> > in del_timer_sync() hasn't been optimized in some damaging way?
> >
> 
> I am looking into my CLANG objdump...
> 
> $ egrep -nr 'save|restore|acquire|release'
> objdump-Dr_kernel-workqueue_o_CLANG-3-7.txt | egrep 'irq|map'
> 5718:                   4601: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4
> 5766:                   4699: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
> 6173:                   4bd9: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
> 6265:                   4d05: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4
> 
> ...this is what I have.
> 
> Does that help?

It doesn't. I am asking for disassembly of del_timer_sync() (that's in 
kernel/time/timer.o).

-- 
Jiri Kosina
SUSE Labs

--
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/

[toc] | [prev] | [next] | [standalone]

#1232768

FromJiri Kosina <jikos@kernel.org>
Date2015-09-25 14:50 +0200
Message-ID<qcABQ-1BX-9@gated-at.bofh.it>
In reply to#1232752
On Fri, 25 Sep 2015, Sedat Dilek wrote:

> >> $ egrep -nr 'save|restore|acquire|release'
> >> objdump-Dr_kernel-workqueue_o_CLANG-3-7.txt | egrep 'irq|map'
> >> 5718:                   4601: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4
> >> 5766:                   4699: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
> >> 6173:                   4bd9: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
> >> 6265:                   4d05: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4
> >>
> >> ...this is what I have.
> >>
> >> Does that help?
> >
> > It doesn't. I am asking for disassembly of del_timer_sync() (that's in
> > kernel/time/timer.o).
> >
> 
> See attached file.

The sequence looks correct. So I don't really see what call sequence could 
lead to calling flush_work() from __cancel_work_timer() with IRQs 
disabled (which is what your stacktrace is suggesting).

The fact that this doesn't happen with GCC-compiled kernels is really 
suspicious.

-- 
Jiri Kosina
SUSE Labs

--
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/

[toc] | [prev] | [next] | [standalone]

#1232773

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-25 14:50 +0200
Message-ID<qcABR-1BX-19@gated-at.bofh.it>
In reply to#1232768
On Fri, Sep 25, 2015 at 2:40 PM, Jiri Kosina <jikos@kernel.org> wrote:
> On Fri, 25 Sep 2015, Sedat Dilek wrote:
>
>> >> $ egrep -nr 'save|restore|acquire|release'
>> >> objdump-Dr_kernel-workqueue_o_CLANG-3-7.txt | egrep 'irq|map'
>> >> 5718:                   4601: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4
>> >> 5766:                   4699: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
>> >> 6173:                   4bd9: R_X86_64_PC32     _raw_spin_lock_irqsave-0x4
>> >> 6265:                   4d05: R_X86_64_PC32     _raw_spin_unlock_irqrestore-0x4
>> >>
>> >> ...this is what I have.
>> >>
>> >> Does that help?
>> >
>> > It doesn't. I am asking for disassembly of del_timer_sync() (that's in
>> > kernel/time/timer.o).
>> >
>>
>> See attached file.
>
> The sequence looks correct. So I don't really see what call sequence could
> lead to calling flush_work() from __cancel_work_timer() with IRQs
> disabled (which is what your stacktrace is suggesting).
>
> The fact that this doesn't happen with GCC-compiled kernels is really
> suspicious.
>

Hm, and now?

Shall I try a different OptLevel than default -O2?

CONFIG_LOCKDEP=n ?

- Sedat -
--
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/

[toc] | [prev] | [next] | [standalone]

#1232799

FromJiri Kosina <jikos@kernel.org>
Date2015-09-25 15:20 +0200
Message-ID<qcB4T-2t3-23@gated-at.bofh.it>
In reply to#1232773
On Fri, 25 Sep 2015, Sedat Dilek wrote:

> > The sequence looks correct. So I don't really see what call sequence could
> > lead to calling flush_work() from __cancel_work_timer() with IRQs
> > disabled (which is what your stacktrace is suggesting).
> >
> > The fact that this doesn't happen with GCC-compiled kernels is really
> > suspicious.
> >
> 
> Hm, and now?

I guess one of the things to try is to generate ftrace graph trace to see 
what exact function sequence leads to this warning.

-- 
Jiri Kosina
SUSE Labs

--
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/

[toc] | [prev] | [next] | [standalone]

#1232802

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-25 15:20 +0200
Message-ID<qcB4T-2t3-21@gated-at.bofh.it>
In reply to#1232799
On Fri, Sep 25, 2015 at 3:13 PM, Jiri Kosina <jikos@kernel.org> wrote:
> On Fri, 25 Sep 2015, Sedat Dilek wrote:
>
>> > The sequence looks correct. So I don't really see what call sequence could
>> > lead to calling flush_work() from __cancel_work_timer() with IRQs
>> > disabled (which is what your stacktrace is suggesting).
>> >
>> > The fact that this doesn't happen with GCC-compiled kernels is really
>> > suspicious.
>> >
>>
>> Hm, and now?
>
> I guess one of the things to try is to generate ftrace graph trace to see
> what exact function sequence leads to this warning.
>

Can I do this via kernel-boot-parameter?
No experiences with ftrace here.

- Sedat -
--
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/

[toc] | [prev] | [next] | [standalone]

#1233637

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-27 10:40 +0200
Message-ID<qdfEZ-1QA-3@gated-at.bofh.it>
In reply to#1232799
On Sun, Sep 27, 2015 at 10:10 AM, Sedat Dilek <sedat.dilek@gmail.com> wrote:
> On Fri, Sep 25, 2015 at 3:13 PM, Jiri Kosina <jikos@kernel.org> wrote:
>> On Fri, 25 Sep 2015, Sedat Dilek wrote:
>>
>>> > The sequence looks correct. So I don't really see what call sequence could
>>> > lead to calling flush_work() from __cancel_work_timer() with IRQs
>>> > disabled (which is what your stacktrace is suggesting).
>>> >
>>> > The fact that this doesn't happen with GCC-compiled kernels is really
>>> > suspicious.
>>> >
>>>
>>> Hm, and now?
>>
>> I guess one of the things to try is to generate ftrace graph trace to see
>> what exact function sequence leads to this warning.
>>
>
> Which kernel-config settings are helpful for ftrace and tracing at all?
>
> I have here...
>
> CONFIG_IRQSOFF_TRACER=n
>
> ...is that helpful to trigger why I see "irqs_disabled"...
>
> [   23.874836] BUG: sleeping function called from invalid context at
> kernel/workqueue.c:2678
> [   23.874902] in_atomic(): 0, irqs_disabled(): 1, pid: 1411, name: acpid
>
> Also independent of this issue I would like to set...
>
> CONFIG_LOCKDEP=y
> CONFIG_DEBUG_LOCKDEP=y <--- XXX: New setting
>
> I recall something like a trace/tracing filesystem?
> I cannot find or remember the Kconfig - do you?
>

It is CONFIG_TRACING=y (see [1] and "tracefs: Add new tracefs file
system" from [2]).

- Sedat -

[1] https://lwn.net/Articles/631798/
[2] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=4282d60689d4f21b40692029080440cc58e8a17d
--
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/

[toc] | [prev] | [next] | [standalone]

#1232763

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-25 14:40 +0200
Message-ID<qcAsa-1qE-7@gated-at.bofh.it>
In reply to#1232742
On Fri, Sep 25, 2015 at 2:00 PM, Jiri Kosina <jikos@kernel.org> wrote:
> On Thu, 24 Sep 2015, Sedat Dilek wrote:
>
>> >> >> > >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
>> >> >> > >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
>> >> >> > >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
>> >> >> > >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
>> >> >> > >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
>> >> >> > >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
>> >> >> > >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
>> >> >> > >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
>> >> >> > >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
>> >> >> > >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
>> >> >>
>> >> >> This one is even more strange. It says that flush_work() is being called
>> >> >> from __cancel_work_timer() with IRQs disabled, but flags are explicitly
>> >> >> restored just one statement before that, and usbhid_close() explicitly
>> >> >> calls cancel_work_sync() after unconditionally enabling interrupts.
>> >> >>
>> >> >> So I am not able to make any sense of either of the traces really.
>> >> >>
>> >> >> Are you seeing this with the same .config with GCC-compiled kernel as
>> >> >> well?
>> >> >
>> >> > Actually could you please provide disassembly of your
>> >> > __cancel_work_timer()?
>> >> >
>> >>
>> >> Disassembly of which file - corresponding workqueue or hid file?
>> >
>> >         make kernel/workqueue.o
>> >         objdump -Dr kernel/workqueue.o
>> >
>> > and copy/paste output for __cancel_work_timer function.
>> >
>>
>> It was a bit long, so I attached the full output.
>
>     216a:       ff 14 25 00 00 00 00    callq  *0x0
>                         216d: R_X86_64_32S      pv_irq_ops+0x8
>     2171:       4c 89 ef                mov    %r13,%rdi
>     2174:       e8 00 00 00 00          callq  2179 <__cancel_work_timer+0x189>
>                         2175: R_X86_64_PC32     flush_work-0x4
>
> So the ordering generated by compiler is correct here.
>
> This however:
>
> [   24.824639] hardirqs last  enabled at (7913): [<ffffffff8192a2b2>] _raw_spin_unlock_irq+0x32/0x60
> [   24.824646] hardirqs last disabled at (7914): [<ffffffff81120e37>] del_timer_sync+0x37/0x110
>
> combined with the stacktrace above, doesn't still make too much sense; IRQ
> disable/enable is properly paired in del_timer_sync() and timer base lock
> locking.
>
> Could you look into the generated assembly whether the sequence
>
>         local_irq_save(flags);
>         lock_map_acquire(&timer->lockdep_map);
>         lock_map_release(&timer->lockdep_map);
>         local_irq_restore(flags);
>
> in del_timer_sync() hasn't been optimized in some damaging way?
>

OK, now I see what you mean that snippet...

[ kernel/time/timer.c ]
...
int del_timer_sync(struct timer_list *timer)
{
#ifdef CONFIG_LOCKDEP
unsigned long flags;

/*
* If lockdep gives a backtrace here, please reference
* the synchronization rules above.
*/
local_irq_save(flags);
lock_map_acquire(&timer->lockdep_map);
lock_map_release(&timer->lockdep_map);
local_irq_restore(flags);
#endif
...

So, I could try to see with CONFIG_LOCKDEP=n ?

- Sedat -

[1] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/kernel/time/timer.c?id=v4.3-rc2#n1080
--
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/

[toc] | [prev] | [next] | [standalone]

#1231932

FromSedat Dilek <sedat.dilek@gmail.com>
Date2015-09-24 10:10 +0200
Message-ID<qc9Lk-5Dv-5@gated-at.bofh.it>
In reply to#1231929
On Thu, Sep 24, 2015 at 9:57 AM, Jiri Kosina <jikos@kernel.org> wrote:
> On Thu, 24 Sep 2015, Sedat Dilek wrote:
>
>> I am seeing this call-trace when compiling a Linux v4.2.y or Linux
>> v4.3-rcN kernel with my llvm-toolchain and llvmlinux-amd64 patchset.
>> CLANG sometimes catches things which GCC does not.
>>
>> Not sure if this is a workqueue or hid issue...
>>
>> [   24.824396] BUG: sleeping function called from invalid context at
>> kernel/workqueue.c:2767
>> [   24.824511] in_atomic(): 0, irqs_disabled(): 1, pid: 1485, name: acpid
>> [   24.824596] 3 locks held by acpid/1485:
>> [   24.824599]  #0:  (&evdev->mutex){+.+...}, at: [<ffffffff8174a2bc>]
>> evdev_release+0xbc/0xf0
>> [   24.824612]  #1:  (&dev->mutex#2){+.+...}, at: [<ffffffff817419d7>]
>> input_close_device+0x27/0x70
>> [   24.824624]  #2:  (hid_open_mut){+.+...}, at: [<ffffffffa0056388>]
>> usbhid_close+0x28/0xb0 [usbhid]
>> [   24.824636] irq event stamp: 7914
>> [   24.824639] hardirqs last  enabled at (7913): [<ffffffff8192a2b2>]
>> _raw_spin_unlock_irq+0x32/0x60
>> [   24.824646] hardirqs last disabled at (7914): [<ffffffff81120e37>]
>> del_timer_sync+0x37/0x110
>> [   24.824652] softirqs last  enabled at (7220): [<ffffffff818b06a9>]
>> local_bh_enable+0x9/0x20
>> [   24.824659] softirqs last disabled at (7218): [<ffffffff818b0689>]
>> local_bh_disable+0x9/0x20
>> [   24.824666] CPU: 1 PID: 1485 Comm: acpid Not tainted
>> 4.3.0-rc2-3-llvmlinux-amd64 #2
>> [   24.824670] Hardware name: SAMSUNG ELECTRONICS CO., LTD.
>> 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013
>> [   24.824673]  ffff8800d4806948 0000000000000096 0000000000000000
>> ffff8800b8933bf8
>> [   24.824680]  ffffffff8149a4ad ffff8800b8933c28 ffffffff810cd53a
>> ffffffff81c56fcc
>> [   24.824686]  ffff8801185f4240 0000000000000000 0000000000000acf
>> ffff8800b8933c68
>> [   24.824693] Call Trace:
>> [   24.824699]  [<ffffffff8149a4ad>] dump_stack+0x7d/0xa0
>> [   24.824705]  [<ffffffff810cd53a>] ___might_sleep+0x28a/0x2a0
>> [   24.824709]  [<ffffffff810cd23f>] __might_sleep+0x4f/0xc0
>> [   24.824715]  [<ffffffff810b01de>] __cancel_work_timer+0x2e/0x270
>> [   24.824720]  [<ffffffff8192a252>] ? _raw_spin_unlock_irqrestore+0x52/0x80
>> [   24.824725]  [<ffffffff81120ded>] ? try_to_del_timer_sync+0xad/0xc0
>> [   24.824730]  [<ffffffff810b01a8>] cancel_work_sync+0x18/0x20
>
> Could you please (on a kernel compiled with debuginfo) resolve (using
> addr2line) those offsets to source code lines? Especially
> __cancel_work_timer+0x2e will be interesting in this case.
>

Hi,

I can do that, but not sure if I have enough disc-space on my
Ubuntu/precise AMD64 system.

> __cancel_work_timer() calls try_to_grab_pending() which disabled IRQs, but
> as far as I can see, the only way it goes to sleep then is when
> try_to_grab_pending() returned -ENOENT, but in such case it reenabled IRQs
> explicitly before.
>
> Also the fact that "hardirqs last disabled at (7914): [<ffffffff81120e37>]
> del_timer_sync+0x37/0x110" is a bit puzzling as well, but AFAICS
> del_timer_sync is complete outside the codepath that's on stack.
>
> [ ... snip ... ]
>> >> [   24.705463] BUG: sleeping function called from invalid context at
>> >> kernel/workqueue.c:2680
>> >> [   24.705576] in_atomic(): 0, irqs_disabled(): 1, pid: 1447, name: acpid
>> >> [   24.705662] 3 locks held by acpid/1447:
>> >> [   24.705664]  #0:  (&evdev->mutex){+.+...}, at: [<ffffffff8173b9ac>]
>> >> evdev_release+0xbc/0xf0
>> >> [   24.705678]  #1:  (&dev->mutex#2){+.+...}, at: [<ffffffff81733117>]
>> >> input_close_device+0x27/0x70
>> >> [   24.705691]  #2:  (hid_open_mut){+.+...}, at: [<ffffffffa0056378>]
>> >> usbhid_close+0x28/0xb0 [usbhid]
>> >> [   24.705704] irq event stamp: 19968
>> >> [   24.705706] hardirqs last  enabled at (19967): [<ffffffff81917ff2>]
>> >> _raw_spin_unlock_irq+0x32/0x60
>> >> [   24.705713] hardirqs last disabled at (19968): [<ffffffff81120477>]
>> >> del_timer_sync+0x37/0x110
>> >> [   24.705720] softirqs last  enabled at (18890): [<ffffffff8189e7c9>]
>> >> local_bh_enable+0x9/0x20
>> >> [   24.705726] softirqs last disabled at (18888): [<ffffffff8189e7a9>]
>> >> local_bh_disable+0x9/0x20
>> >> [   24.705734] CPU: 2 PID: 1447 Comm: acpid Not tainted
>> >> 4.2.0-2-llvmlinux-small #2
>> >> [   24.705737] Hardware name: SAMSUNG ELECTRONICS CO., LTD.
>> >> 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013
>> >> [   24.705741]  ffff8800d57ea948 0000000000000092 0000000000000000
>> >> ffff8800bb3e3aa8
>> >> [   24.705748]  ffffffff8149287d ffff8800bb3e3ad8 ffffffff810cbf7a
>> >> ffffffff81c51a34
>> >> [   24.705754]  ffff8800d3095000 0000000000000000 0000000000000a78
>> >> ffff8800bb3e3b18
>> >> [   24.705761] Call Trace:
>> >> [   24.705767]  [<ffffffff8149287d>] dump_stack+0x7d/0xa0
>> >> [   24.705774]  [<ffffffff810cbf7a>] ___might_sleep+0x28a/0x2a0
>> >> [   24.705779]  [<ffffffff810cbc7f>] __might_sleep+0x4f/0xc0
>> >> [   24.705784]  [<ffffffff810ae8ff>] start_flush_work+0x2f/0x290
>> >> [   24.705789]  [<ffffffff810ae8ac>] flush_work+0x5c/0x80
>> >> [   24.705792]  [<ffffffff810ae86a>] ? flush_work+0x1a/0x80
>> >> [   24.705799]  [<ffffffff810eddcd>] ? trace_hardirqs_off+0xd/0x10
>> >> [   24.705804]  [<ffffffff810ad938>] ? try_to_grab_pending+0x48/0x360
>> >> [   24.705810]  [<ffffffff81917e13>] ? _raw_spin_lock_irqsave+0x73/0x80
>> >> [   24.705814]  [<ffffffff810aecf9>] __cancel_work_timer+0x179/0x260
>
> This one is even more strange. It says that flush_work() is being called
> from __cancel_work_timer() with IRQs disabled, but flags are explicitly
> restored just one statement before that, and usbhid_close() explicitly
> calls cancel_work_sync() after unconditionally enabling interrupts.
>
> So I am not able to make any sense of either of the traces really.
>
> Are you seeing this with the same .config with GCC-compiled kernel as
> well?
>

No, with GCC v4.9 I am not seeing this issue.
It's helpful to also compile with GCC and debuginfo for comparison reasons?

Thanks for your quick response and 1st analysis.

- Sedat -
--
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/

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web