This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Issue related to stap scripts used for system call tracing
- From: "ramya rao" <ba dot ramya at gmail dot com>
- To: systemtap at sources dot redhat dot com
- Date: Tue, 9 Oct 2007 15:19:35 +0530
- Subject: Issue related to stap scripts used for system call tracing
- Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=beta; h=domainkey-signature:received:received:message-id:date:from:to:subject:mime-version:content-type:content-transfer-encoding:content-disposition; bh=xoKvtTQgN2QbVWUVWsbVZOfzz1K+tRiWf1xuBcyDNqA=; b=EBAh29iAdfFPHqZGYo2ADObC6WjYqQJedovn+l3VQm2z96hvfY27mYJnqqVE6BYrH7EDt49EcYwpAD8wToKr5oGUsvs7wosL70UNwo57bZa0EEhCnsnB7diEYtfvN0RAy7IG/ABEuG/NuK9l6OSY8k9Cp6YG8AQBa036r1nbB4c=
- Domainkey-signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta; h=received:message-id:date:from:to:subject:mime-version:content-type:content-transfer-encoding:content-disposition; b=Nssw2rMgTSLN0AMyPYwvWk94RHEpuzxwb5gj+4HrJMWjyyMEfqo8NRqObpwo/jfpBfF9sqtMGbvUaQJaCZ+/aqgr2YYIz5zqWPjQ4j14Q/iDypZyiehl32SaHaHu+VoEmeoyENPbEuXGlpn4F+woH+2d/krbpQtvn+AutSv91Hc=
Hi all,
We have an issue regarding the usage of systemtap.
When we were trying out the sample scripts given in systemtap tutorial
, we observed that system is crashing when we are executing scripts
related to system calls.
To illustrate:
Given below is a script that traces "sys_open" system call.
#!/usr/bin/stap
# cat strace-open.stp
probe syscall.open
{
printf ("%s(%d) open (%s)\n", execname(), pid(), argstr)
}
probe timer.ms(10000) # after 10 seconds
{
exit ()
}
Also when we tried to trace do_fork system call, we observed that the
system crashed.
When we executed the script with -vvv option, we observed that the
compilation was successful. However the system crashed when the stap
execution started.
Observations:
1. Following message appeared when we executed the script with -vvv option:
Building modules, stage 2.
make -rR -f /usr/src/linux-2.6.16.46-0.12/scripts/Makefile.modpost
scripts/mod/modpost -m -a -i
/usr/src/linux-2.6.16.46-0.12/Module.symvers -I
/tmp/stapoLq77i/Modules.symvers -o /tmp/stapoLq77i/Modules.symvers -s
/dev/null vmlinux
/tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.o
gcc -m32 -Wp,-MD,/tmp/stapoLq77i/.stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.mod.o.d
-nostdinc -isystem /usr/lib/gcc/i586-suse-linux/4.1.2/include
-D__KERNEL__ -Iinclude -include
/usr/src/linux-2.6.16.46-0.12/include/linux/autoconf.h -Wall -Wundef
-Wstrict-prototypes -Wno-trigraphs
-Werror-implicit-function-declaration -fno-strict-aliasing -fno-common
-ffreestanding -Os -pipe -msoft-float -mpreferred-stack-boundary=2
-march=i586 -mtune=generic -mregparm=3
-Iinclude/asm-i386/mach-default -fno-omit-frame-pointer
-fno-optimize-sibling-calls -g -fno-stack-protector
-Wdeclaration-after-statement -Wno-pointer-sign
-D"KBUILD_STR(s)=#s"
-D"KBUILD_BASENAME=KBUILD_STR(stap_95ab067bf1c40efc3500959b85e5a4a0_3372093)"
-D"KBUILD_MODNAME=KBUILD_STR(stap_95ab067bf1c40efc3500959b85e5a4a0_3372093)"
-DMODULE -c -o /tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.mod.o
/tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.mod.c
ld -m elf_i386 -m elf_i386 -r -o
/tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.ko
/tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.o
/tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.mod.o
make: Leaving directory `/usr/src/linux-2.6.16.46-0.12'
Pass 4: compiled C into
"stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.ko" in
6140usr/1640sys/9626real ms.
Copying /tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.ko
to /root/.systemtap/cache/95/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.ko
Copying /tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.c
to /root/.systemtap/cache/95/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.c
Pass 5: starting run.
Running sudo /usr/bin/staprun -v -v -u root -d 5129
/tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.ko
main:141 modpath="/tmp/stapoLq77i/stap_95ab067bf1c40efc3500959b85e5a4a0_3372093.ko",
modname="stap_95ab067bf1c40efc3500959b85e5a4a0_3372093"
run_stp_check:194 executing /usr/lib/systemtap/stp_check
Thus the system stopped after run_stp_check.
2. Once the system rebooted, we observed the latest dump file and
could get following information:
a. PANIC: "kernel BUG at fs/buffer.c:1950!" was the panic string.
b. Oops Message is as shown below:
kernel BUG at fs/buffer.c:1950!
invalid opcode: 0000 [#1]
last sysfs file: /module/ide_core/sections/.text
Modules linked in: stap_2b62fb77dc8202f9681e20fdc73b3c2b_3579 joydev
st sr_mod i915 drm snd_pcm_oss snd_mixer_oss ipv6 snd_seq
snd_seq_device af_packet binfm
t_misc button battery ac apparmor aamatch_pcre loop dm_mod
snd_intel8x0 snd_ac97_codec usbhid snd_ac97_bus snd_pcm snd_timer snd
soundcore i2c_i801 snd_page_
alloc intel_agp uhci_hcd ide_cd i2c_core ehci_hcd hw_random cdrom
usbcore agpgart i8xx_tco tg3 parport_pc lp parport reiserfs edd fan sg
thermal processor at
a_piix libata piix sd_mod scsi_mod ide_disk ide_core
CPU: 0
EIP: 0060:[<c015428f>] Tainted: G U VLI
EFLAGS: 00010246 (2.6.16.46-CORE-DUMP-By-Rajesh-0.12-default #15)
EIP is at __block_prepare_write+0x18/0x398
eax: 00000020 ebx: c8012030 ecx: c8012030 edx: c8012030
esi: e39ed7c0 edi: 00000005 ebp: c0321f0c esp: c0321eb4
ds: 007b es: 007b ss: 0068
Process swapper (pid: 0, threadinfo=c0320000 task=c02d12a0)
Stack: <0>c0105aa0 c8012030 c8012030 f7ffee40 0000000a c0321edc
c011cadf 470b0d6d
000c2045 002b6c9c c0321eec c012a343 00000000 e4875458 00000000 c0321f08
00000086 00000086 108a80cd c8012030 e39ed7c0 00000005 c0321f1c c0154627
Call Trace:
[<c010415d>] show_stack_log_lvl+0xaa/0xb5
[<c010427b>] show_registers+0x113/0x17f
[<c0104412>] die+0x12b/0x1aa
[<c0284006>] do_trap+0x7c/0x96
[<c0104a74>] do_invalid_op+0x89/0x93
[<c0103c4f>] error_code+0x4f/0x60
[<c0154627>] block_prepare_write+0x18/0x27
[<c0118ac8>] __put_task_struct_cb+0xee/0xf3
[<c0126467>] __rcu_process_callbacks+0xd3/0x128
[<c01264ce>] rcu_process_callbacks+0x12/0x23
[<c011d3c9>] tasklet_action+0x3a/0x5b
[<c011d26a>] __do_softirq+0x38/0x83
[<c011d2da>] do_softirq+0x25/0x2a
[<c011d4c9>] irq_exit+0x28/0x2a
[<c0104f9c>] do_IRQ+0x4e/0x5a
[<c0103b2a>] common_interrupt+0x1a/0x20
[<c0101d92>] cpu_idle+0x3b/0x50
[<c0100434>] rest_init+0x1e/0x22
[<c0322690>] start_kernel+0x2c3/0x2cb
[<c0100199>] 0xc0100199
Code: f0 83 c6 04 8b 45 ec 39 45 f0 7c 85 5e 5f 5b 5e 5f 5d c3 55 89
e5 57 56 53 83 ec 4c 89 45 b4 89 55 b0 89 4d ac 8b 02 a8 01 75 08 <0f>
0b 9e 07 b5 23 2a
c0 81 7d ac 00 10 00 00 76 08 0f 0b 9f 07
c. The code snippet from the file buffer.c that contains line number
1950 (as referred in the panic string ) is as shown below:
1941 static int __block_prepare_write(struct inode *inode, struct page *page,
1942 unsigned from, unsigned to, get_block_t *get_block)
1943 {
1944 unsigned block_start, block_end;
1945 sector_t block;
1946 int err = 0;
1947 unsigned blocksize, bbits;
1948 struct buffer_head *bh, *head, *wait[2], **wait_bh=wait;
1949
1950 BUG_ON(!PageLocked(page));
1951 BUG_ON(from > PAGE_CACHE_SIZE);
1952 BUG_ON(to > PAGE_CACHE_SIZE);
1953 BUG_ON(from > to);
I have enclosed the system information below:
Linux version: Suse Linux 10.1
Kernel version: 2.6.16.46-0.12
Machine: i686 (3192 MHz)
MEMORY: 1 GB
Systemtap version: systemtap-0.5.14.20070811-7
Vmlinux image with debug info is available in
/boot/vmlinux-2.6.16.46-0.12-debug (SIZE: 32MB)
Also config options CONFIG_DEBUG_INFO, CONFIG_KPROBES ,
CONFIG_DEBUG_FS and CONFIG_RELAY are set to y.
Can anyone please suggest us how to resolve the aforementioned issue?
Thanks,
Ramya