[Bug runtime/6487] New: kernel.function("internal_add_timer") freezes system.

[Bug runtime/6487] New: kernel.function("internal_add_timer") freezes system.

[mhiramat at redhat dot com]

I ran the below command:

$ stap -e 'probe kernel.function("internal_add_timer") {printf("%s\n",pp())}'

It worked few seconds. However, after a while, the system was frozen.

-- 
           Summary: kernel.function("internal_add_timer") freezes system.
           Product: systemtap
           Version: unspecified
            Status: NEW
          Severity: normal
          Priority: P2
         Component: runtime
        AssignedTo: systemtap at sources dot redhat dot com
        ReportedBy: mhiramat at redhat dot com


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[mhiramat at redhat dot com]

------- Additional Comments From mhiramat at redhat dot com  2008-05-07 15:39 -------
(In reply to comment #0)
> I ran the below command:
> 
> $ stap -e 'probe kernel.function("internal_add_timer") {printf("%s\n",pp())}'
> 
> It worked few seconds. However, after a while, the system was frozen.

I tested it with 2.6.25 on x86. And the kernel did not show any error messages.


By the way, curiously, below command did not freeze system.

$ stap -e 'probe kernel.function("internal_add_timer") {}'


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[mhiramat at redhat dot com]

------- Additional Comments From mhiramat at redhat dot com  2008-05-07 15:45 -------
(In reply to comment #1)
> By the way, curiously, below command did not freeze system.
> 
> $ stap -e 'probe kernel.function("internal_add_timer") {}'
> 

Oops, when I tried to stop it, it caused a soft lockup.
---
stap_9017fb37783d59da64aa2cc1999ac78d_247: systemtap: 0.7/0.131, base: f8b03000,
memory: 496426+25746+376+13600 data+text+ctx+net, probes: 1
BUG: soft lockup - CPU#1 stuck for 61s! [staprun:7749]

Pid: 7749, comm: staprun Not tainted (2.6.25 #4)
EIP: 0060:[<c0127259>] EFLAGS: 00000246 CPU: 1
EIP is at lock_timer_base+0x34/0x3e
EAX: f72b1634 EBX: 00000000 ECX: f5e4f600 EDX: f469bf1c
ESI: 00000000 EDI: f72b1634 EBP: f469bf14 ESP: f469bf04
 DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
CR0: 8005003b CR2: bfd26e38 CR3: 338e4000 CR4: 000006d0
DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
DR6: ffff4ff0 DR7: 00000400
 [<c0127278>] try_to_del_timer_sync+0x15/0x4f
 [<f8b066eb>] ? _stp_kfree+0x8/0xa [stap_9017fb37783d59da64aa2cc1999ac78d_247]
 [<c01272bf>] del_timer_sync+0xd/0x18
 [<f8b05017>] _stp_kill_time+0x35/0x6c [stap_9017fb37783d59da64aa2cc1999ac78d_247]
 [<f8b07277>] _stp_transport_close+0x31/0x38
[stap_9017fb37783d59da64aa2cc1999ac78d_247]
 [<f8b07286>] cleanup_module+0x8/0xa [stap_9017fb37783d59da64aa2cc1999ac78d_247]
 [<c0141f35>] sys_delete_module+0x195/0x1d0
 [<c010487e>] sysenter_past_esp+0x5f/0xa5
 =======================
---

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[mhiramat at redhat dot com]

------- Additional Comments From mhiramat at redhat dot com  2008-05-07 18:15 -------
(In reply to comment #0)
> I ran the below command:
> 
> $ stap -e 'probe kernel.function("internal_add_timer") {printf("%s\n",pp())}'
> 
> It worked few seconds. However, after a while, the system was frozen.

I tested it on x86-64.
Fortunately, this time, I found a deadlock on mod_timer.

---
BUG: spinlock lockup on CPU#0, swapper/0, ffffffff809bba80
Pid: 0, comm: swapper Not tainted 2.6.25 #10

Call Trace:
 <#DB>  [<ffffffff8033317c>] ? __delay+0x18/0x24
 [<ffffffff803365fa>] _raw_spin_lock+0xfb/0x123
 [<ffffffff804a2945>] _spin_lock+0x2d/0x31
 [<ffffffff8023e22c>] __mod_timer+0x8e/0xca
 [<ffffffff8026d266>] relay_switch_subbuf+0xa2/0x130
 [<ffffffff8852a306>]
:stap_2a9a9c2834db4b34b8386b192ef333bb_390:stp_print_flush+0xb8/0xc9
 [<ffffffff8852bc10>]
:stap_2a9a9c2834db4b34b8386b192ef333bb_390:probe_1062+0xd8/0x107
 [<ffffffff8852f08e>]
:stap_2a9a9c2834db4b34b8386b192ef333bb_390:enter_kprobe_probe+0x14a/0x2d4
 [<ffffffff804a4381>] kprobe_exceptions_notify+0x1ad/0x402
 [<ffffffff804a52e9>] notifier_call_chain+0x33/0x5b
 [<ffffffff804a536b>] __atomic_notifier_call_chain+0x5a/0x83
 [<ffffffff804a53a3>] atomic_notifier_call_chain+0xf/0x11
 [<ffffffff8024bd30>] notify_die+0x2e/0x30
 [<ffffffff804a3c3c>] do_int3+0x43/0xaa
 [<ffffffff804a3333>] int3+0x93/0xb0
 [<ffffffff8023dac4>] ? internal_add_timer+0x1/0xbd
 <<EOE>>  <IRQ>  [<ffffffff8023e24a>] ? __mod_timer+0xac/0xca
 [<ffffffff8023e420>] ? mod_timer+0x25/0x27
 [<ffffffff8852e082>] ?
:stap_2a9a9c2834db4b34b8386b192ef333bb_390:__stp_time_timer_callback+0x8d/0xb7
 [<ffffffff8852dff5>] ?
:stap_2a9a9c2834db4b34b8386b192ef333bb_390:__stp_time_timer_callback+0x0/0xb7
 [<ffffffff8023dd92>] ? run_timer_softirq+0x14c/0x1c6
 [<ffffffff8023a5d9>] ? __do_softirq+0x5f/0xe3
 [<ffffffff8020d12c>] ? call_softirq+0x1c/0x28
 [<ffffffff8020ea77>] ? do_softirq+0x39/0x8a
 [<ffffffff8023a578>] ? irq_exit+0x4e/0x50
 [<ffffffff8021df7c>] ? smp_apic_timer_interrupt+0x8b/0xa7
 [<ffffffff8020cbdb>] ? apic_timer_interrupt+0x6b/0x70
 <EOI>  [<ffffffff8020ae9d>] ? default_idle+0x43/0x73
 [<ffffffff8020ae9b>] ? default_idle+0x41/0x73
 [<ffffffff8020ae5a>] ? default_idle+0x0/0x73
 [<ffffffff8020af4c>] ? cpu_idle+0x7f/0x9d
 [<ffffffff8048ca36>] ? rest_init+0x5a/0x5c
--- 

Hmm, relay_switch_subbuf() calls __mod_timer() for waking a reader process up.
And, the __mod_timer() acquires a spin lock of timer->base->lock which has been
acquired in the previous __mod_timer(). So it causes a deadlock.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[joshua dot i dot stone at intel dot com]

------- Additional Comments From joshua dot i dot stone at intel dot com  2008-05-07 18:48 -------
It's just a coincidence that the first mod_timer was also from stap.  There's a
real bug here: a probe on the internals of __mod_timer will call
stp_print_flush, and if the buffer is full it will end up calling __mod_timer
again and cause a deadlock.

relay_switch_subbuf has this note:
> /*
>  * Calling wake_up_interruptible() from here
>  * will deadlock if we happen to be logging
>  * from the scheduler (trying to re-grab
>  * rq->lock), so defer it.
>  */
> __mod_timer(&buf->timer, jiffies + 1);

... but in this case we happen to be logging from within __mod_timer, so it's a
new deadlock.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-05-07 18:54 -------
The whole relay and timer subsystem may need to be put into the probing
blacklist.  Argh.

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-05-07 19:24 -------
(In reply to comment #5)
> The whole relay and timer subsystem may need to be put into the probing
> blacklist.  Argh.

And indeed this reminds me of another reason for my reticence to push more
parts of the systemtap runtime into the kernel proper.  By keeping the code
"inlined" in our module instead of the kernel, it is not subject to probing
and thus reentrance/deadlock.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[mhiramat at redhat dot com]

------- Additional Comments From mhiramat at redhat dot com  2008-05-07 19:34 -------
(In reply to comment #5)
> The whole relay and timer subsystem may need to be put into the probing
> blacklist.  Argh.

Hmm, I think tracing timer subsystem(especially, tracing when the handler is
executed) is still important for us.
So, we'd better improve relayfs not to use __mod_timer().

-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[mhiramat at redhat dot com]

------- Additional Comments From mhiramat at redhat dot com  2008-05-07 20:21 -------
(In reply to comment #7)
> So, we'd better improve relayfs not to use __mod_timer().

LTTng does not use relay_switch_subbuf(), it has another version of switching
function which does not wake readers up, but just sets a flag. An interval timer
checks the flag and wakes the readers up.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-05-09 19:53 -------
Commit e0d0dcf fixes this particular issue, but not in an entirely
satisfying way.  The runtime should depend less on such relatively
kernel-intensive operations in probe context.

A brief gaze over other parts of the runtime suggest that
kernel/workqueue.c may need similar treatment.


-- 


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-05-09 19:54 -------
pushed

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |FIXED


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-05-12 23:26 -------
jkenisto reports blacklisting kernel/timer.c is too broad and kills
elementary tapset functions like getgid() etc.

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|RESOLVED                    |REOPENED
         Resolution|FIXED                       |


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[mhiramat at redhat dot com]

------- Additional Comments From mhiramat at redhat dot com  2008-05-16 17:10 -------
PR6504 will solve this issue.

-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
  BugsThisDependsOn|                            |6504


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[fche at redhat dot com]

------- Additional Comments From fche at redhat dot com  2008-09-17 19:20 -------
commit 7ef27e8


-- 
           What    |Removed                     |Added
----------------------------------------------------------------------------
             Status|REOPENED                    |RESOLVED
         Resolution|                            |FIXED


http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

[Bug runtime/6487] kernel.function("internal_add_timer") freezes system.

[fche at redhat dot com]

-- 
Bug 6487 depends on bug 6504, which changed state.

Bug 6504 Summary: change _stp_print_flush to avoid calling into kernel/relay.c
http://sourceware.org/bugzilla/show_bug.cgi?id=6504

           What    |Old Value                   |New Value
----------------------------------------------------------------------------
             Status|NEW                         |RESOLVED
         Resolution|                            |FIXED

http://sourceware.org/bugzilla/show_bug.cgi?id=6487

------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.