Issue related to stap scripts used for system call tracing

Issue related to stap scripts used for system call tracing

[ramya rao]

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

Re: Issue related to stap scripts used for system call tracing

[Frank Ch. Eigler]

"ramya rao" <ba.ramya@gmail.com> writes:

> [...]  we observed that system is crashing when we are executing
> scripts related to system calls.

That's not good.

> Given below is a script that traces "sys_open" system call.
> [...]

This looks fine.

> Also when we tried to trace do_fork system call, we observed that the
> system crashed.

My guess is that your debugging information had a mismatch with the
actual running kernel, and we failed to detect this.  Please check
the pc= numbers in
% stap -vv -p2 'probe syscall.read {}' 2>&1 | grep probe
against those in /proc/kallsyms.

- FChE