Skip to content

Kernel oops and 100% CPU usage on fbt:isofs:: probes #40

@OmegaPhil

Description

@OmegaPhil

dtrace: commit d663d2d, Sat Aug 18 16:24:10 2012 +0100
uname -a: Linux debian-testing-vm 3.2.0-3-amd64 #1 SMP Mon Jul 23 02:45:17 UTC 2012 x86_64 GNU/Linux

I am currently trying out dtrace in my Debian virtual machine (Debian Wheezy/Testing) via Virtualbox in order to probe anything that goes on in the isofs kernel module (trying to find out more about a hang).

After loading the module (sudo modprobe -v isofs) I run the following trivial script (my first):

#!/usr/sbin/dtrace -s


/* Intercepting all isofs function entries and exits */
fbt:isofs::
{
        trace("worked!");
        exit(0);
        /*printf("%s %s", probefunc, probename);*/
}

Originally I had the normal printf line, but thats commented out to test this in general. When the above script is ran, the following kernel oops happens:

Aug 19 19:44:36 debian-testing-vm kernel: [  146.857394] dtracedrv: module license 'CDDL' taints kernel.
Aug 19 19:44:36 debian-testing-vm kernel: [  146.857402] Disabling lock debugging due to kernel taint
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883607] Pid: 3198, comm: insmod Tainted: P           O 3.2.0-3-amd64 #1
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883614] Call Trace:
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883689]  [<ffffffffa052e001>] ? mutex_enter_common+0x27/0xcb [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883758]  [<ffffffffa0524807>] ? par_alloc+0x1f/0xc6 [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883798]  [<ffffffffa052b473>] ? fbt_provide_module+0x34/0x23e [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883808]  [<ffffffff8124d0e2>] ? device_create_vargs+0x86/0xbe
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883816]  [<ffffffff81036457>] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883825]  [<ffffffff813499cf>] ? _cond_resched+0x7/0x1c
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883830]  [<ffffffff81036457>] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883836]  [<ffffffff813499cf>] ? _cond_resched+0x7/0x1c
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883842]  [<ffffffff8134a1b0>] ? mutex_lock+0xd/0x2d
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883883]  [<ffffffffa050c86e>] ? dtrace_module_loaded+0x92/0x10d [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883891]  [<ffffffff8134dcd6>] ? notifier_call_chain+0x2e/0x5b
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883897]  [<ffffffff81036457>] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883904]  [<ffffffff81063261>] ? __blocking_notifier_call_chain+0x48/0x5e
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883912]  [<ffffffff81074f6e>] ? sys_init_module+0x1b6/0x25b
Aug 19 19:44:36 debian-testing-vm kernel: [  146.883919]  [<ffffffff8134fc92>] ? system_call_fastpath+0x16/0x1b
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880448] BUG: unable to handle kernel paging request at ffffffffa0182086
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880453] IP: [<ffffffffa052b91a>] fbt_enable+0x5b/0x6a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880464] PGD 1607067 PUD 160b063 PMD 3745b067 PTE 0
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880468] Oops: 0002 [#1] SMP 
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880470] CPU 0 
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880471] Modules linked in: isofs dtracedrv(P) vboxsf(O) pci_stub vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) mperf cpufreq_stats cpufreq_conservative cpufreq_userspace cpufreq_powers
ave ppdev lp vboxvideo(O) drm rfcomm bnep bluetooth rfkill binfmt_misc fuse vhba(O) loop joydev i2c_piix4 snd_intel8x0 snd_ac97_codec snd_pcm snd_page_alloc snd_seq snd_seq_device snd_timer snd soundcore i2c_core ac97_bus parport_pc psmo
use ac serio_raw power_supply parport button processor evdev thermal_sys pcspkr vboxguest(O) ext4 crc16 jbd2 mbcache usbhid hid sd_mod crc_t10dif sr_mod cdrom ata_generic ata_piix ahci libahci ohci_hcd ehci_hcd e1000 libata usbcore scsi_
mod usb_common [last unloaded: scsi_wait_scan]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880507] 
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880509] Pid: 3225, comm: isofs_tracing.d Tainted: P           O 3.2.0-3-amd64 #1 innotek GmbH VirtualBox
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880512] RIP: 0010:[<ffffffffa052b91a>]  [<ffffffffa052b91a>] fbt_enable+0x5b/0x6a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880520] RSP: 0018:ffff88003c965898  EFLAGS: 00010202
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880522] RAX: ffffffffa0182086 RBX: ffff88001e0c97c0 RCX: 0000000000000002
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880524] RDX: 7fffffffffffffcc RSI: ffff88003c965848 RDI: 000000003745b067
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880525] RBP: ffff88001e0c9740 R08: ffff880000000c18 R09: ffff88000160b800
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880526] R10: ffff88001e118ff8 R11: 0000000000000000 R12: ffff88003744ffc0
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880528] R13: 0000000000000000 R14: ffff88001e091600 R15: ffffffffa05194e1
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880536] FS:  00007fd4d9c4b700(0000) GS:ffff88003fc00000(0000) knlGS:0000000000000000
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880538] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880539] CR2: ffffffffa0182086 CR3: 000000001e118000 CR4: 00000000000006f0
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880543] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880545] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880546] Process isofs_tracing.d (pid: 3225, threadinfo ffff88003c964000, task ffff88003cede180)
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880548] Stack:
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880549]  ffff88001bfffd40 ffffffffa051b02d ffff88001e018200 0000000000000007
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880552]  ffff880000000006 ffff88001e0e66c0 ffff88001e0182c0 ffffffffa050c0da
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880555]  0000000000000006 ffff88003c9659f0 0000000000000007 ffff8800265bc300
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880557] Call Trace:
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880564]  [<ffffffffa051b02d>] ? dtrace_ecb_create_enable+0x1b4c/0x1be0 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880574]  [<ffffffffa050c0da>] ? dtrace_match_probe+0x8c/0xa6 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880579]  [<ffffffffa05194e1>] ? dtrace_ecb_destroy+0x555/0x555 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880585]  [<ffffffffa050c2ec>] ? dtrace_match+0x1f8/0x226 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880590]  [<ffffffff810eb6e5>] ? __kmalloc+0x100/0x112
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880596]  [<ffffffffa052456b>] ? kmem_zalloc+0x2e/0x54 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880602]  [<ffffffffa051b231>] ? dtrace_probe_enable+0x170/0x177 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880608]  [<ffffffffa050e34f>] ? dtrace_strcmp+0x1b/0x1b [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880613]  [<ffffffffa050e34f>] ? dtrace_strcmp+0x1b/0x1b [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880618]  [<ffffffffa0508f03>] ? dtrace_match_glob+0x199/0x199 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880623]  [<ffffffffa0508f03>] ? dtrace_match_glob+0x199/0x199 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880628]  [<ffffffffa051b372>] ? dtrace_enabling_match+0x13a/0x1ca [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880634]  [<ffffffffa0520fe5>] ? dtrace_ioctl+0xc3e/0x217a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880637]  [<ffffffff810cd779>] ? pte_offset_kernel+0x16/0x35
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880644]  [<ffffffff810c926a>] ? zone_page_state_add+0x14/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880647]  [<ffffffff810c9ec0>] ? __inc_zone_state+0x41/0x49
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880650]  [<ffffffff810ca0dd>] ? zone_statistics+0x41/0x74
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880653]  [<ffffffff810ba446>] ? get_page_from_freelist+0x57a/0x665
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880656]  [<ffffffff810bad51>] ? __alloc_pages_nodemask+0x6bf/0x726
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880659]  [<ffffffff810b3c44>] ? find_get_page+0x40/0x63
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880661]  [<ffffffff81036457>] ? should_resched+0x5/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880665]  [<ffffffff813499cf>] ? _cond_resched+0x7/0x1c
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880668]  [<ffffffff810b5aa8>] ? filemap_fault+0x1e6/0x33e
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880671]  [<ffffffff810f5ef5>] ? lookup_page_cgroup+0x2d/0x42
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880673]  [<ffffffff810f18d1>] ? mem_cgroup_update_page_stat+0x17/0xd4
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880676]  [<ffffffff810cdecd>] ? __do_fault+0x371/0x3ac
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880678]  [<ffffffff810d019f>] ? handle_pte_fault+0x298/0x79f
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880680]  [<ffffffff810cd779>] ? pte_offset_kernel+0x16/0x35
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880687]  [<ffffffffa0523c2e>] ? dtracedrv_ioctl.isra.3+0x3c/0x4d [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880693]  [<ffffffffa0523c4f>] ? dtracedrv_unlocked_ioctl+0x6/0xa [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880697]  [<ffffffff81106911>] ? do_vfs_ioctl+0x459/0x49a
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880699]  [<ffffffff81036457>] ? should_resched+0x5/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880702]  [<ffffffff810d3612>] ? remove_vma+0x64/0x6b
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880704]  [<ffffffff810d47c7>] ? do_munmap+0x2da/0x2f3
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880706]  [<ffffffff8110699d>] ? sys_ioctl+0x4b/0x72
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880710]  [<ffffffff8134fc92>] ? system_call_fastpath+0x16/0x1b
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880714] Code: 54 a0 48 8b 73 08 31 c0 e8 ff 92 00 00 48 8b 7b 08 ba 01 00 00 00 be 01 00 00 00 e8 8e 8e ff ff 85 c0 74 09 48 8b 43 08 8a 53 12 <88> 10 48 8b 5b 48 48 85 db 75 b0 31 c0 5b c3 41 56 41 89 d6 41 
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880737] RIP  [<ffffffffa052b91a>] fbt_enable+0x5b/0x6a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880744]  RSP <ffff88003c965898>
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880745] CR2: ffffffffa0182086
Aug 19 19:44:56 debian-testing-vm kernel: [  166.880747] ---[ end trace b484dd282d33d09e ]---

Something (no process name) then uses 100% kernel mode time on one CPU, and dtrace ignores SIGINT - time to reboot.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions