splat in kretprobe in get_task_mm(current)

splat in kretprobe in get_task_mm(current)

[Peter Moody]

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

Hi folks,

I've managed to trigger the following splat on 3.15.0-rc8 using the attached kretprobe module.

[  339.208634] BUG: spinlock cpu recursion on CPU#4, rm/8733
[  339.208643]  lock: kretprobe_table_locks+0x600/0x2000, .magic: dead4ead, .owner: rm/8734, .owner_cpu: 4
[  339.208647] CPU: 4 PID: 8733 Comm: rm Tainted: G          IOE 3.15.0-rc8-splat+ #14
[  339.208648] Hardware name: Dell Inc. Precision WorkStation T3500  /09KPNV, BIOS A10 01/21/2011
[  339.208650]  ffff88044d3a2570 ffff880454e63d48 ffffffff81773413 0000000000000007
[  339.208654]  ffffffff82842080 ffff880454e63d68 ffffffff8176ec74 ffffffff82842080
[  339.208658]  ffffffff81a8b6a6 ffff880454e63d88 ffffffff8176ec9f ffffffff82842080
[  339.208662] Call Trace:
[  339.208667]  [<ffffffff81773413>] dump_stack+0x46/0x58
[  339.208671]  [<ffffffff8176ec74>] spin_dump+0x8f/0x94
[  339.208674]  [<ffffffff8176ec9f>] spin_bug+0x26/0x2b
[  339.208678]  [<ffffffff810c4195>] do_raw_spin_lock+0x105/0x190
[  339.208683]  [<ffffffff8177c7c0>] _raw_spin_lock_irqsave+0x70/0x90
[  339.208687]  [<ffffffff817839dc>] ? kretprobe_hash_lock+0x6c/0x80
[  339.208690]  [<ffffffff8177a86e>] ? mutex_unlock+0xe/0x10
[  339.208693]  [<ffffffff817839dc>] kretprobe_hash_lock+0x6c/0x80
[  339.208697]  [<ffffffff8177f16d>] trampoline_handler+0x3d/0x220
[  339.208700]  [<ffffffff811bc537>] ? kfree+0x147/0x190
[  339.208703]  [<ffffffff8177f0fe>] kretprobe_trampoline+0x25/0x57
[  339.208707]  [<ffffffff811e28e8>] ? do_execve+0x18/0x20
[  339.208710]  [<ffffffff817862a9>] stub_execve+0x69/0xa0

Unfortunately triggering the splat is kind of a pain. I've only been able to it by building chromeos. The cros build process kicks off dozens of processes (in this case, it was 32) to fetch/build the various packages for the system image. I can try to come up with a better reproducer if this splat and module aren't enough.

If I remove getting the reference to mm, I avoid the splat.

Cheers,
peter


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: exec_mm_probe.c --]
[-- Type: text/x-csrc, Size: 951 bytes --]

#include <linux/version.h>
#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/mm.h>
#include <linux/kprobes.h>

static int cntr;

static int exec_handler(struct kretprobe_instance *ri, struct pt_regs *regs)
{
  int ret = (int)regs_return_value(regs);
  if (!(unlikely(IS_ERR_VALUE(ret)))) {
     struct mm_struct *mm = NULL;
     mm = get_task_mm(current);
     if (mm)
       mmput(mm);
  }
  return 0;
}

static struct kretprobe exec_kretprobe = {
  .kp.symbol_name = "do_execve",
  .handler = exec_handler,
};

static int __init probe_init(void)
{
  int err;
  if ((err = register_kretprobe(&exec_kretprobe))) {
    pr_err("register failed: %d\n", err);
    return err;
  }
  pr_info("exec_mm_probe loaded.\n");
  cntr = 0;
  return 0;
}

static void probe_exit(void)
{
  unregister_kretprobe(&exec_kretprobe);
  pr_info("exec_mm_probe unloaded.\n");
}

MODULE_LICENSE("GPL v2");

module_init(probe_init);
module_exit(probe_exit);

Re: splat in kretprobe in get_task_mm(current)

[Peter Moody]

As a follow up, I can reliably reproduce this bug with the following code

#include <unistd.h>
#include <sys/types.h>

int main(int argc, char *argv[]) {
  char *envp_[] = {NULL};
  char *argv_[] = {argv[0]};
  execve(argv[0], argv_, envp_);
  return 0;
}

run in parallel like so:

$ for x in $(seq 0 32) ; do ./a.out & done

giving me the following splat:.

[ 133.627336] BUG: spinlock cpu recursion on CPU#4, a.out/4643
[ 133.627346]  lock: kretprobe_table_locks+0x1b80/0x2000, .magic: dead4ead, .owner: a.out/4630, .owner_cpu: 4
[ 133.627350] CPU: 4 PID: 4643 Comm: a.out Tainted: G          IOE 3.15.0-rc8-splat+ #14
[ 133.627351] Hardware name: Dell Inc. Precision WorkStation T3500  /09KPNV, BIOS A10 01/21/2011
[ 133.627353]  ffff8804d5ae0000 ffff8804a7b4fd48 ffffffff81773413 0000000000000007
[ 133.627358]  ffffffff82843600 ffff8804a7b4fd68 ffffffff8176ec74 ffffffff82843600
[ 133.627362]  ffffffff81a8b6a6 ffff8804a7b4fd88 ffffffff8176ec9f ffffffff82843600
[ 133.627366] Call Trace:
[ 133.627372]  [<ffffffff81773413>] dump_stack+0x46/0x58
[ 133.627376]  [<ffffffff8176ec74>] spin_dump+0x8f/0x94
[ 133.627379]  [<ffffffff8176ec9f>] spin_bug+0x26/0x2b
[ 133.627384]  [<ffffffff810c4195>] do_raw_spin_lock+0x105/0x190
[ 133.627389]  [<ffffffff8177c7c0>] _raw_spin_lock_irqsave+0x70/0x90
[ 133.627394]  [<ffffffff817839dc>] ? kretprobe_hash_lock+0x6c/0x80
[ 133.627398]  [<ffffffff8177a86e>] ? mutex_unlock+0xe/0x10
[ 133.627401]  [<ffffffff817839dc>] kretprobe_hash_lock+0x6c/0x80
[ 133.627404]  [<ffffffff8177f16d>] trampoline_handler+0x3d/0x220
[ 133.627407]  [<ffffffff8177f0fe>] kretprobe_trampoline+0x25/0x57
[ 133.627412]  [<ffffffff811e28e8>] ? do_execve+0x18/0x20
[ 133.627415]  [<ffffffff817862a9>] stub_execve+0x69/0xa0

On Tue, Jun 03 2014 at 10:39, Peter Moody wrote:
> Hi folks,
>
> I've managed to trigger the following splat on 3.15.0-rc8 using the attached kretprobe module.
>
> [  339.208634] BUG: spinlock cpu recursion on CPU#4, rm/8733
> [  339.208643]  lock: kretprobe_table_locks+0x600/0x2000, .magic: dead4ead, .owner: rm/8734, .owner_cpu: 4
> [  339.208647] CPU: 4 PID: 8733 Comm: rm Tainted: G          IOE 3.15.0-rc8-splat+ #14
> [  339.208648] Hardware name: Dell Inc. Precision WorkStation T3500  /09KPNV, BIOS A10 01/21/2011
> [  339.208650]  ffff88044d3a2570 ffff880454e63d48 ffffffff81773413 0000000000000007
> [  339.208654]  ffffffff82842080 ffff880454e63d68 ffffffff8176ec74 ffffffff82842080
> [  339.208658]  ffffffff81a8b6a6 ffff880454e63d88 ffffffff8176ec9f ffffffff82842080
> [  339.208662] Call Trace:
> [  339.208667]  [<ffffffff81773413>] dump_stack+0x46/0x58
> [  339.208671]  [<ffffffff8176ec74>] spin_dump+0x8f/0x94
> [  339.208674]  [<ffffffff8176ec9f>] spin_bug+0x26/0x2b
> [  339.208678]  [<ffffffff810c4195>] do_raw_spin_lock+0x105/0x190
> [  339.208683]  [<ffffffff8177c7c0>] _raw_spin_lock_irqsave+0x70/0x90
> [  339.208687]  [<ffffffff817839dc>] ? kretprobe_hash_lock+0x6c/0x80
> [  339.208690]  [<ffffffff8177a86e>] ? mutex_unlock+0xe/0x10
> [  339.208693]  [<ffffffff817839dc>] kretprobe_hash_lock+0x6c/0x80
> [  339.208697]  [<ffffffff8177f16d>] trampoline_handler+0x3d/0x220
> [  339.208700]  [<ffffffff811bc537>] ? kfree+0x147/0x190
> [  339.208703]  [<ffffffff8177f0fe>] kretprobe_trampoline+0x25/0x57
> [  339.208707]  [<ffffffff811e28e8>] ? do_execve+0x18/0x20
> [  339.208710]  [<ffffffff817862a9>] stub_execve+0x69/0xa0
>
> Unfortunately triggering the splat is kind of a pain. I've only been able to it by building chromeos. The cros build
> process kicks off dozens of processes (in this case, it was 32) to fetch/build the various packages for the system
> image. I can try to come up with a better reproducer if this splat and module aren't enough.
>
> If I remove getting the reference to mm, I avoid the splat.
>
> Cheers,
> peter
>
>
> #include <linux/version.h>
> #include <linux/kernel.h>
> #include <linux/module.h>
> #include <linux/mm.h>
> #include <linux/kprobes.h>
>
> static int cntr;
>
> static int exec_handler(struct kretprobe_instance *ri, struct pt_regs *regs)
> {
>   int ret = (int)regs_return_value(regs);
>   if (!(unlikely(IS_ERR_VALUE(ret)))) {
>      struct mm_struct *mm = NULL;
>      mm = get_task_mm(current);
>      if (mm)
>        mmput(mm);
>   }
>   return 0;
> }
>
> static struct kretprobe exec_kretprobe = {
>   .kp.symbol_name = "do_execve",
>   .handler = exec_handler,
> };
>
> static int __init probe_init(void)
> {
>   int err;
>   if ((err = register_kretprobe(&exec_kretprobe))) {
>     pr_err("register failed: %d\n", err);
>     return err;
>   }
>   pr_info("exec_mm_probe loaded.\n");
>   cntr = 0;
>   return 0;
> }
>
> static void probe_exit(void)
> {
>   unregister_kretprobe(&exec_kretprobe);
>   pr_info("exec_mm_probe unloaded.\n");
> }
>
> MODULE_LICENSE("GPL v2");
>
> module_init(probe_init);
> module_exit(probe_exit);

Re: splat in kretprobe in get_task_mm(current)

[Masami Hiramatsu]

Hi Peter,

(2014/06/04 6:53), Peter Moody wrote:
> 
> As a follow up, I can reliably reproduce this bug with the following code
> 
> #include <unistd.h>
> #include <sys/types.h>
> 
> int main(int argc, char *argv[]) {
>   char *envp_[] = {NULL};
>   char *argv_[] = {argv[0]};
>   execve(argv[0], argv_, envp_);
>   return 0;
> }
> 
> run in parallel like so:
> 
> $ for x in $(seq 0 32) ; do ./a.out & done
> 
> giving me the following splat:.

Thank you for reporting that. I've tried to reproduce it with your code, but
not succeeded yet. Could you share us your kernel config too?

Thank you again,

> 
> [ 133.627336] BUG: spinlock cpu recursion on CPU#4, a.out/4643
> [ 133.627346]  lock: kretprobe_table_locks+0x1b80/0x2000, .magic: dead4ead, .owner: a.out/4630, .owner_cpu: 4
> [ 133.627350] CPU: 4 PID: 4643 Comm: a.out Tainted: G          IOE 3.15.0-rc8-splat+ #14
> [ 133.627351] Hardware name: Dell Inc. Precision WorkStation T3500  /09KPNV, BIOS A10 01/21/2011
> [ 133.627353]  ffff8804d5ae0000 ffff8804a7b4fd48 ffffffff81773413 0000000000000007
> [ 133.627358]  ffffffff82843600 ffff8804a7b4fd68 ffffffff8176ec74 ffffffff82843600
> [ 133.627362]  ffffffff81a8b6a6 ffff8804a7b4fd88 ffffffff8176ec9f ffffffff82843600
> [ 133.627366] Call Trace:
> [ 133.627372]  [<ffffffff81773413>] dump_stack+0x46/0x58
> [ 133.627376]  [<ffffffff8176ec74>] spin_dump+0x8f/0x94
> [ 133.627379]  [<ffffffff8176ec9f>] spin_bug+0x26/0x2b
> [ 133.627384]  [<ffffffff810c4195>] do_raw_spin_lock+0x105/0x190
> [ 133.627389]  [<ffffffff8177c7c0>] _raw_spin_lock_irqsave+0x70/0x90
> [ 133.627394]  [<ffffffff817839dc>] ? kretprobe_hash_lock+0x6c/0x80
> [ 133.627398]  [<ffffffff8177a86e>] ? mutex_unlock+0xe/0x10
> [ 133.627401]  [<ffffffff817839dc>] kretprobe_hash_lock+0x6c/0x80
> [ 133.627404]  [<ffffffff8177f16d>] trampoline_handler+0x3d/0x220
> [ 133.627407]  [<ffffffff8177f0fe>] kretprobe_trampoline+0x25/0x57
> [ 133.627412]  [<ffffffff811e28e8>] ? do_execve+0x18/0x20
> [ 133.627415]  [<ffffffff817862a9>] stub_execve+0x69/0xa0
> 


-- 
Masami HIRAMATSU
Software Platform Research Dept. Linux Technology Research Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: masami.hiramatsu.pt@hitachi.com

Re: splat in kretprobe in get_task_mm(current)

[Masami Hiramatsu]

(2014/06/04 17:03), Masami Hiramatsu wrote:
> Hi Peter,
> 
> (2014/06/04 6:53), Peter Moody wrote:
>>
>> As a follow up, I can reliably reproduce this bug with the following code
>>
>> #include <unistd.h>
>> #include <sys/types.h>
>>
>> int main(int argc, char *argv[]) {
>>   char *envp_[] = {NULL};
>>   char *argv_[] = {argv[0]};
>>   execve(argv[0], argv_, envp_);
>>   return 0;
>> }
>>
>> run in parallel like so:
>>
>> $ for x in $(seq 0 32) ; do ./a.out & done
>>
>> giving me the following splat:.
> 
> Thank you for reporting that. I've tried to reproduce it with your code, but
> not succeeded yet. Could you share us your kernel config too?

Hmm, it seems that on my environment (Fedora20, gcc version 4.8.2 20131212),
do_execve() in sys_execve has been optimized out (and do_execve_common() is
also renamed). I'll try to rebuild it. However, since such optimization sometimes
depends on kernel config, I'd like to do it with your config.

Thank you,

> 
> Thank you again,
> 
>>
>> [ 133.627336] BUG: spinlock cpu recursion on CPU#4, a.out/4643
>> [ 133.627346]  lock: kretprobe_table_locks+0x1b80/0x2000, .magic: dead4ead, .owner: a.out/4630, .owner_cpu: 4
>> [ 133.627350] CPU: 4 PID: 4643 Comm: a.out Tainted: G          IOE 3.15.0-rc8-splat+ #14
>> [ 133.627351] Hardware name: Dell Inc. Precision WorkStation T3500  /09KPNV, BIOS A10 01/21/2011
>> [ 133.627353]  ffff8804d5ae0000 ffff8804a7b4fd48 ffffffff81773413 0000000000000007
>> [ 133.627358]  ffffffff82843600 ffff8804a7b4fd68 ffffffff8176ec74 ffffffff82843600
>> [ 133.627362]  ffffffff81a8b6a6 ffff8804a7b4fd88 ffffffff8176ec9f ffffffff82843600
>> [ 133.627366] Call Trace:
>> [ 133.627372]  [<ffffffff81773413>] dump_stack+0x46/0x58
>> [ 133.627376]  [<ffffffff8176ec74>] spin_dump+0x8f/0x94
>> [ 133.627379]  [<ffffffff8176ec9f>] spin_bug+0x26/0x2b
>> [ 133.627384]  [<ffffffff810c4195>] do_raw_spin_lock+0x105/0x190
>> [ 133.627389]  [<ffffffff8177c7c0>] _raw_spin_lock_irqsave+0x70/0x90
>> [ 133.627394]  [<ffffffff817839dc>] ? kretprobe_hash_lock+0x6c/0x80
>> [ 133.627398]  [<ffffffff8177a86e>] ? mutex_unlock+0xe/0x10
>> [ 133.627401]  [<ffffffff817839dc>] kretprobe_hash_lock+0x6c/0x80
>> [ 133.627404]  [<ffffffff8177f16d>] trampoline_handler+0x3d/0x220
>> [ 133.627407]  [<ffffffff8177f0fe>] kretprobe_trampoline+0x25/0x57
>> [ 133.627412]  [<ffffffff811e28e8>] ? do_execve+0x18/0x20
>> [ 133.627415]  [<ffffffff817862a9>] stub_execve+0x69/0xa0
>>
> 
> 


-- 
Masami HIRAMATSU
Software Platform Research Dept. Linux Technology Research Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: masami.hiramatsu.pt@hitachi.com

Re: splat in kretprobe in get_task_mm(current)

[Peter Moody]

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


On Wed, Jun 04 2014 at 07:07, Masami Hiramatsu wrote:

>> Thank you for reporting that. I've tried to reproduce it with your code, but
>> not succeeded yet. Could you share us your kernel config too?
>
> Hmm, it seems that on my environment (Fedora20, gcc version 4.8.2 20131212),
> do_execve() in sys_execve has been optimized out (and do_execve_common() is
> also renamed). I'll try to rebuild it. However, since such optimization sometimes
> depends on kernel config, I'd like to do it with your config.
>
> Thank you,

Sure thing, sorry for not attaching it to begin with.

One other thing is that, at least on the systems I've been able to repro on, the more processes, the more likely I was to not emit a splat before just deadlocking the machine. eg. on a 12 core machine, I got the splat with 32 processes and a deadlock with 50. On a 2 core qemu virtual machine I got a deadlock with 32 and a splat with something like 12 or 16.

And FWIW, I'm running ubuntu precise, with gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5)

Cheers,
peter


[-- Attachment #2: config-3.15.0-rc8-splat+.gz --]
[-- Type: application/octet-stream, Size: 42474 bytes --]

Re: Re: splat in kretprobe in get_task_mm(current)

[Masami Hiramatsu]

(2014/06/05 0:23), Peter Moody wrote:
> 
> On Wed, Jun 04 2014 at 07:07, Masami Hiramatsu wrote:
> 
>>> Thank you for reporting that. I've tried to reproduce it with your code, but
>>> not succeeded yet. Could you share us your kernel config too?
>>
>> Hmm, it seems that on my environment (Fedora20, gcc version 4.8.2 20131212),
>> do_execve() in sys_execve has been optimized out (and do_execve_common() is
>> also renamed). I'll try to rebuild it. However, since such optimization sometimes
>> depends on kernel config, I'd like to do it with your config.
>>
>> Thank you,
> 
> Sure thing, sorry for not attaching it to begin with.
> 
> One other thing is that, at least on the systems I've been able to repro on, the more processes,
> the more likely I was to not emit a splat before just deadlocking the machine. eg. on a 12 core
> machine, I got the splat with 32 processes and a deadlock with 50. On a 2 core qemu virtual
> machine I got a deadlock with 32 and a splat with something like 12 or 16.
> 
> And FWIW, I'm running ubuntu precise, with gcc version 4.6.3 (Ubuntu/Linaro 4.6.3-1ubuntu5)


Thank you for sharing the kconfig. I saw the CONFIG_DEBUG_ATOMIC_SLEEP was not set
in your kconfig. When I set that and run your test, I had (a lot of) below warnings
instead of deadlock.

[  342.072132] BUG: sleeping function called from invalid context at /home/fedora/ksrc/linux-3/kernel/fork.c:615
[  342.080684] in_atomic(): 1, irqs_disabled(): 1, pid: 5017, name: execve
[  342.080684] INFO: lockdep is turned off.
[  342.080684] irq event stamp: 0
[  342.080684] hardirqs last  enabled at (0): [<          (null)>]           (null)
[  342.080684] hardirqs last disabled at (0): [<ffffffff81045468>] copy_process.part.31+0x5ba/0x183d
[  342.080684] softirqs last  enabled at (0): [<ffffffff81045468>] copy_process.part.31+0x5ba/0x183d
[  342.080684] softirqs last disabled at (0): [<          (null)>]           (null)
[  342.080684] CPU: 5 PID: 5017 Comm: execve Not tainted 3.15.0-rc8+ #7
[  342.080684] Hardware name: Red Hat Inc. OpenStack Nova, BIOS 0.5.1 01/01/2007
[  342.080684]  0000000000000000 ffff8803ff81bdf8 ffffffff81554140 ffff88040a9df500
[  342.080684]  ffff8803ff81be08 ffffffff8106d17c ffff8803ff81be20 ffffffff81044bd8
[  342.080684]  ffffffff8114ad8f ffff8803ff81be30 ffffffffa015802d ffff8803ff81be88
[  342.080684] Call Trace:
[  342.080684]  [<ffffffff81554140>] dump_stack+0x4d/0x66
[  342.080684]  [<ffffffff8106d17c>] __might_sleep+0x118/0x11a
[  342.080684]  [<ffffffff81044bd8>] mmput+0x20/0xd9
[  342.080684]  [<ffffffff8114ad8f>] ? SyS_execve+0x2a/0x2e
[  342.080684]  [<ffffffffa015802d>] exec_handler+0x2d/0x34 [exec_mm_probe]
[  342.080684]  [<ffffffff81032a2c>] trampoline_handler+0x11b/0x1ac
[  342.080684]  [<ffffffff8103265a>] kretprobe_trampoline+0x25/0x4c
[  342.080684]  [<ffffffff81032635>] ? kretprobe_trampoline_holder+0x9/0x9
[  342.080684]  [<ffffffff8155ca99>] stub_execve+0x69/0xa0

Here, as you can see, calling mmput() in kretprobe handler is actually the root cause
of this problem.

Thank you,

-- 
Masami HIRAMATSU
Software Platform Research Dept. Linux Technology Research Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: masami.hiramatsu.pt@hitachi.com

Re: splat in kretprobe in get_task_mm(current)

[Peter Moody]

On Wed, Jun 04 2014 at 15:49, Masami Hiramatsu wrote:

> Here, as you can see, calling mmput() in kretprobe handler is actually the root cause
> of this problem.

Indeed, deferring the mmput to a workqueue solved my issue.

Thanks for your quick reply today!

Cheers,
peter

Re: (ltc-kernel 9473) Re: splat in kretprobe in get_task_mm(current)

[Masami Hiramatsu]

(2014/06/04 23:07), Masami Hiramatsu wrote:
> (2014/06/04 17:03), Masami Hiramatsu wrote:
>> Hi Peter,
>>
>> (2014/06/04 6:53), Peter Moody wrote:
>>>
>>> As a follow up, I can reliably reproduce this bug with the following code
>>>
>>> #include <unistd.h>
>>> #include <sys/types.h>
>>>
>>> int main(int argc, char *argv[]) {
>>>   char *envp_[] = {NULL};
>>>   char *argv_[] = {argv[0]};
>>>   execve(argv[0], argv_, envp_);
>>>   return 0;
>>> }
>>>
>>> run in parallel like so:
>>>
>>> $ for x in $(seq 0 32) ; do ./a.out & done
>>>
>>> giving me the following splat:.
>>
>> Thank you for reporting that. I've tried to reproduce it with your code, but
>> not succeeded yet. Could you share us your kernel config too?
> 
> Hmm, it seems that on my environment (Fedora20, gcc version 4.8.2 20131212),
> do_execve() in sys_execve has been optimized out (and do_execve_common() is
> also renamed). I'll try to rebuild it. However, since such optimization sometimes
> depends on kernel config, I'd like to do it with your config.

OK, I think at least I could find a clue.
Actually I forgot enabling spinlock debug, but a deadlock catched by rcu_sched.

[ 1155.568010] INFO: rcu_sched detected stalls on CPUs/tasks: { 4 6 7} (detected by 3, t=5252 jiffies, g=20035, c=20034, q=1965612)
[ 1155.572339] sending NMI to all CPUs:
...
[ 1134.596992] NMI backtrace for cpu 4
[ 1134.596992] CPU: 4 PID: 5614 Comm: execve Not tainted 3.15.0-rc8+ #6
[ 1134.596992] Hardware name: Red Hat Inc. OpenStack Nova, BIOS 0.5.1 01/01/2007
[ 1134.596992] task: ffff88040c806f00 ti: ffff8800d9130000 task.ti: ffff8800d9130000
[ 1134.596992] RIP: 0010:[<ffffffff81526d7d>]  [<ffffffff81526d7d>] _raw_spin_lock_irqsave+0x4d/0x61
[ 1134.596992] RSP: 0018:ffff8800d9133c68  EFLAGS: 00000083
[ 1134.596992] RAX: 000000000009692e RBX: 0000000000000286 RCX: 0000000000000030
[ 1134.596992] RDX: 0000000000005944 RSI: 0000000000000030 RDI: ffffffff81cb2800
[ 1134.596992] RBP: ffff8800d9133c78 R08: 0000000000015fe0 R09: ffffea00036c5200
[ 1134.596992] R10: 0000000000000000 R11: ffffffff810435ed R12: ffff88040ac3ef00
[ 1134.596992] R13: ffff8800db14e4c0 R14: 0000000000000040 R15: ffff88040ac3ef00
[ 1134.596992] FS:  0000000000000000(0000) GS:ffff88041fd00000(0000) knlGS:0000000000000000
[ 1134.596992] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1134.596992] CR2: 0000000000601034 CR3: 0000000401da1000 CR4: 00000000000406e0
[ 1134.596992] Stack:
[ 1134.596992]  ffffffff81cb2800 ffff8800d9133ca8 ffff8800d9133c90 ffffffff810b2923
[ 1134.596992]  0000000000000009 ffff8800d9133cc8 ffffffff810b34ac 0000000000000000
[ 1134.596992]  0000000000000000 ffff88041fd12b00 ffff88040ac3ef00 ffff8800db14e4c0
[ 1134.596992] Call Trace:
[ 1134.596992]  [<ffffffff810b2923>] kretprobe_table_lock+0x1d/0x23
[ 1134.596992]  [<ffffffff810b34ac>] kprobe_flush_task+0x50/0xca
[ 1134.596992]  [<ffffffff8106a889>] finish_task_switch+0x94/0x107
[ 1134.596992]  [<ffffffff81523ba0>] __schedule+0x497/0x743
[ 1134.596992]  [<ffffffff810c3eeb>] ? __buffer_unlock_commit+0x12/0x14
[ 1134.596992]  [<ffffffff810c4a30>] ? trace_buffer_unlock_commit_regs+0x3e/0x46
[ 1134.596992]  [<ffffffff810d85ca>] ? kretprobe_trace_func+0x2a2/0x2b6
[ 1134.596992]  [<ffffffff8113b6ec>] ? SyS_execve+0x2a/0x2e
[ 1134.596992]  [<ffffffff8152420a>] _cond_resched+0x44/0x57
[ 1134.596992]  [<ffffffff8104383c>] mmput+0x12/0xc6
[ 1134.596992]  [<ffffffff8113b6ec>] ? SyS_execve+0x2a/0x2e
[ 1134.596992]  [<ffffffffa000a02d>] exec_handler+0x2d/0x34 [exec_mm_probe]
[ 1134.596992]  [<ffffffff8103197c>] trampoline_handler+0x11b/0x1ac
[ 1134.596992]  [<ffffffff810315b2>] kretprobe_trampoline+0x25/0x4c
[ 1134.596992]  [<ffffffff8113e12e>] ? final_putname+0x34/0x37
[ 1134.596992]  [<ffffffff8103158d>] ? kretprobe_trampoline_holder+0x9/0x9
[ 1134.596992]  [<ffffffff81527cb9>] stub_execve+0x69/0xa0

This seems that mmput() invoking __schedule() function which is not allowed in
k*probes handler, since the handler is called from special path. As you can see
in Documentation/kprobes.txt, "5. Kprobes Features and Limitations" says

---
 Probe handlers are run with preemption disabled.  Depending on the
 architecture and optimization state, handlers may also run with
 interrupts disabled (e.g., kretprobe handlers and optimized kprobe
 handlers run without interrupt disabled on x86/x86-64).  In any case,
 your handler should not yield the CPU (e.g., by attempting to acquire
 a semaphore).
---

So the mmput() yielding the CPU (by calling __schedule()) which is not allowed
officially. I think even though this should not happen, but currently, that is
a limitation.

Thank you,


-- 
Masami HIRAMATSU
Software Platform Research Dept. Linux Technology Research Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: masami.hiramatsu.pt@hitachi.com