From: Rusty Russell Subject: cpu hotplug: benchmark times for various stages. This is a simple hack, designed to show where we are actually spending time in cpu hotplug. Signed-off-by: Rusty Russell --- kernel/cpu.c | 143 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 140 insertions(+), 3 deletions(-) diff --git a/kernel/cpu.c b/kernel/cpu.c --- a/kernel/cpu.c +++ b/kernel/cpu.c @@ -139,13 +139,109 @@ int __ref register_cpu_notifier(struct n return ret; } +/* Hotplug measurement hack. */ +#include +struct cpu_plug_time { + const char *tag; + union ktime ktime; + int (*notifier_call)(struct notifier_block *, unsigned long, void *); +}; + +static struct cpu_plug_time cpu_times[1024]; +static unsigned int num_cpu_times; + +static void mark_time(const char *tag, + int (*call)(struct notifier_block *, + unsigned long, + void *)) +{ + if (num_cpu_times == ARRAY_SIZE(cpu_times)) + return; + cpu_times[num_cpu_times].tag = tag; + cpu_times[num_cpu_times].ktime = ktime_get(); + cpu_times[num_cpu_times++].notifier_call = call; +} + +static void reset_time(const char *tag) +{ + cpu_times[0].tag = tag; + cpu_times[0].ktime = ktime_get(); + cpu_times[0].notifier_call = NULL; + + num_cpu_times = 1; +} + +static void dump_times(void) +{ + unsigned int i; + + printk("Time information for %s:\n", cpu_times[0].tag); + for (i = 1; i < num_cpu_times; i++) { + unsigned long unused; + char namebuf[KSYM_NAME_LEN]; + union ktime diff; + struct cpu_plug_time *t = &cpu_times[i]; + + diff = ktime_sub(t->ktime, cpu_times[i-1].ktime); + printk("%llu: %s: %p (%s)\n", + (long long)ktime_to_ns(diff), t->tag, + t->notifier_call, + t->notifier_call ? + kallsyms_lookup((unsigned long)t->notifier_call, + &unused, &unused, NULL, namebuf) : + "NULL"); + } +} + +static int notifier_call_chain_cpu(struct notifier_block **nl, + unsigned long val, void *v, + int nr_to_call, + int *nr_calls) +{ + int ret = NOTIFY_DONE; + struct notifier_block *nb, *next_nb; + + mark_time("notifier start", NULL); + nb = rcu_dereference_raw(*nl); + + while (nb && nr_to_call) { + next_nb = rcu_dereference_raw(nb->next); + +#ifdef CONFIG_DEBUG_NOTIFIERS + if (unlikely(!func_ptr_is_kernel_text(nb->notifier_call))) { + WARN(1, "Invalid notifier called!"); + nb = next_nb; + continue; + } +#endif + ret = nb->notifier_call(nb, val, v); + mark_time("notifier call", nb->notifier_call); + + if (nr_calls) + (*nr_calls)++; + + if ((ret & NOTIFY_STOP_MASK) == NOTIFY_STOP_MASK) + break; + nb = next_nb; + nr_to_call--; + } + return ret; +} + +static int __raw_notifier_call_chain_cpu(struct raw_notifier_head *nh, + unsigned long val, void *v, + int nr_to_call, int *nr_calls) +{ + return notifier_call_chain_cpu(&nh->head, val, v, nr_to_call, nr_calls); +} + static int __cpu_notify(unsigned long val, void *v, int nr_to_call, int *nr_calls) { int ret; - ret = __raw_notifier_call_chain(&cpu_chain, val, v, nr_to_call, - nr_calls); + ret = __raw_notifier_call_chain_cpu(&cpu_chain, val, v, nr_to_call, + nr_calls); return notifier_to_errno(ret); } @@ -199,11 +295,15 @@ static int __ref take_cpu_down(void *_pa int err; /* Ensure this CPU doesn't handle any more interrupts. */ + mark_time("__cpu_disable start", NULL); err = __cpu_disable(); + mark_time("__cpu_disable end", NULL); if (err < 0) return err; + mark_time("CPU_DYING start", NULL); cpu_notify(CPU_DYING | param->mod, param->hcpu); + mark_time("CPU_DYING end", NULL); return 0; } @@ -225,8 +325,11 @@ static int __ref _cpu_down(unsigned int return -EINVAL; cpu_hotplug_begin(); + mark_time("cpu_hotplug_begin", NULL); + mark_time("CPU_DOWN_PREPARE start", NULL); err = __cpu_notify(CPU_DOWN_PREPARE | mod, hcpu, -1, &nr_calls); + mark_time("CPU_DOWN_PREPARE end", NULL); if (err) { nr_calls--; __cpu_notify(CPU_DOWN_FAILED | mod, hcpu, nr_calls, NULL); @@ -235,7 +338,9 @@ static int __ref _cpu_down(unsigned int goto out_release; } + mark_time("stop_machine start", NULL); err = __stop_machine(take_cpu_down, &tcd_param, cpumask_of(cpu)); + mark_time("stop_machine end", NULL); if (err) { /* CPU didn't die: tell everyone. Can't complain. */ cpu_notify_nofail(CPU_DOWN_FAILED | mod, hcpu); @@ -251,19 +356,26 @@ static int __ref _cpu_down(unsigned int * * Wait for the stop thread to go away. */ + mark_time("idle_cpu start", NULL); while (!idle_cpu(cpu)) cpu_relax(); + mark_time("idle_cpu end", NULL); /* This actually kills the CPU. */ __cpu_die(cpu); + mark_time("__cpu_die", NULL); /* CPU is completely dead: tell everyone. Too late to complain. */ + mark_time("CPU_DEAD start", NULL); cpu_notify_nofail(CPU_DEAD | mod, hcpu); + mark_time("CPU_DEAD end", NULL); check_for_tasks(cpu); + mark_time("check_for_tasks", NULL); out_release: cpu_hotplug_done(); + mark_time("cpu_hotplug_done", NULL); if (!err) cpu_notify_nofail(CPU_POST_DEAD | mod, hcpu); return err; @@ -273,17 +385,23 @@ int __ref cpu_down(unsigned int cpu) { int err; + reset_time("cpu_down"); cpu_maps_update_begin(); + mark_time("cpu_maps_update_begin", NULL); if (cpu_hotplug_disabled) { err = -EBUSY; goto out; } + mark_time("_cpu_down start", NULL); err = _cpu_down(cpu, 0); + mark_time("_cpu_down end", NULL); out: cpu_maps_update_done(); + mark_time("cpu_maps_update_done", NULL); + dump_times(); return err; } EXPORT_SYMBOL(cpu_down); @@ -299,7 +417,10 @@ static int __cpuinit _cpu_up(unsigned in if (cpu_online(cpu) || !cpu_present(cpu)) return -EINVAL; + mark_time("_cpu_up start", NULL); cpu_hotplug_begin(); + mark_time("cpu_hotplug_begin", NULL); + mark_time("CPU_UP_PREPARE start:", NULL); ret = __cpu_notify(CPU_UP_PREPARE | mod, hcpu, -1, &nr_calls); if (ret) { nr_calls--; @@ -307,19 +428,26 @@ static int __cpuinit _cpu_up(unsigned in __func__, cpu); goto out_notify; } + mark_time("CPU_UP_PREPARE end", NULL); /* Arch-specific enabling code. */ ret = __cpu_up(cpu); + mark_time("__cpu_up", NULL); if (ret != 0) goto out_notify; BUG_ON(!cpu_online(cpu)); /* Now call notifier in preparation. */ + mark_time("CPU_ONLINE start:", NULL); cpu_notify(CPU_ONLINE | mod, hcpu); + mark_time("CPU_ONLINE end", NULL); out_notify: - if (ret != 0) + if (ret != 0) { + mark_time("CPU_UP_CANCELED", NULL); __cpu_notify(CPU_UP_CANCELED | mod, hcpu, nr_calls, NULL); + } + mark_time("cpu_hotplug_done", NULL); cpu_hotplug_done(); return ret; @@ -344,7 +472,9 @@ int __cpuinit cpu_up(unsigned int cpu) return -EINVAL; } + reset_time("cpu_up"); #ifdef CONFIG_MEMORY_HOTPLUG + nid = cpu_to_node(cpu); if (!node_online(nid)) { err = mem_online_node(nid); @@ -366,6 +496,7 @@ int __cpuinit cpu_up(unsigned int cpu) } #endif + mark_time("cpu_maps_update_begin", NULL); cpu_maps_update_begin(); if (cpu_hotplug_disabled) { @@ -376,7 +507,13 @@ int __cpuinit cpu_up(unsigned int cpu) err = _cpu_up(cpu, 0); out: + mark_time("cpu_maps_update_done", NULL); cpu_maps_update_done(); + if (err) + mark_time("cpu_up failed", NULL); + else + mark_time("cpu_up success", NULL); + dump_times(); return err; } EXPORT_SYMBOL_GPL(cpu_up);