Kernel oops and 100% CPU usage on fbt:isofs:: probes about linux HOT 8 OPEN

Hello OmegaPhil

interesting. Are you having success for things which have not been
modprobe'd after the dtrace module?

On 19 August 2012 20:14, OmegaPhil [email protected] wrote:

dtrace: commit d663d2dhttps://github.com/dtrace4linux/linux/commit/d663d2dde5c56f79494306b50411d6a2e740e0e1,
Sat Aug 18 16:24:10 2012 +0100
uname -a: Linux debian-testing-vm 3.2.0-3-amd64 #1https://github.com/dtrace4linux/linux/issues/1SMP Mon Jul 23 02:45:17 UTC 2012 x86_64 GNU/Linux

I am currently trying out dtrace in my Debian virtual machine 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] [] ? mutex_enter_common+0x27/0xcb [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883758] [] ? par_alloc+0x1f/0xc6 [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883798] [] ? fbt_provide_module+0x34/0x23e [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883808] [] ? device_create_vargs+0x86/0xbe
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883816] [] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883825] [] ? _cond_resched+0x7/0x1c
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883830] [] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883836] [] ? _cond_resched+0x7/0x1c
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883842] [] ? mutex_lock+0xd/0x2d
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883883] [] ? dtrace_module_loaded+0x92/0x10d [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883891] [] ? notifier_call_chain+0x2e/0x5b
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883897] [] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883904] [] ? _blocking_notifier_call_chain+0x48/0x5e
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883912] [] ? sys_init_module+0x1b6/0x25b
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883919] [] ? 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: [] 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:[] [] 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] [] ? dtrace_ecb_create_enable+0x1b4c/0x1be0 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880574] [] ? dtrace_match_probe+0x8c/0xa6 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880579] [] ? dtrace_ecb_destroy+0x555/0x555 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880585] [] ? dtrace_match+0x1f8/0x226 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880590] [] ? __kmalloc+0x100/0x112
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880596] [] ? kmem_zalloc+0x2e/0x54 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880602] [] ? dtrace_probe_enable+0x170/0x177 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880608] [] ? dtrace_strcmp+0x1b/0x1b [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880613] [] ? dtrace_strcmp+0x1b/0x1b [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880618] [] ? dtrace_match_glob+0x199/0x199 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880623] [] ? dtrace_match_glob+0x199/0x199 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880628] [] ? dtrace_enabling_match+0x13a/0x1ca [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880634] [] ? dtrace_ioctl+0xc3e/0x217a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880637] [] ? pte_offset_kernel+0x16/0x35
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880644] [] ? zone_page_state_add+0x14/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880647] [] ? __inc_zone_state+0x41/0x49
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880650] [] ? zone_statistics+0x41/0x74
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880653] [] ? get_page_from_freelist+0x57a/0x665
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880656] [] ? __alloc_pages_nodemask+0x6bf/0x726
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880659] [] ? find_get_page+0x40/0x63
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880661] [] ? should_resched+0x5/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880665] [] ? _cond_resched+0x7/0x1c
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880668] [] ? filemap_fault+0x1e6/0x33e
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880671] [] ? lookup_page_cgroup+0x2d/0x42
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880673] [] ? mem_cgroup_update_page_stat+0x17/0xd4
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880676] [] ? __do_fault+0x371/0x3ac
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880678] [] ? handle_pte_fault+0x298/0x79f
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880680] [] ? pte_offset_kernel+0x16/0x35
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880687] [] ? dtracedrv_ioctl.isra.3+0x3c/0x4d [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880693] [] ? dtracedrv_unlocked_ioctl+0x6/0xa [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880697] [] ? do_vfs_ioctl+0x459/0x49a
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880699] [] ? should_resched+0x5/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880702] [] ? remove_vma+0x64/0x6b
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880704] [] ? do_munmap+0x2da/0x2f3
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880706] [] ? sys_ioctl+0x4b/0x72
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880710] [] ? 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 [] fbt_enable+0x5b/0x6a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880744] RSP
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.

�
Reply to this email directly or view it on GitHubhttps://github.com//issues/40.

from linux.

I just reproduced on deb6-64 - worked fine on Ubuntu....off to debug.

On 19 August 2012 20:22, Paul Fox [email protected] wrote:

Hello OmegaPhil

interesting. Are you having success for things which have not been
modprobe'd after the dtrace module?

On 19 August 2012 20:14, OmegaPhil [email protected] wrote:

dtrace: commit d663d2dhttps://github.com/dtrace4linux/linux/commit/d663d2dde5c56f79494306b50411d6a2e740e0e1,
Sat Aug 18 16:24:10 2012 +0100
uname -a: Linux debian-testing-vm 3.2.0-3-amd64 #1https://github.com/dtrace4linux/linux/issues/1SMP Mon Jul 23 02:45:17 UTC 2012 x86_64 GNU/Linux

I am currently trying out dtrace in my Debian virtual machine 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] [] ? mutex_enter_common+0x27/0xcb [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883758] [] ? par_alloc+0x1f/0xc6 [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883798] [] ? fbt_provide_module+0x34/0x23e [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883808] [] ? device_create_vargs+0x86/0xbe
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883816] [] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883825] [] ? _cond_resched+0x7/0x1c
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883830] [] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883836] [] ? _cond_resched+0x7/0x1c
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883842] [] ? mutex_lock+0xd/0x2d
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883883] [] ? dtrace_module_loaded+0x92/0x10d [dtracedrv]
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883891] [] ? notifier_call_chain+0x2e/0x5b
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883897] [] ? should_resched+0x5/0x23
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883904] [] ? _blocking_notifier_call_chain+0x48/0x5e
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883912] [] ? sys_init_module+0x1b6/0x25b
Aug 19 19:44:36 debian-testing-vm kernel: [ 146.883919] [] ? 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: [] 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:[] [] 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] [] ? dtrace_ecb_create_enable+0x1b4c/0x1be0 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880574] [] ? dtrace_match_probe+0x8c/0xa6 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880579] [] ? dtrace_ecb_destroy+0x555/0x555 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880585] [] ? dtrace_match+0x1f8/0x226 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880590] [] ? __kmalloc+0x100/0x112
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880596] [] ? kmem_zalloc+0x2e/0x54 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880602] [] ? dtrace_probe_enable+0x170/0x177 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880608] [] ? dtrace_strcmp+0x1b/0x1b [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880613] [] ? dtrace_strcmp+0x1b/0x1b [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880618] [] ? dtrace_match_glob+0x199/0x199 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880623] [] ? dtrace_match_glob+0x199/0x199 [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880628] [] ? dtrace_enabling_match+0x13a/0x1ca [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880634] [] ? dtrace_ioctl+0xc3e/0x217a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880637] [] ? pte_offset_kernel+0x16/0x35
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880644] [] ? zone_page_state_add+0x14/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880647] [] ? __inc_zone_state+0x41/0x49
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880650] [] ? zone_statistics+0x41/0x74
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880653] [] ? get_page_from_freelist+0x57a/0x665
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880656] [] ? __alloc_pages_nodemask+0x6bf/0x726
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880659] [] ? find_get_page+0x40/0x63
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880661] [] ? should_resched+0x5/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880665] [] ? _cond_resched+0x7/0x1c
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880668] [] ? filemap_fault+0x1e6/0x33e
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880671] [] ? lookup_page_cgroup+0x2d/0x42
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880673] [] ? mem_cgroup_update_page_stat+0x17/0xd4
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880676] [] ? __do_fault+0x371/0x3ac
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880678] [] ? handle_pte_fault+0x298/0x79f
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880680] [] ? pte_offset_kernel+0x16/0x35
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880687] [] ? dtracedrv_ioctl.isra.3+0x3c/0x4d [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880693] [] ? dtracedrv_unlocked_ioctl+0x6/0xa [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880697] [] ? do_vfs_ioctl+0x459/0x49a
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880699] [] ? should_resched+0x5/0x23
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880702] [] ? remove_vma+0x64/0x6b
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880704] [] ? do_munmap+0x2da/0x2f3
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880706] [] ? sys_ioctl+0x4b/0x72
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880710] [] ? 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 [] fbt_enable+0x5b/0x6a [dtracedrv]
Aug 19 19:44:56 debian-testing-vm kernel: [ 166.880744] RSP
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.

�
Reply to this email directly or view it on GitHubhttps://github.com//issues/40.

from linux.

Ha, wow, thanks for the fast feedback! Your last message came as I was just hacking together my first basic 'commandline' script:

dtrace -n 'proc:::start,proc:::exit { printf("Process: %s %s", execname, probename); }'

Works perfectly. Just say if you want me to test anything. If you use IRC, I'm OmegaPhil on Freenode, if you want faster feedback.

Cheers

from linux.

Hello Phil

i've tracked the issue down to the way modules are loaded; when dtrace is
loaded, it gets the callback as the module loads, but some of the pages in
a module are freed (the .init section) but dtrace doesnt know this. I found

cat /proc/dtrace/fbt

will give a GPF for functions no longer in memory, so now I have something
to debug.

I wont get around to fixing tonite - maybe in next day or two, so just be
careful of modprobes; if you unload dtrace and reload after the new module,
everything should be fine.

(Im normally on google chat).

Have fun!

On 19 August 2012 20:30, OmegaPhil [email protected] wrote:

Ha, wow, thanks for the fast feedback! Your last message came as I was
just hacking together my first basic 'commandline' script:

execname, probename); }'

Works perfectly. Just say if you want me to test anything. If you use IRC,
I'm OmegaPhil on Freenode, if you want faster feedback.

Cheers

—
Reply to this email directly or view it on GitHubhttps://github.com/dtrace4linux/linux/issues/40#issuecomment-7855970.

from linux.

Excellent, thanks for the workaround - should be fine (I'm basically a n00b doing my first kernel dive, looked into dtrace today).

from linux.

Works great - heres the output when mount locks up with 100% kernel mode on trying to mount a presumably bad iso9660 filesystem:

dtrace: script './isofs_tracing.d' matched 96 probes
CPU     ID                    FUNCTION:NAME
  0 262919                isofs_mount:entry isofs_mount entry
  0 262920           isofs_fill_super:entry isofs_fill_super entry
  0 262934                   sb_bread:entry sb_bread entry
  0 262935                     brelse:entry brelse entry
  0 262936                    brelse:return brelse return
  0 262934                   sb_bread:entry sb_bread entry
  0 262935                     brelse:entry brelse entry
  0 262935                     brelse:entry brelse entry
  0 262995                 isofs_iget:entry isofs_iget entry
  0 262932          isofs_alloc_inode:entry isofs_alloc_inode entry
  0 262937                  init_once:entry init_once entry
  0 262937                  init_once:entry init_once entry
  0 262937                  init_once:entry init_once entry
  0 262937                  init_once:entry init_once entry
  0 262937                  init_once:entry init_once entry
  0 262937                  init_once:entry init_once entry
  0 262933         isofs_alloc_inode:return isofs_alloc_inode return
  0 262917            isofs_iget5_set:entry isofs_iget5_set entry
  0 262918           isofs_iget5_set:return isofs_iget5_set return
  0 262934                   sb_bread:entry sb_bread entry

Never returns from sb_bread presumably. Now to see how to work kgdb!

from linux.

Just a note to say I fixed the driver loading issue.

Interested to see how you get on with this issue, and if dtrace helps you.

thanks

On 19 August 2012 22:29, OmegaPhil [email protected] wrote:

Works great - heres the output when mount locks up with 100% kernel mode
on trying to mount a presumably bad iso9660 filesystem:

dtrace: script './isofs_tracing.d' matched 96 probes
CPU ID FUNCTION:NAME
0 262919 isofs_mount:entry isofs_mount entry
0 262920 isofs_fill_super:entry isofs_fill_super entry
0 262934 sb_bread:entry sb_bread entry
0 262935 brelse:entry brelse entry
0 262936 brelse:return brelse return
0 262934 sb_bread:entry sb_bread entry
0 262935 brelse:entry brelse entry
0 262935 brelse:entry brelse entry
0 262995 isofs_iget:entry isofs_iget entry
0 262932 isofs_alloc_inode:entry isofs_alloc_inode entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262933 isofs_alloc_inode:return isofs_alloc_inode return
0 262917 isofs_iget5_set:entry isofs_iget5_set entry
0 262918 isofs_iget5_set:return isofs_iget5_set return
0 262934 sb_bread:entry sb_bread entry

Never returns from sb_bread presumably. Now to see how to work kgdb!

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/40#issuecomment-7857051.

from linux.

Cheers :)

Sure - should I spam here or somewhere else? I think this is pretty much
what I was aiming to get out of dtrace (although I am somewhat ignorant
of what it can achieve). I am currently levelling up to start diving
into the kernel proper with kgdb, now I have some target functions to
look at. I dont really know C and I'm certainly no kernel programmer -
my target is more to find some crap code and then do a basic patch to
detect the problem and exit out. Locking up mount and then making the
operating system unrestartable without a hardboot is Windows-level
failure, so I thought it would be a good introduction.

On 20/08/12 23:37, dtrace4linux wrote:

Just a note to say I fixed the driver loading issue.

Interested to see how you get on with this issue, and if dtrace helps you.

thanks

On 19 August 2012 22:29, OmegaPhil [email protected] wrote:

Works great - heres the output when mount locks up with 100% kernel mode
on trying to mount a presumably bad iso9660 filesystem:

dtrace: script './isofs_tracing.d' matched 96 probes
CPU ID FUNCTION:NAME
0 262919 isofs_mount:entry isofs_mount entry
0 262920 isofs_fill_super:entry isofs_fill_super entry
0 262934 sb_bread:entry sb_bread entry
0 262935 brelse:entry brelse entry
0 262936 brelse:return brelse return
0 262934 sb_bread:entry sb_bread entry
0 262935 brelse:entry brelse entry
0 262935 brelse:entry brelse entry
0 262995 isofs_iget:entry isofs_iget entry
0 262932 isofs_alloc_inode:entry isofs_alloc_inode entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262937 init_once:entry init_once entry
0 262933 isofs_alloc_inode:return isofs_alloc_inode return
0 262917 isofs_iget5_set:entry isofs_iget5_set entry
0 262918 isofs_iget5_set:return isofs_iget5_set return
0 262934 sb_bread:entry sb_bread entry

Never returns from sb_bread presumably. Now to see how to work kgdb!

—
Reply to this email directly or view it on
GitHubhttps://github.com//issues/40#issuecomment-7857051.

—
Reply to this email directly or view it on GitHub
#40 (comment).

from linux.