[developer] Strangeness in cpudrv's attach?

Discussion:

Dan McDonald via illumos-developer

2014-10-10 01:29:21 UTC

Consider this code from $SRC/uts/common/io/cpudrv.c:

/* NOTE, to reach here a previous call to cpudrv_is_enabled() must have succeded! */

280 mutex_init(&cpudsp->lock, NULL, MUTEX_DRIVER, NULL);
281 if (cpudrv_is_enabled(cpudsp)) {
282 if (cpudrv_init(cpudsp) != DDI_SUCCESS) {
283 cpudrv_enabled = B_FALSE;
284 cpudrv_free(cpudsp);
285 ddi_soft_state_free(cpudrv_state, instance);
286 return (DDI_FAILURE);
287 }
288 if (cpudrv_comp_create(cpudsp) != DDI_SUCCESS) {
289 cpudrv_enabled = B_FALSE;
290 cpudrv_free(cpudsp);
291 ddi_soft_state_free(cpudrv_state, instance);
292 return (DDI_FAILURE);
293 }
294 if (ddi_prop_update_string(DDI_DEV_T_NONE,
295 dip, "pm-class", "CPU") != DDI_PROP_SUCCESS) {
296 cpudrv_enabled = B_FALSE;
297 cpudrv_free(cpudsp);
298 ddi_soft_state_free(cpudrv_state, instance);
299 return (DDI_FAILURE);
300 }
301
302 /*
303 * Taskq is used to dispatch routine to monitor CPU
304 * activities.
305 */
306 cpudsp->cpudrv_pm.tq = ddi_taskq_create(dip,
307 "cpudrv_monitor", CPUDRV_TASKQ_THREADS,
308 TASKQ_DEFAULTPRI, 0);
309
310 mutex_init(&cpudsp->cpudrv_pm.timeout_lock, NULL,
311 MUTEX_DRIVER, NULL);
312 cv_init(&cpudsp->cpudrv_pm.timeout_cv, NULL,
313 CV_DEFAULT, NULL);
314
315 /*
316 * Driver needs to assume that CPU is running at
317 * unknown speed at DDI_ATTACH and switch it to the
318 * needed speed. We assume that initial needed speed
319 * is full speed for us.
320 */
321 /*
322 * We need to take the lock because cpudrv_monitor()
323 * will start running in parallel with attach().
324 */
325 mutex_enter(&cpudsp->lock);
326 cpudsp->cpudrv_pm.cur_spd = NULL;
327 cpudsp->cpudrv_pm.pm_started = B_FALSE;
328 /*
329 * We don't call pm_raise_power() directly from attach
330 * because driver attach for a slave CPU node can
331 * happen before the CPU is even initialized. We just
332 * start the monitoring system which understands
333 * unknown speed and moves CPU to top speed when it
334 * has been initialized.
335 */
336 CPUDRV_MONITOR_INIT(cpudsp);
337 mutex_exit(&cpudsp->lock);
338
339 }
340
341 if (!cpudrv_mach_init(cpudsp)) { /* XXX PANIC HERE if above if is FALSE! */

The last call above to cpudrv_mach_init() has an ASSERT() for cpudsp->cp not being NULL. Problem is, IF the above check for cpudrv_is_active() FAILS, cpudsp->cp will be NULL, and the machine will panic. I have a coredump to prove it!

Now how the failure (passes is_active(), then fails is_active()) may be relevant, but shouldn't this code be more robust?

What should REALLY happen if the shown cpudrv_is_active() call fails? Calling cpudrv_mach_init() immediately will panic your system, so I'd like a better solution. Even if it means changing the assert() in cpudrv_mach_init() to if (NULL) return B_FALSE. I'm leaning toward this last solution, as the caller appears to handle its failure robustly.

Thanks,
Dan

-------------------------------------------
illumos-developer
Archives: https://www.listbox.com/member/archive/182179/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182179/21175072-86d49504
Modify Your Subscription: https://www.listbox.com/member/?member_id=21175072&id_secret=21175072-abdf7b7e
Powered by Listbox: http://www.listbox.com

Rafael Vanoni via illumos-developer

2014-10-10 21:36:44 UTC

Permalink

Post by Dan McDonald via illumos-developer
/* NOTE, to reach here a previous call to cpudrv_is_enabled() must have succeded! */
280 mutex_init(&cpudsp->lock, NULL, MUTEX_DRIVER, NULL);
281 if (cpudrv_is_enabled(cpudsp)) {
282 if (cpudrv_init(cpudsp) != DDI_SUCCESS) {
283 cpudrv_enabled = B_FALSE;
284 cpudrv_free(cpudsp);
285 ddi_soft_state_free(cpudrv_state, instance);
286 return (DDI_FAILURE);
287 }
288 if (cpudrv_comp_create(cpudsp) != DDI_SUCCESS) {
289 cpudrv_enabled = B_FALSE;
290 cpudrv_free(cpudsp);
291 ddi_soft_state_free(cpudrv_state, instance);
292 return (DDI_FAILURE);
293 }
294 if (ddi_prop_update_string(DDI_DEV_T_NONE,
295 dip, "pm-class", "CPU") != DDI_PROP_SUCCESS) {
296 cpudrv_enabled = B_FALSE;
297 cpudrv_free(cpudsp);
298 ddi_soft_state_free(cpudrv_state, instance);
299 return (DDI_FAILURE);
300 }
301
302 /*
303 * Taskq is used to dispatch routine to monitor CPU
304 * activities.
305 */
306 cpudsp->cpudrv_pm.tq = ddi_taskq_create(dip,
307 "cpudrv_monitor", CPUDRV_TASKQ_THREADS,
308 TASKQ_DEFAULTPRI, 0);
309
310 mutex_init(&cpudsp->cpudrv_pm.timeout_lock, NULL,
311 MUTEX_DRIVER, NULL);
312 cv_init(&cpudsp->cpudrv_pm.timeout_cv, NULL,
313 CV_DEFAULT, NULL);
314
315 /*
316 * Driver needs to assume that CPU is running at
317 * unknown speed at DDI_ATTACH and switch it to the
318 * needed speed. We assume that initial needed speed
319 * is full speed for us.
320 */
321 /*
322 * We need to take the lock because cpudrv_monitor()
323 * will start running in parallel with attach().
324 */
325 mutex_enter(&cpudsp->lock);
326 cpudsp->cpudrv_pm.cur_spd = NULL;
327 cpudsp->cpudrv_pm.pm_started = B_FALSE;
328 /*
329 * We don't call pm_raise_power() directly from attach
330 * because driver attach for a slave CPU node can
331 * happen before the CPU is even initialized. We just
332 * start the monitoring system which understands
333 * unknown speed and moves CPU to top speed when it
334 * has been initialized.
335 */
336 CPUDRV_MONITOR_INIT(cpudsp);
337 mutex_exit(&cpudsp->lock);
338
339 }
340
341 if (!cpudrv_mach_init(cpudsp)) { /* XXX PANIC HERE if above if is FALSE! */
The last call above to cpudrv_mach_init() has an ASSERT() for cpudsp->cp not being NULL. Problem is, IF the above check for cpudrv_is_active() FAILS, cpudsp->cp will be NULL, and the machine will panic. I have a coredump to prove it!
Now how the failure (passes is_active(), then fails is_active()) may be relevant, but shouldn't this code be more robust?
What should REALLY happen if the shown cpudrv_is_active() call fails? Calling cpudrv_mach_init() immediately will panic your system, so I'd like a better solution. Even if it means changing the assert() in cpudrv_mach_init() to if (NULL) return B_FALSE. I'm leaning toward this last solution, as the caller appears to handle its failure robustly.
Thanks,
Dan

s/is_active/is_enabled

Hi Dan,

This may be happening because another CPU running a bit ahead of this
other failed to initialize CPU PM (probably a buggy ACPI table) and
decided to disable it. I see a few iffy things just by looking at some
of this cpudrv code, but can you check the value of cpudrv_enabled and
the cp->cpu_m.mcpu_pm_mach_state->ms_caps (cp being a cpu_t*) ?

This could be a race around cpudrv_enabled. Can you look for other
cpudrv*(), cpupm*() stack traces in the dump? Since you can reproduce
this, adding a few asserts on assignments to cpudsp->cp might help debug
this further.

You should be able to workaround this by disabling it in /etc/system, if
that's of use.

Cheers,
Rafael

-------------------------------------------
illumos-developer
Archives: https://www.listbox.com/member/archive/182179/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182179/21175072-86d49504
Modify Your Subscription: https://www.listbox.com/member/?member_id=21175072&id_secret=21175072-abdf7b7e
Powered by Listbox: http://www.listbox.com

Dan McDonald via illumos-developer

2014-10-10 21:55:22 UTC

Permalink

Post by Rafael Vanoni via illumos-developer
s/is_active/is_enabled
Hi Dan,
This may be happening because another CPU running a bit ahead of this other failed to initialize CPU PM (probably a buggy ACPI table) and decided to disable it. I see a few iffy things just by looking at some of this cpudrv code, but can you check the value of cpudrv_enabled and the cp->cpu_m.mcpu_pm_mach_state->ms_caps (cp being a cpu_t*) ?

cp is NULL (but its parent cpudrv_devstate_t had a CPU id of 8), and cpudrv_enabled actually is 0.

Post by Rafael Vanoni via illumos-developer
cpudrv_enabled/X

cpudrv_enabled:
cpudrv_enabled: 0

Post by Rafael Vanoni via illumos-developer
This could be a race around cpudrv_enabled. Can you look for other cpudrv*(), cpupm*() stack traces in the dump? Since you can reproduce this, adding a few asserts on assignments to cpudsp->cp might help debug this further.

This dump was from a customer's production system. I can't just go and debug this. I'd have done all of this myself if I could do it in-house.

I did find other threads, though:

ffffff01e9013c40 fffffffffbc2eb80 0 0 60 0
PC: panic_idle+0x20 THREAD: mt_config_thread()
stack pointer for thread ffffff01e9013c40: ffffff01e90137b0
cpudrv_is_enabled+0x27()
cpudrv_attach+0x3a()
devi_attach+0x92()
attach_node+0xa7()
i_ndi_config_node+0x86()
i_ddi_attachchild+0x48()
devi_attach_node+0x5e()
config_immediate_children+0xbf()
devi_config_common+0xd9()
mt_config_thread+0x58()
thread_start+8()

THREE threads looked like this:

ffffff01e8b1ac40 fffffffffbc2eb80 0 0 -1 0
PC: panic_idle+0x20 THREAD: idle()
stack pointer for thread ffffff01e8b1ac40: ffffff01e8b1a8c0
cpupm_record_turbo_info+0x41()
do_splx+0x65()
tsc_gethrtimeunscaled_delta+0x3c()
gethrtime_unscaled+0xa()
cpu_idle_exit_state+0x2b()
tsc_gethrtimeunscaled_delta+0x3c()
gethrtime_unscaled+0xa()
cpu_idle_exit_state+0x2b()
0xffffff01e8b1aad0()
apix_do_interrupt+0xfe()
_interrupt+0xba()
i86_mwait+0xd()
cpu_idle_mwait+0x109()
idle+0xa7()
thread_start+8()

I'll see if any of them have CPU pointers, and better, if any of them have id==8. I can't do that right this second, though.

Post by Rafael Vanoni via illumos-developer
You should be able to workaround this by disabling it in /etc/system, if that's of use.

I'll remember that.

Does my "return FALSE instead of panic" make any sense? I have no sense of that from the audience, and looking at the code, it seems the no-brainer thing to do.

Thanks,
Dan

-------------------------------------------
illumos-developer
Archives: https://www.listbox.com/member/archive/182179/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182179/21175072-86d49504
Modify Your Subscription: https://www.listbox.com/member/?member_id=21175072&id_secret=21175072-abdf7b7e
Powered by Listbox: http://www.listbox.com

Rafael Vanoni via illumos-developer

2014-10-10 22:22:21 UTC

Permalink

Post by Dan McDonald via illumos-developer

cp is NULL (but its parent cpudrv_devstate_t had a CPU id of 8), and cpudrv_enabled actually is 0.

Post by Rafael Vanoni via illumos-developer
cpudrv_enabled/X

cpudrv_enabled: 0

This dump was from a customer's production system. I can't just go and debug this. I'd have done all of this myself if I could do it in-house.
ffffff01e9013c40 fffffffffbc2eb80 0 0 60 0
PC: panic_idle+0x20 THREAD: mt_config_thread()
stack pointer for thread ffffff01e9013c40: ffffff01e90137b0
cpudrv_is_enabled+0x27()
cpudrv_attach+0x3a()
devi_attach+0x92()
attach_node+0xa7()
i_ndi_config_node+0x86()
i_ddi_attachchild+0x48()
devi_attach_node+0x5e()
config_immediate_children+0xbf()
devi_config_common+0xd9()
mt_config_thread+0x58()
thread_start+8()
ffffff01e8b1ac40 fffffffffbc2eb80 0 0 -1 0
PC: panic_idle+0x20 THREAD: idle()
stack pointer for thread ffffff01e8b1ac40: ffffff01e8b1a8c0
cpupm_record_turbo_info+0x41()
do_splx+0x65()
tsc_gethrtimeunscaled_delta+0x3c()
gethrtime_unscaled+0xa()
cpu_idle_exit_state+0x2b()
tsc_gethrtimeunscaled_delta+0x3c()
gethrtime_unscaled+0xa()
cpu_idle_exit_state+0x2b()
0xffffff01e8b1aad0()
apix_do_interrupt+0xfe()
_interrupt+0xba()
i86_mwait+0xd()
cpu_idle_mwait+0x109()
idle+0xa7()
thread_start+8()
I'll see if any of them have CPU pointers, and better, if any of them have id==8. I can't do that right this second, though.

Post by Rafael Vanoni via illumos-developer
You should be able to workaround this by disabling it in /etc/system, if that's of use.

I'll remember that.
Does my "return FALSE instead of panic" make any sense? I have no sense of that from the audience, and looking at the code, it seems the no-brainer thing to do.
Thanks,
Dan

Given that this isn't reproducible in house, that would be fine with me.
Please file a bug for future reference. I'd suggest wrapping a lock
around cpudrv_enabled, it seems fairly self contained. But again, w/o a
reproducible test that's a moot point.

Rafael

-------------------------------------------
illumos-developer
Archives: https://www.listbox.com/member/archive/182179/=now
RSS Feed: https://www.listbox.com/member/archive/rss/182179/21175072-86d49504
Modify Your Subscription: https://www.listbox.com/member/?member_id=21175072&id_secret=21175072-abdf7b7e
Powered by Listbox: http://www.listbox.com