RE: Kernel panics during execution of timeouts.stp example when booted with kgdboc=kms,kbd

[<dmitry.krivenok@emc.com>]

[-- Attachment #1: Type: text/plain, Size: 5435 bytes --]

Hi,
I've configured serial console on my Fedora-16 VM and below is what I got:

...
...
[   15.083666] abrtd[716]: Init complete, entering main loop
Entering kdb (current=0xffff880131281730, pid 1185) on processor 3 Oops: (null)
due to oops @ 0xffffffff81076c2b
CPU 3 <d>Modules linked in: stap_5c9aa472e68e1b50280a6ab04af46f6e__1185 nfs fscache auth_rpcgss nfs_acl lockd 8021q fcoe libfcoe libfc scsi_transport_fc scsi_tgt garp stp llc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables ppdev vmw_balloon microcode e1000 parport_pc parport i2c_piix4 i2c_core uinput shpchp sunrpc mptspi mptscsih mptbase scsi_transport_spi [last unloaded: scsi_wait_scan]
<c>
<d>Pid: 1185, comm: stapio Not tainted 3.1.4-1.fc16.x86_64 #1<c> VMware, Inc. VMware Virtual Platform<c>/440BX Desktop Reference Platform<c>
<d>RIP: 0010:[<ffffffff81076c2b>]  [<ffffffff81076c2b>] sys_nanosleep+0x1/0x6a
<d>RSP: 0018:ffff88013068ff80  EFLAGS: 00000297
<d>RAX: 0000000000000023 RBX: ffffffffffffffff RCX: 00007fbdf15389d0
<d>RDX: 0000000000000000 RSI: 0000000000000000 RDI: 00007fffb165b740
<d>RBP: 00007fbdf273a010 R08: 00007fbdf1538700 R09: 00007fbdf1e72f50
<d>R10: 00007fbdf15389d0 R11: 0000000000000293 R12: 0000000000008002
<d>R13: 00007fbdf27403b0 R14: 00007fbdf273a008 R15: 000000000000000b
<d>FS:  00007fbdf2514700(0000) GS:ffff88013fd80000(0000) knlGS:0000000000000000
<d>CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
<d>CR2: 00007fbdf1df5340 CR3: 0000000133b3a000 CR4: 00000000000006e0
<d>DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
<d>DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process stapio (pid: 1185, threadinfo ffff88013068e000, task ffff880131281730)
<0>Stack:
<c> ffffffff814bd9c2<c> 0000000000000293<c> 00007fbdf15389d0<c> 00007fbdf1e72f50<c>
<c> 00007fbdf1538700<c> 0000000000000023<c> 00007fbdf20fd7e5<c> 0000000000000000<c>
<c> 0000000000000000<c> 00007fffb165b740<c> 0000000000000023<c> 00007fbdf1df536d<c>
<0>Call Trace:
[3]more> 
<0> [<ffffffff814bd9c2>] ? system_call_fastpath+0x16/0x1b
[3]more> 
<0>Code: ff ba fc fd ff ff 48 63 c2 48 8b 55 d8 65 48 33 14 25 28 00 00 00 74 05 e8 14 0b fe ff 48 83 c4 70 5b 41 5c 41 5d 41 5e 5d c3 cc <48> 89 e5 41 54 53 48 83 ec 10 66 66 66 66 90 49 89 fc 48 89 f3 
[3]more> 
Call Trace:
[3]more> 
 [<ffffffff814bd9c2>] ? system_call_fastpath+0x16/0x1b
[3]more> 
[3]more> 
[3]kdb>


Also, I've run "sudo stap-report > ~/tmp/stap-report.out 2>&1" and attached the output.
I'm going to investigate this problem more deeply later today and then post the results.

Thanks,
Dmitry

-----Original Message-----
From: systemtap-owner@sourceware.org [mailto:systemtap-owner@sourceware.org] On Behalf Of Mark Wielaard
Sent: Wednesday, December 07, 2011 3:20 PM
To: Krivenok, Dmitry
Cc: systemtap@sourceware.org
Subject: Re: Kernel panics during execution of timeouts.stp example when booted with kgdboc=kms,kbd

Hi,

On Tue, 2011-12-06 at 03:39 -0500, dmitry.krivenok@emc.com wrote:
> The problem is that kernel panics if you run it with "kgdboc=kms,kbd"
> parameter and then run standard timeout.stp example as follows:
> 
> $ sudo stap -v `locate timeout.stp`
> Pass 1: parsed user script and 77 library script(s) using 78192virt/22076res/2376shr kb, in 190usr/60sys/689real ms.
> Pass 2: analyzed script: 12 probe(s), 7 function(s), 5 embed(s), 10 global(s) using 202032virt/44892res/3256shr kb, in 790usr/4810sys/10056real ms.
> Pass 3: using cached /root/.systemtap/cache/dd/stap_ddd8c5ac8daf0d8644742908043722b3_12685.c
> Pass 4: using cached /root/.systemtap/cache/dd/stap_ddd8c5ac8daf0d8644742908043722b3_12685.ko
> Pass 5: starting run.
> 
> I also tried to run stap with -vvv options and the last lines I saw were:
> ...
> ...
> execing: /usr/local/libexec/systemtap/stapio -v -v -R stap_ddd8c5ac8daf0d8644742908043722b3_1_777
> stapio:parse_modpath:368 modpath="/lib/modules/3.1.1/systemtap/stap_ddd8c5ac8daf0d8644742908043722b3_1_777.ko"
> stapio:main:41 modpath="/lib/modules/3.1.1/systemtap/stap_ddd8c5ac8daf0d8644742908043722b3_1_777.ko", modname="stap_ddd8c5ac8daf0d8644742908043722b3_1_777"
> stapio:init_stapio:338 init_stapio
> stapio:init_ctl_channel:31 Opened /sys/kernel/debug/systemtap/stap_ddd8c5ac8daf0d8644742908043722b3_1_777/.cmd (3)
> stapio:stp_main_loop:529 in main loop
> stapio:init_relayfs:239 initializing relayfs
> stapio:init_relayfs:263 attempting to open /sys/kernel/debug/systemtap/stap_ddd8c5ac8daf0d8644742908043722b3_1_777/trace0
> stapio:init_relayfs:263 attempting to open /sys/kernel/debug/systemtap/stap_ddd8c5ac8daf0d8644742908043722b3_1_777/trace1
> stapio:init_relayfs:269 ncpus=1, bulkmode = 0
> stapio:init_relayfs:352 starting threads
> 
> The problem is 100% reproducible on both systems.
> I'm not sure if it's a bug in Systemtap or kernel, because I could misconfigure something.
> 
> Could someone please try to reproduce the problem and post results here?

I don't have the above setup here handy atm. But it would be helpful if
you could post the results of 'stap-report' somewhere. And even better
if you could try and get a serial console dump of the kernel panic you
are getting, see http://sourceware.org/systemtap/wiki/HowToReportBugs
and here http://sourceware.org/systemtap/wiki/DeveloperSetupTips for
some guides on setting that up.

Thanks,

Mark



[-- Attachment #2: stap-report.out --]
[-- Type: application/octet-stream, Size: 7263 bytes --]

== stap -V ==
Systemtap translator/driver (version 1.6/0.152 non-git sources)
Copyright (C) 2005-2011 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
enabled features: AVAHI LIBRPM LIBSQLITE3 NSS BOOST_SHARED_PTR TR1_UNORDERED_MAP NLS
== which stap ==
/usr/bin/stap
== locate --regex '/stap(run)?$' | xargs ls -ald ==
-rwxr-xr-x 1 root root    1913816 Jul 26 03:24 /usr/bin/stap
---s--x--- 1 root stapusr  154464 Jul 26 03:24 /usr/bin/staprun
== printenv | egrep '^PATH=|^LD_LIBRARY_PATH=|^SYSTEMTAP_.*=|^XDG_DATA.*=' ==
PATH=/sbin:/bin:/usr/sbin:/usr/bin
== stap -vv -p4 -e 'probe begin {exit()}' ==
Systemtap translator/driver (version 1.6/0.152 non-git sources)
Copyright (C) 2005-2011 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
enabled features: AVAHI LIBRPM LIBSQLITE3 NSS BOOST_SHARED_PTR TR1_UNORDERED_MAP NLS
Created temporary directory "/tmp/stapaoSrhE"
Session arch: x86_64 release: 3.1.4-1.fc16.x86_64
Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
Searched: " /usr/share/systemtap/tapset/*.stp ", found: 74, processed: 74
Pass 1: parsed user script and 78 library script(s) using 97528virt/22848res/2864shr kb, in 170usr/50sys/219real ms.
Pass 2: analyzed script: 1 probe(s), 1 function(s), 0 embed(s), 0 global(s) using 97924virt/23376res/2928shr kb, in 10usr/0sys/7real ms.
function recursion-analysis: max-nesting 0  non-recursive
Pass 3: translated to C into "/tmp/stapaoSrhE/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.c" using 98036virt/23832res/3324shr kb, in 0usr/0sys/0real ms.
Running make -C /lib/modules/3.1.4-1.fc16.x86_64/build M=/tmp/stapaoSrhE modules ARCH=x86_64 --no-print-directory
  CC [M]  /tmp/stapaoSrhE/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.o
  Building modules, stage 2.
  MODPOST 1 modules
  CC      /tmp/stapaoSrhE/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.mod.o
  LD [M]  /tmp/stapaoSrhE/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.ko
Spawn waitpid result (0x0): 0
/root/.systemtap/cache/2b/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.ko
Pass 4: compiled C into "stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.ko" in 6180usr/4280sys/10664real ms.
Copying /tmp/stapaoSrhE/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.ko to /root/.systemtap/cache/2b/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.ko
Copying /tmp/stapaoSrhE/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.c to /root/.systemtap/cache/2b/stap_2b9c7007d8b51b58a7b3d1ad5572cdfa_723.c
Copying /tmp/stapaoSrhE/stapconf_4068b222ed1181e542189cbb03c46ca6_543.h to /root/.systemtap/cache/40/stapconf_4068b222ed1181e542189cbb03c46ca6_543.h
Running rm -rf /tmp/stapaoSrhE
Spawn waitpid result (0x0): 0
== gcc -v ==
Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/usr/libexec/gcc/x86_64-redhat-linux/4.6.2/lto-wrapper
Target: x86_64-redhat-linux
Configured with: ../configure --prefix=/usr --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=http://bugzilla.redhat.com/bugzilla --enable-bootstrap --enable-shared --enable-threads=posix --enable-checking=release --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-gnu-unique-object --enable-linker-build-id --enable-languages=c,c++,objc,obj-c++,java,fortran,ada,go,lto --enable-plugin --enable-java-awt=gtk --disable-dssi --with-java-home=/usr/lib/jvm/java-1.5.0-gcj-1.5.0.0/jre --enable-libgcj-multifile --enable-java-maintainer-mode --with-ecj-jar=/usr/share/java/eclipse-ecj.jar --disable-libjava-multilib --with-ppl --with-cloog --with-tune=generic --with-arch_32=i686 --build=x86_64-redhat-linux
Thread model: posix
gcc version 4.6.2 20111027 (Red Hat 4.6.2-1) (GCC) 
== uname -a ==
Linux csx-spb-fedora16 3.1.4-1.fc16.x86_64 #1 SMP Tue Nov 29 11:37:53 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux
== dmesg | egrep 'stap|systemtap' | tail -n 10 ==
== cat /proc/cpuinfo | egrep 'processor|vendor_id|model name' ==
processor	: 0
vendor_id	: GenuineIntel
model name	: Intel(R) Xeon(R) CPU            5120  @ 1.86GHz
processor	: 1
vendor_id	: GenuineIntel
model name	: Intel(R) Xeon(R) CPU            5120  @ 1.86GHz
processor	: 2
vendor_id	: GenuineIntel
model name	: Intel(R) Xeon(R) CPU            5120  @ 1.86GHz
processor	: 3
vendor_id	: GenuineIntel
model name	: Intel(R) Xeon(R) CPU            5120  @ 1.86GHz
== rpm -qa --qf '%{name}-%{version} %{release}.%{arch}\n' | egrep 'systemtap|elfutils|kernel|gcc' | sort ==
abrt-addon-kerneloops-2.0.6 1.fc16.x86_64
elfutils-0.152 1.fc16.x86_64
elfutils-libelf-0.152 1.fc16.x86_64
elfutils-libs-0.152 1.fc16.x86_64
gcc-4.6.2 1.fc16.x86_64
gcc-c++-4.6.2 1.fc16.x86_64
gcc-gfortran-4.6.2 1.fc16.x86_64
kernel-3.1.1 2.fc16.x86_64
kernel-3.1.2 1.fc16.x86_64
kernel-3.1.4 1.fc16.x86_64
kernel-debuginfo-3.1.4 1.fc16.x86_64
kernel-debuginfo-common-x86_64-3.1.4 1.fc16.x86_64
kernel-devel-3.1.1 2.fc16.x86_64
kernel-devel-3.1.2 1.fc16.x86_64
kernel-devel-3.1.4 1.fc16.x86_64
kernel-headers-3.1.4 1.fc16.x86_64
kernel-tools-3.1.4 1.fc16.x86_64
libgcc-4.6.2 1.fc16.x86_64
libreport-plugin-kerneloops-2.0.7 1.fc16.x86_64
systemtap-1.6 1.fc16.x86_64
systemtap-runtime-1.6 1.fc16.x86_64
systemtap-sdt-devel-1.6 1.fc16.x86_64
== egrep 'PROBE|TRACE|MARKER|_DEBUG_' /lib/modules/3.1.4-1.fc16.x86_64/build/.config | grep -v not.set | sort | fmt -w 80 ==
CONFIG_AIC79XX_DEBUG_MASK=0 CONFIG_AIC7XXX_DEBUG_MASK=0
CONFIG_ARCH_CPU_PROBE_RELEASE=y CONFIG_ARCH_MEMORY_PROBE=y
CONFIG_ARCH_SUPPORTS_DEBUG_PAGEALLOC=y CONFIG_BLK_DEV_IO_TRACE=y
CONFIG_CAN_PM_TRACE=y CONFIG_CB710_DEBUG_ASSUMPTIONS=y
CONFIG_CONTEXT_SWITCH_TRACER=y CONFIG_DEBUG_BOOT_PARAMS=y
CONFIG_DEBUG_BUGVERBOSE=y CONFIG_DEBUG_DEVRES=y CONFIG_DEBUG_FS=y
CONFIG_DEBUG_INFO=y CONFIG_DEBUG_KERNEL=y CONFIG_DEBUG_LIST=y
CONFIG_DEBUG_MEMORY_INIT=y CONFIG_DEBUG_NX_TEST=m CONFIG_DEBUG_RODATA=y
CONFIG_DEBUG_RODATA_TEST=y CONFIG_DEBUG_SHIRQ=y CONFIG_DEBUG_STACKOVERFLOW=y
CONFIG_DYNAMIC_FTRACE=y CONFIG_FTRACE=y CONFIG_FTRACE_MCOUNT_RECORD=y
CONFIG_FTRACE_NMI_ENTER=y CONFIG_FTRACE_SYSCALLS=y
CONFIG_FUNCTION_GRAPH_TRACER=y CONFIG_FUNCTION_TRACER=y
CONFIG_GENERIC_IRQ_PROBE=y CONFIG_GENERIC_TRACER=y CONFIG_HAVE_ARCH_TRACEHOOK=y
CONFIG_HAVE_DYNAMIC_FTRACE=y CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y
CONFIG_HAVE_FTRACE_NMI_ENTER=y CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_FUNCTION_TRACER=y CONFIG_HAVE_FUNCTION_TRACE_MCOUNT_TEST=y
CONFIG_HAVE_KPROBES=y CONFIG_HAVE_KRETPROBES=y
CONFIG_HAVE_MMIOTRACE_SUPPORT=y CONFIG_HAVE_OPTPROBES=y
CONFIG_HAVE_SYSCALL_TRACEPOINTS=y CONFIG_INFINIBAND_IPOIB_DEBUG_DATA=y
CONFIG_KEYS_DEBUG_PROC_KEYS=y CONFIG_KPROBES=y CONFIG_KPROBE_EVENT=y
CONFIG_KRETPROBES=y CONFIG_MTD_GEN_PROBE=m CONFIG_MTD_JEDECPROBE=m
CONFIG_MTD_NAND_DISKONCHIP_PROBE_ADDRESS=0 CONFIG_MTD_QINFO_PROBE=m
CONFIG_NETFILTER_XT_TARGET_TRACE=m CONFIG_NET_DCCPPROBE=m
CONFIG_NET_SCTPPROBE=m CONFIG_NOP_TRACER=y CONFIG_OPTPROBES=y
CONFIG_PM_TRACE=y CONFIG_PM_TRACE_RTC=y CONFIG_SCHED_TRACER=y
CONFIG_STACKTRACE=y CONFIG_STACKTRACE_SUPPORT=y CONFIG_STACK_TRACER=y
CONFIG_TRACEPOINTS=y CONFIG_TRACER_MAX_TRACE=y CONFIG_TRACE_IRQFLAGS_SUPPORT=y
CONFIG_USER_STACKTRACE_SUPPORT=y CONFIG_UTRACE=y CONFIG_WIMAX_DEBUG_LEVEL=8
CONFIG_WIMAX_I2400M_DEBUG_LEVEL=8 CONFIG_XEN_DEBUG_FS=y
== find /debugfs /proc /sys /dev -name '*kprobes*' 2>/dev/null | xargs grep . ==
/proc/sys/debug/kprobes-optimization:1