Bug 10171 - on ia64, using itrace probes cause a spinlock lockup
Summary: on ia64, using itrace probes cause a spinlock lockup
Status: RESOLVED WONTFIX
Alias: None
Product: systemtap
Classification: Unclassified
Component: runtime (show other bugs)
Version: unspecified
: P2 normal
Target Milestone: ---
Assignee: Unassigned
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-05-18 19:52 UTC by David Smith
Modified: 2015-01-29 01:36 UTC (History)
1 user (show)

See Also:
Host: ia64
Target:
Build:
Last reconfirmed:

Attachments
test script (216 bytes, text/plain)
2009-05-18 19:53 UTC, David Smith 		Details
View All Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description David Smith 2009-05-18 19:52:18 UTC 
On ia64, kernel 2.6.18-146.el5debug, when using itrace probes, the system will
lockup.  The console reports:

====
BUG: spinlock lockup on CPU#0, ls/2576, e0000040fe1092d8 (Tainted: G)

Call Trace:
 [<a000000100013b40>] show_stack+0x40/0xa0
                                sp=e0000003f640f870 bsp=e0000003f6409440
 [<a000000100013bd0>] dump_stack+0x30/0x60
                                sp=e0000003f640fa40 bsp=e0000003f6409428
 [<a0000001002de200>] _raw_spin_lock+0x200/0x260
                                sp=e0000003f640fa40 bsp=e0000003f64093e8
 [<a00000010065ff50>] _spin_lock_irqsave+0x30/0x60
                                sp=e0000003f640fa40 bsp=e0000003f64093c0
 [<a00000010009c730>] force_sig_info+0x30/0x160
                                sp=e0000003f640fa40 bsp=e0000003f6409380
 [<a000000100661450>] ia64_fault+0xff0/0x1280
                                sp=e0000003f640fa40 bsp=e0000003f6409328
 [<a00000010000bfe0>] __ia64_leave_kernel+0x0/0x280
                                sp=e0000003f640fc60 bsp=e0000003f6409328
 [<a0000001002de0d0>] _raw_spin_lock+0xd0/0x260
                                sp=e0000003f640fe30 bsp=e0000003f64092c0
 [<a00000010065ff50>] _spin_lock_irqsave+0x30/0x60
                                sp=e0000003f640fe30 bsp=e0000003f6409298
 [<a00000010009c730>] force_sig_info+0x30/0x160
                                sp=e0000003f640fe30 bsp=e0000003f6409258
 [<a00000010009c890>] force_sig+0x30/0x60
                                sp=e0000003f640fe30 bsp=e0000003f6409230
 [<a00000010002cfe0>] syscall_trace_leave+0x100/0x140
                                sp=e0000003f640fe30 bsp=e0000003f64091d0
 [<a00000010000bda0>] __ia64_trace_syscall+0x100/0x110
                                sp=e0000003f640fe30 bsp=e0000003f64091d0
 [<a000000000010620>] __start_ivt_text+0xffffffff00010620/0x400
                                sp=e0000003f6410000 bsp=e0000003f64091d0
====

This always happens after a call to set_tid_address(), which is the 79th syscall
that 'ls' runs.  By this point the insn probe has been hit at least
555391 times (the test script prints the number of instructions at every
syscall entry and exit).
Comment 1 David Smith 2009-05-18 19:53:21 UTC 
Created attachment 3944 [details]
test script

Run the test script like this:

# stap -v itrace_test.stp -c ls ls
Comment 2 David Smith 2009-05-18 19:57:17 UTC 
To avoid system lockups, commit 5ec6fd7 disables itrace on ia64.
Comment 3 David Smith 2009-05-18 20:56:55 UTC 
Here's the systemtap output before the system hang:

# stap -v --vp 0001 itrace4.stp -c ls ls
Pass 1: parsed user script and 51 library script(s) in 365usr/8sys/526real ms.
Pass 2: analyzed script: 8 probe(s), 4 function(s), 2 embed(s), 2 global(s) in
7usr/2sys/15real ms.
Pass 3: translated to C into
"/tmp/stapmozR9J/stap_bd7372e527ddf60a23ef57cc59e37943_2592.c" in
3usr/2sys/22real ms.
Running make -C "/lib/modules/2.6.18-146.el5debug/build" M="/tmp/stapmozR9J"
modules >/dev/null
Pass 4: compiled C into "stap_bd7372e527ddf60a23ef57cc59e37943_2592.ko" in
7299usr/881sys/10657real ms.
Pass 5: starting run.
systemtap starting probe
pid 2686 begins
pid 2686 syscall 1060 (8013 instrs)
pid 2686 syscall return 1060 = 6917529027641131008 (8013 instrs)
pid 2686 syscall 1130 (11235 instrs)
pid 2686 syscall return 1130 = 0 (11235 instrs)
pid 2686 syscall 1049 (12318 instrs)
pid 2686 syscall return 1049 = 2 (12318 instrs)
pid 2686 syscall 1028 (13589 instrs)
pid 2686 syscall return 1028 = 3 (13589 instrs)
pid 2686 syscall 1212 (13615 instrs)
pid 2686 syscall return 1212 = 0 (13615 instrs)
pid 2686 syscall 1151 (13646 instrs)
pid 2686 syscall return 1151 = 2305843009213939712 (13646 instrs)
pid 2686 syscall 1029 (13658 instrs)
pid 2686 syscall return 1029 = 0 (13658 instrs)
pid 2686 syscall 1028 (16138 instrs)
pid 2686 syscall return 1028 = 3 (16138 instrs)
pid 2686 syscall 1026 (16156 instrs)
pid 2686 syscall return 1026 = 832 (16156 instrs)
pid 2686 syscall 1212 (17003 instrs)
pid 2686 syscall return 1212 = 0 (17003 instrs)
pid 2686 syscall 1151 (18482 instrs)
pid 2686 syscall return 1151 = 2305843009214021632 (18482 instrs)
pid 2686 syscall 1155 (18517 instrs)
pid 2686 syscall return 1155 = 0 (18517 instrs)
pid 2686 syscall 1151 (18588 instrs)
pid 2686 syscall return 1151 = 2305843009214136320 (18588 instrs)
pid 2686 syscall 1029 (19724 instrs)
pid 2686 syscall return 1029 = 0 (19724 instrs)
pid 2686 syscall 1028 (23584 instrs)
pid 2686 syscall return 1028 = 3 (23584 instrs)
pid 2686 syscall 1026 (23602 instrs)
pid 2686 syscall return 1026 = 832 (23602 instrs)
pid 2686 syscall 1212 (24281 instrs)
pid 2686 syscall return 1212 = 0 (24281 instrs)
pid 2686 syscall 1151 (25724 instrs)
pid 2686 syscall return 1151 = 2305843009214152704 (25724 instrs)
pid 2686 syscall 1155 (25759 instrs)
pid 2686 syscall return 1155 = 0 (25759 instrs)
pid 2686 syscall 1151 (25857 instrs)
pid 2686 syscall return 1151 = 2305843009214267392 (25857 instrs)
pid 2686 syscall 1029 (26662 instrs)
pid 2686 syscall return 1029 = 0 (26662 instrs)
pid 2686 syscall 1028 (31041 instrs)
pid 2686 syscall return 1028 = 3 (31041 instrs)
pid 2686 syscall 1026 (31059 instrs)
pid 2686 syscall return 1026 = 832 (31059 instrs)
pid 2686 syscall 1212 (31807 instrs)
pid 2686 syscall return 1212 = 0 (31807 instrs)
pid 2686 syscall 1151 (33415 instrs)
pid 2686 syscall return 1151 = 2305843009214283776 (33415 instrs)
pid 2686 syscall 1155 (33450 instrs)
pid 2686 syscall return 1155 = 0 (33450 instrs)
pid 2686 syscall 1151 (33548 instrs)
pid 2686 syscall return 1151 = 2305843009214496768 (33548 instrs)
pid 2686 syscall 1151 (33794 instrs)
pid 2686 syscall return 1151 = 2305843009214513152 (33794 instrs)
pid 2686 syscall 1029 (34438 instrs)
pid 2686 syscall return 1029 = 0 (34438 instrs)
pid 2686 syscall 1028 (37917 instrs)
pid 2686 syscall return 1028 = 3 (37917 instrs)
pid 2686 syscall 1026 (37935 instrs)
pid 2686 syscall return 1026 = 832 (37935 instrs)
pid 2686 syscall 1212 (38680 instrs)
pid 2686 syscall return 1212 = 0 (38680 instrs)
pid 2686 syscall 1151 (39083 instrs)
pid 2686 syscall return 1151 = 2305843009214529536 (39083 instrs)
pid 2686 syscall 1151 (40381 instrs)
pid 2686 syscall return 1151 = 2305843009214545920 (40381 instrs)
pid 2686 syscall 1155 (40416 instrs)
pid 2686 syscall return 1155 = 0 (40416 instrs)
pid 2686 syscall 1151 (40487 instrs)
pid 2686 syscall return 1151 = 2305843009217150976 (40487 instrs)
pid 2686 syscall 1151 (41144 instrs)
pid 2686 syscall return 1151 = 2305843009217183744 (41144 instrs)
pid 2686 syscall 1029 (41851 instrs)
pid 2686 syscall return 1029 = 0 (41851 instrs)
pid 2686 syscall 1028 (48373 instrs)
pid 2686 syscall return 1028 = 3 (48373 instrs)
pid 2686 syscall 1026 (48391 instrs)
pid 2686 syscall return 1026 = 832 (48391 instrs)
pid 2686 syscall 1212 (49316 instrs)
pid 2686 syscall return 1212 = 0 (49316 instrs)
pid 2686 syscall 1151 (50993 instrs)
pid 2686 syscall return 1151 = 2305843009217200128 (50993 instrs)
pid 2686 syscall 1155 (51028 instrs)
pid 2686 syscall return 1155 = 0 (51028 instrs)
pid 2686 syscall 1151 (51099 instrs)
pid 2686 syscall return 1151 = 2305843009217413120 (51099 instrs)
pid 2686 syscall 1151 (52728 instrs)
pid 2686 syscall return 1151 = 2305843009217445888 (52728 instrs)
pid 2686 syscall 1029 (53459 instrs)
pid 2686 syscall return 1029 = 0 (53459 instrs)
pid 2686 syscall 1028 (59664 instrs)
pid 2686 syscall return 1028 = 3 (59664 instrs)
pid 2686 syscall 1026 (59682 instrs)
pid 2686 syscall return 1026 = 832 (59682 instrs)
pid 2686 syscall 1212 (60412 instrs)
pid 2686 syscall return 1212 = 0 (60412 instrs)
pid 2686 syscall 1151 (61963 instrs)
pid 2686 syscall return 1151 = 2305843009217462272 (61963 instrs)
pid 2686 syscall 1155 (61998 instrs)
pid 2686 syscall return 1155 = 0 (61998 instrs)
pid 2686 syscall 1151 (62096 instrs)
pid 2686 syscall return 1151 = 2305843009217544192 (62096 instrs)
pid 2686 syscall 1029 (62782 instrs)
pid 2686 syscall return 1029 = 0 (62782 instrs)
pid 2686 syscall 1028 (69397 instrs)
pid 2686 syscall return 1028 = 3 (69397 instrs)
pid 2686 syscall 1026 (69415 instrs)
pid 2686 syscall return 1026 = 832 (69415 instrs)
pid 2686 syscall 1212 (70196 instrs)
pid 2686 syscall return 1212 = 0 (70196 instrs)
pid 2686 syscall 1151 (71792 instrs)
pid 2686 syscall return 1151 = 2305843009217560576 (71792 instrs)
pid 2686 syscall 1155 (71827 instrs)
pid 2686 syscall return 1155 = 0 (71827 instrs)
pid 2686 syscall 1151 (71898 instrs)
pid 2686 syscall return 1151 = 2305843009217642496 (71898 instrs)
pid 2686 syscall 1029 (72721 instrs)
pid 2686 syscall return 1029 = 0 (72721 instrs)
pid 2686 syscall 1028 (78039 instrs)
pid 2686 syscall return 1028 = 3 (78039 instrs)
pid 2686 syscall 1026 (78057 instrs)
pid 2686 syscall return 1026 = 832 (78057 instrs)
pid 2686 syscall 1212 (78784 instrs)
pid 2686 syscall return 1212 = 0 (78784 instrs)
pid 2686 syscall 1151 (80458 instrs)
pid 2686 syscall return 1151 = 2305843009217658880 (80458 instrs)
pid 2686 syscall 1155 (80493 instrs)
pid 2686 syscall return 1155 = 0 (80493 instrs)
pid 2686 syscall 1151 (80591 instrs)
pid 2686 syscall return 1151 = 2305843009218232320 (80591 instrs)
pid 2686 syscall 1151 (81620 instrs)
pid 2686 syscall return 1151 = 2305843009218248704 (81620 instrs)
pid 2686 syscall 1029 (82228 instrs)
pid 2686 syscall return 1029 = 0 (82228 instrs)
pid 2686 syscall 1151 (138668 instrs)
pid 2686 syscall return 1151 = 2305843009218297856 (138668 instrs)
pid 2686 syscall 1151 (155927 instrs)
pid 2686 syscall return 1151 = 2305843009218314240 (155927 instrs)
pid 2686 syscall 1151 (167006 instrs)
pid 2686 syscall return 1151 = 2305843009218347008 (167006 instrs)
pid 2686 syscall 1151 (175003 instrs)
pid 2686 syscall return 1151 = 2305843009218363392 (175003 instrs)
pid 2686 syscall 1151 (192265 instrs)
pid 2686 syscall return 1151 = 2305843009218379776 (192265 instrs)
pid 2686 syscall 1151 (475867 instrs)
pid 2686 syscall return 1151 = 2305843009218396160 (475867 instrs)
pid 2686 syscall 1151 (493422 instrs)
pid 2686 syscall return 1151 = 2305843009218412544 (493422 instrs)
pid 2686 syscall 1151 (501256 instrs)
pid 2686 syscall return 1151 = 2305843009218428928 (501256 instrs)
Comment 4 Frank Ch. Eigler 2009-11-21 19:29:08 UTC 
incomplete work snapshotted in pr10653-itrace-crashes branch
Comment 5 Frank Ch. Eigler 2015-01-29 01:36:48 UTC 
old rhel5 utrace/uprobes is unlikely to be perfected, especially ia64