When try the following simple probe with the current systemtap snapshot (20060713) on 2.6.17-1.2366.fc6 on x86_64 machine (need to use work around mentioned in Red Hat bugzilla #197220): stap -vv -k -e 'probe begin { log ("hello world") }' Get the following report in /var/log/messages: Jul 13 11:27:02 dhcp59-158 kernel: BUG: sleeping function called from invalid context at kernel/mutex.c:86 Jul 13 11:27:02 dhcp59-158 kernel: in_atomic():0, irqs_disabled():1 Jul 13 11:27:02 dhcp59-158 kernel: Jul 13 11:27:02 dhcp59-158 kernel: Call Trace: Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff8026c869>] dump_stack+0x12/0x17 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff80264c86>] mutex_lock+0x15/0x23 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff803fdf49>] cpufreq_get+0x36/0x93 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff885c164b>] :stap_2379:__stp_init_time+0x63/0x122 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff80291396>] on_each_cpu+0x19/0x22 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff885c0ccf>] :stap_2379:_stp_init_time+0x19/0x30 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff885c1ade>] :stap_2379:_stp_handle_start+0x9/0x49 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff885c1b9a>] :stap_2379:_stp_proc_write_cmd+0x7c/0xc2 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff802168e4>] vfs_write+0xce/0x174 Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff8021717e>] sys_write+0x45/0x6e Jul 13 11:27:02 dhcp59-158 kernel: [<ffffffff8025eace>] system_call+0x7e/0x83 Code in src/runtime/time.c is causing the problem: int _stp_init_time(void) { int ret = 0; ret = on_each_cpu(__stp_init_time, NULL, 0, 1); #ifdef CONFIG_CPU_FREQ if (ret == 0) ret = cpufreq_register_notifier(&__stp_time_notifier, CPUFREQ_TRANSITION_NOTIFIER); #endif return ret; }
The question is why this __stp_init_time appears to be in irqs_disabled context. Does the "on_each_cpu" IPI widget imply that?
Subject: Re: BUG: sleeping function called from invalid context at kernel/mutex.c:86 "fche at redhat dot com" <sourceware-bugzilla@sourceware.org> writes: > ------- Additional Comments From fche at redhat dot com 2006-07-13 20:15 ------- > The question is why this __stp_init_time appears to be in irqs_disabled context. > Does the "on_each_cpu" IPI widget imply that? Yes. Quoting kernel/softirq.c: /* * Call a function on all processors */ int on_each_cpu(void (*func) (void *info), void *info, int retry, int wait) { int ret = 0; preempt_disable(); ret = smp_call_function(func, info, retry, wait); local_irq_disable(); func(info); local_irq_enable(); preempt_enable(); return ret; }
I should be able to move this call away from the IPI handler, instead doing a for_each_online_cpu->cpufreq_get. I will test this and commit if it looks okay...
Fixed in src/runtime/time.c r1.3