Re: [PATCH 1/7] Simple Performance Counters: Core Piece
From: Mathieu Desnoyers
Date: Fri Aug 17 2007 - 12:48:14 EST
Hi Christoph,
Actually, get_cycles() at least on some AMD cpus, do not synchronize the
core, which can skew the results. You might want to use
get_cycles_sync() there.
Mathieu
* Christoph Lameter (clameter@xxxxxxx) wrote:
> Simple performance counters are a way to measure the performance on code
> paths in the Linux kernel. Code must be instrumented with calls that signal
> the start and the stop of a measurement.
>
> The beginning of a code path must have the following. Either:
>
> INIT_PC(var)
>
> or
> struct pc var;
>
> ...
>
> pc_start(&var);
>
>
>
> and at the end of the segment of code to be measured either:
>
> pc_stop(&var, PC_xxx);
>
> to just measure time intervals. Or
>
> pc_bytes(&var, bytes, PC_xxx)
>
> to measure the amount of data that a code path can handle.
>
>
> The data can then be viewed as the kernel runs via
>
> cat /proc/perf/all
>
> Which will show some timing and performance statistics. The numbers in ()
> show 3 values: (mininum/average/maximum)
>
> update_process_times 21370 14.8ms(194ns/693ns/9us)
> alloc_pages 297542 189.4ms(96ns/637ns/68.7us) 1.2gb(4.1kb/4.2kb/16.4kb)
> kmem_cache_alloc 637116 71.7ms(10ns/113ns/60.8us)
> kmem_cache_free 566426 39.2ms(19ns/69ns/7.1us)
> kfree 48622 4.1ms(19ns/84ns/3.7us)
>
>
> update_process_times needed between 194ns and 9us. On average is needsd 693 nanoseconds.
> 21370 measurements werer performed.
>
>
> Data can be zeroed by writing to /proc/perf/reset.
>
> Typically one would zero the counters and then perform a kernel activity that
> exercises the instrumented code path.
>
>
>
> Data can be viewed in
> /proc/perf
>
> Special files:
>
> /proc/perf/all Shows a summary
> /proc/perf/reset Writing to this file resets counters
> /proc/perf/0 Counters on processor 0
>
> Signed-off-by: Christoph Lameter <clameter@xxxxxxx>
> ---
> include/linux/perf.h | 55 ++++++++
> init/Kconfig | 10 ++
> kernel/Makefile | 1 +
> kernel/perf.c | 368 ++++++++++++++++++++++++++++++++++++++++++++++++++
> kernel/timer.c | 3 +
> 5 files changed, 437 insertions(+), 0 deletions(-)
> create mode 100644 include/linux/perf.h
> create mode 100644 kernel/perf.c
>
> diff --git a/include/linux/perf.h b/include/linux/perf.h
> new file mode 100644
> index 0000000..2958c81
> --- /dev/null
> +++ b/include/linux/perf.h
> @@ -0,0 +1,55 @@
> +#ifndef __LINUX_PERF_H
> +#define __LINUX_PERF_H
> +
> +#include <linux/timex.h>
> +/*
> + * Time Stamp Performance Counters
> + *
> + * (C) 2007 Silicon Graphics, Inc.
> + * Christoph Lameter <clameter@xxxxxxx>, April 2007
> + *
> + * Counters are calculated using the cycle counter. If a process
> + * is migrated to another cpu during the measurement then the measurement
> + * is invalid.
> + */
> +
> +enum pc_item {
> + PC_UPDATE_PROCESS_TIMES,
> + NR_PC_ITEMS
> +};
> +
> +/*
> + * Information about the start of the measurement
> + */
> +struct pc {
> + unsigned long time;
> + int processor;
> +};
> +
> +#define pc_stop(__pc, __nr) pc_bytes(__pc, 0, __nr)
> +
> +#ifdef CONFIG_PERFCOUNT
> +
> +#define INIT_PC(__var) struct pc __var = \
> + { get_cycles(), raw_smp_processor_id() }
> +
> +static inline void pc_start(struct pc *pc)
> +{
> + pc->processor = raw_smp_processor_id();
> + pc->time = get_cycles();
> +}
> +
> +void pc_bytes(struct pc *pc, unsigned long bytes, enum pc_item nr);
> +
> +void pc_stop_printk(struct pc *pc);
> +
> +#else
> +
> +#define INIT_PC(__var) char __var[0]
> +#define pc_start(__var) do { } while (!__var)
> +#define pc_bytes(__var, __b, __i) do { } while (!__var)
> +#define pc_stop_printk(__var) do { } while (!__var)
> +#endif
> +
> +#endif
> +
> diff --git a/init/Kconfig b/init/Kconfig
> index 96b5459..affb532 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -206,6 +206,16 @@ config TASK_IO_ACCOUNTING
>
> Say N if unsure.
>
> +config PERFCOUNT
> + bool "Time Stamp Counter based performance measurements"
> + help
> + Enables performance counters based on the time stamp counters.
> + These can be used to measure code paths in the kernel and also
> + gauge their effectiveness in transferring bytes. The performance
> + counters must be added by modifying code. The counters will then
> + be visible via files in /proc/perf/*.
> +
> +
> config USER_NS
> bool "User Namespaces (EXPERIMENTAL)"
> default n
> diff --git a/kernel/Makefile b/kernel/Makefile
> index 2a99983..0f3eaa9 100644
> --- a/kernel/Makefile
> +++ b/kernel/Makefile
> @@ -51,6 +51,7 @@ obj-$(CONFIG_RELAY) += relay.o
> obj-$(CONFIG_SYSCTL) += utsname_sysctl.o
> obj-$(CONFIG_TASK_DELAY_ACCT) += delayacct.o
> obj-$(CONFIG_TASKSTATS) += taskstats.o tsacct.o
> +obj-$(CONFIG_PERFCOUNT) += perf.o
>
> ifneq ($(CONFIG_SCHED_NO_NO_OMIT_FRAME_POINTER),y)
> # According to Alan Modra <alan@xxxxxxxxxxxxxxxx>, the -fno-omit-frame-pointer is
> diff --git a/kernel/perf.c b/kernel/perf.c
> new file mode 100644
> index 0000000..14cba9c
> --- /dev/null
> +++ b/kernel/perf.c
> @@ -0,0 +1,368 @@
> +/*
> + * Simple Performance Counter subsystem
> + *
> + * (C) 2007 Silicong Graphics, Inc.
> + *
> + * Christoph Lameter <clameter@xxxxxxx>
> + */
> +
> +#include <linux/module.h>
> +#include <linux/percpu.h>
> +#include <linux/seq_file.h>
> +#include <linux/fs.h>
> +#include <linux/proc_fs.h>
> +#include <linux/cpumask.h>
> +#include <linux/perf.h>
> +
> +#ifdef CONFIG_NUMA
> +static int unsynced_get_cycles = 1;
> +#else
> +#define unsynced_get_cycles 0
> +#endif
> +
> +const char *var_id[NR_PC_ITEMS] = {
> + "update_process_times",
> +};
> +
> +struct perf_counter {
> + u32 events;
> + u32 mintime;
> + u32 maxtime;
> + u32 minbytes;
> + u32 maxbytes;
> + u32 skipped;
> + u64 time;
> + u64 bytes;
> +};
> +
> +static DEFINE_PER_CPU(struct perf_counter, perf_counters)[NR_PC_ITEMS];
> +
> +void pc_bytes(struct pc *pc, unsigned long bytes, enum pc_item nr)
> +{
> + unsigned long time = get_cycles();
> + unsigned long ns;
> + struct perf_counter *p = &get_cpu_var(perf_counters)[nr];
> +
> + if (unlikely(nr >= NR_PC_ITEMS)) {
> + printk(KERN_CRIT "pc_bytes: item number "
> + "(%d) out of range\n", nr);
> + dump_stack();
> + goto out;
> + }
> +
> + if (unlikely(unsynced_get_cycles &&
> + pc->processor != smp_processor_id())) {
> + /* On different processor. TSC measurement not possible. */
> + p->skipped++;
> + goto out;
> + }
> +
> + ns = cycles_to_ns((unsigned long long)(time - pc->time));
> + p->time += ns;
> + p->events++;
> +
> + if (ns > p->maxtime)
> + p->maxtime = ns;
> +
> + if (p->mintime == 0 || ns < p->mintime)
> + p->mintime = ns;
> +
> + if (bytes) {
> + p->bytes += bytes;
> + if (bytes > p->maxbytes)
> + p->maxbytes = bytes;
> + if (p->minbytes == 0 || bytes < p->minbytes)
> + p->minbytes = bytes;
> + }
> +out:
> + put_cpu_var();
> + return;
> +}
> +EXPORT_SYMBOL(pc_bytes);
> +
> +static void reset_perfcount_item(struct perf_counter *c)
> +{
> + memset(c, 0, sizeof(struct perf_counter));
> +}
> +
> +static void perfcount_reset(void) {
> + int cpu;
> + enum pc_item i;
> +
> + for_each_online_cpu(cpu)
> + for (i = 0; i < NR_PC_ITEMS; i++)
> + reset_perfcount_item(
> + &per_cpu(perf_counters, cpu)[i]);
> +}
> +
> +struct unit {
> + unsigned int n;
> + const char * s;
> +};
> +
> +static const struct unit event_units[] = {
> + { 1000, "" },
> + { 1000, "K" },
> + { 1000, "M" },
> + { 1000, "G" },
> + { 1000, "T" },
> + { 1000, "P" },
> + { 1000, "Q" },
> +};
> +
> +
> +static const struct unit time_units[] = {
> + { 1000, "ns" },
> + { 1000, "us" },
> + { 1000, "ms" },
> + { 60, "s" },
> + { 60, "m" },
> + { 24, "h" },
> + { 365, "d" },
> + { 1000, "y" },
> +};
> +
> +static const struct unit byte_units[] = {
> + { 1000, "b" },
> + { 1000, "kb" },
> + { 1000, "mb" },
> + { 1000, "gb" },
> + { 1000, "tb" },
> + { 1000, "pb" },
> + { 1000, "qb" }
> +};
> +
> +/* Print a value using the given array of units and scale it properly */
> +static void pval(struct seq_file *s, unsigned long x, const struct unit *u)
> +{
> + unsigned n = 0;
> + unsigned rem = 0;
> + unsigned last_divisor = 0;
> +
> + while (x >= u[n].n) {
> + last_divisor = u[n].n;
> + rem = x % last_divisor;
> + x = x / last_divisor;
> + n++;
> + }
> +
> + if (last_divisor)
> + rem = (rem * 10 + last_divisor / 2) / last_divisor;
> + else
> + rem = 0;
> +
> + /*
> + * Rounding may have resulted in the need to go
> + * to the next number
> + */
> + if (rem == 10) {
> + x++;
> + rem = 0;
> + };
> +
> + seq_printf(s, "%lu", x);
> + if (rem) {
> + seq_putc(s, '.');
> + seq_putc(s, '0' + rem);
> + }
> + seq_puts(s, u[n].s);
> +}
> +
> +/* Print a value using the given array of units and scale it properly */
> +void pc_stop_printk(struct pc *pc)
> +{
> + unsigned n = 0;
> + unsigned rem = 0;
> + unsigned last_divisor = 0;
> + const struct unit *u = time_units;
> + unsigned long x = cycles_to_ns(get_cycles() - pc->time);
> +
> + while (x >= u[n].n) {
> + last_divisor = u[n].n;
> + rem = x % last_divisor;
> + x = x / last_divisor;
> + n++;
> + }
> +
> + if (last_divisor)
> + rem = (rem * 10 + last_divisor / 2) / last_divisor;
> + else
> + rem = 0;
> +
> + /*
> + * Rounding may have resulted in the need to go
> + * to the next number
> + */
> + if (rem == 10) {
> + x++;
> + rem = 0;
> + };
> +
> + printk("%lu", x);
> + if (rem) {
> + char x[3] = ".0";
> +
> + x[1] += rem;
> + printk(x);
> + }
> + printk(u[n].s);
> +}
> +
> +/* Print a set of statistical values in the form sum(max/avg/min) */
> +static void pc_print(struct seq_file *s, const struct unit *u,
> + unsigned long count, unsigned long sum,
> + unsigned long min, unsigned long max)
> +{
> + pval(s, sum, u);
> + seq_putc(s,'(');
> + pval(s, min, u);
> + seq_putc(s,'/');
> + if (count)
> + pval(s, (sum + count / 2 ) / count, u);
> + else
> + pval(s, 0, u);
> + seq_putc(s,'/');
> + pval(s, max, u);
> + seq_putc(s,')');
> +}
> +
> +
> +static int perf_show(struct seq_file *s, void *v)
> +{
> + int cpu = (unsigned long)s->private;
> + enum pc_item counter = (unsigned long)v - 1;
> + struct perf_counter summary, *x;
> +
> + if (cpu >= 0)
> + x = &per_cpu(perf_counters, cpu)[counter];
> + else {
> + memcpy(&summary, &per_cpu(perf_counters, 0)[counter],
> + sizeof(summary));
> + for_each_online_cpu(cpu) {
> + struct perf_counter *c =
> + &per_cpu(perf_counters, 0)[counter];
> +
> + summary.events += c->events;
> + summary.skipped += c->skipped;
> + summary.time += c->time;
> + summary.bytes += c->bytes;
> +
> + if (summary.maxtime < c->maxtime)
> + summary.maxtime = c->maxtime;
> +
> + if (summary.mintime == 0 ||
> + (c->mintime != 0 &&
> + summary.mintime > c->mintime))
> + summary.mintime = c->mintime;
> +
> + if (summary.maxbytes < c->maxbytes)
> + summary.maxbytes = c->maxbytes;
> +
> + if (summary.minbytes == 0 ||
> + (c->minbytes != 0 &&
> + summary.minbytes > c->minbytes))
> + summary.minbytes = c->minbytes;
> +
> + }
> + x = &summary;
> + }
> +
> + seq_printf(s, "%-30s %10u ", var_id[counter], x->events);
> + if (x->skipped)
> + seq_printf(s, "(+%3u) ", x->skipped);
> + pc_print(s, time_units, x->events, x->time, x->mintime, x->maxtime);
> + if (x->bytes) {
> + seq_putc(s,' ');
> + pc_print(s, byte_units, x->events, x->bytes,
> + x->minbytes, x->maxbytes);
> + }
> + seq_putc(s, '\n');
> + return 0;
> +}
> +
> +static void *perf_start(struct seq_file *m, loff_t *pos)
> +{
> + return (*pos < NR_PC_ITEMS) ? (void *)(*pos +1) : NULL;
> +}
> +
> +static void *perf_next(struct seq_file *m, void *v, loff_t *pos)
> +{
> + ++*pos;
> + return perf_start(m, pos);
> +}
> +
> +static void perf_stop(struct seq_file *m, void *v)
> +{
> +}
> +
> +struct seq_operations perf_data_ops = {
> + .start = perf_start,
> + .next = perf_next,
> + .stop = perf_stop,
> + .show = perf_show,
> +};
> +
> +static int perf_data_open(struct inode *inode, struct file *file)
> +{
> + int res;
> +
> + res = seq_open(file, &perf_data_ops);
> + if (!res)
> + ((struct seq_file *)file->private_data)->private =
> + PDE(inode)->data;
> +
> + return res;
> +}
> +
> +static struct file_operations perf_data_fops = {
> + .open = perf_data_open,
> + .read = seq_read,
> + .llseek = seq_lseek,
> + .release = seq_release,
> +};
> +
> +static int perf_reset_write(struct file *file, const char __user *buffer,
> + unsigned long count, void *data)
> +{
> + perfcount_reset();
> + return count;
> +}
> +
> +static __init int init_perfcounter(void) {
> + int cpu;
> +
> + struct proc_dir_entry *proc_perf, *perf_reset, *perf_all;
> +
> + proc_perf = proc_mkdir("perf", NULL);
> + if (!proc_perf)
> + return -ENOMEM;
> +
> + perf_reset = create_proc_entry("reset", S_IWUGO, proc_perf);
> + perf_reset->write_proc = perf_reset_write;
> +
> + perf_all = create_proc_entry("all", S_IRUGO, proc_perf);
> + perf_all->proc_fops = &perf_data_fops;
> + perf_all->data = (void *)-1;
> +
> + for_each_possible_cpu(cpu) {
> + char name[20];
> + struct proc_dir_entry *p;
> +
> + sprintf(name, "%d", cpu);
> + p = create_proc_entry(name, S_IRUGO, proc_perf);
> +
> + p->proc_fops = &perf_data_fops;
> + p->data = (void *)(unsigned long)cpu;
> + }
> +
> + perfcount_reset();
> +
> +#if defined(CONFIG_NUMA) && defined(CONFIG_X86_64)
> + if (!unsynchronized_tsc())
> + unsynced_get_cycles = 0;
> +#endif
> + return 0;
> +}
> +
> +__initcall(init_perfcounter);
> +
> diff --git a/kernel/timer.c b/kernel/timer.c
> index 6ce1952..55d4619 100644
> --- a/kernel/timer.c
> +++ b/kernel/timer.c
> @@ -36,6 +36,7 @@
> #include <linux/delay.h>
> #include <linux/tick.h>
> #include <linux/kallsyms.h>
> +#include <linux/perf.h>
>
> #include <asm/uaccess.h>
> #include <asm/unistd.h>
> @@ -824,6 +825,7 @@ void update_process_times(int user_tick)
> {
> struct task_struct *p = current;
> int cpu = smp_processor_id();
> + INIT_PC(pc);
>
> /* Note: this timer irq context must be accounted for as well. */
> if (user_tick)
> @@ -835,6 +837,7 @@ void update_process_times(int user_tick)
> rcu_check_callbacks(cpu, user_tick);
> scheduler_tick();
> run_posix_cpu_timers(p);
> + pc_stop(&pc, PC_UPDATE_PROCESS_TIMES);
> }
>
> /*
> --
> 1.5.2.4
>
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
--
Mathieu Desnoyers
Computer Engineering Ph.D. Student, Ecole Polytechnique de Montreal
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/