This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Issue related to stap scripts used for system call tracing


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


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]