Bug 10171

Summary:	on ia64, using itrace probes cause a spinlock lockup
Product:	systemtap	Reporter:	David Smith <dsmith>
Component:	runtime	Assignee:	Unassigned <systemtap>
Status:	RESOLVED WONTFIX
Severity:	normal	CC:	fche
Priority:	P2
Version:	unspecified
Target Milestone:	---
Host:	ia64	Target:
Build:		Last reconfirmed:
Attachments:	test script

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