Re: [PATCH 4/4] perf/timer: 'perf timer' core code

Thomas Gleixner
2009-12-15T17:45:11Z

On Tue, 15 Dec 2009, Xiao Guangrong wrote:

> It's the core code of 'perf timer', we can use it to analyse timer's
> behavior:
> # perf timer record
> # perf timer lat --print-lat --print-handle
> -------------------------------------------------------------------------------------------------------
> | Timer | TYPE | Avg-latency | Max-latency | Max-latency-at-TS |Max-lat-at-Task |
> |0xf7ad1f5c |hrtimer |996068.500 ns|1607650 ns|10270128658526 |init |
> |0xf7903f04 |timer |0.625 HZ|2 HZ|10270344082394 |swapper |
> |0xf787a05c |hrtimer |200239.500 ns|359929 ns|10269316024808 |main |
> |main :[ PROF]|itimer |0.000 HZ|0 HZ|10237021270557 |main |
> |main :[VIRTUAL]|itimer |0.000 HZ|0 HZ|10257314773501 |main |
>
> ......
>
> -------------------------------------------------------------------------------------------------------
> | Timer | TYPE | Avg-handle (ms)|Max-handle(ms)| Max-handle-at-TS(s)|Max-lat-at-func |
> |0xf7ad1f5c |hrtimer |0.025 |0.025 |10270.129 |0xc016b5b0 |
> |0xf7903f04 |timer |0.009 |0.011 |10260.342 |0xc0159240 |
> |0xf787a05c |hrtimer |0.031 |0.062 |10267.018 |0xc014cc40 |

The output is confusing in several aspects:

1) Different time units:

Please use consistent time units for everything. micro seconds
are fine and we definitely do not care about nanosecond
fractions.

2) Timer description:

Why do we have hex addresses and process names intermingled ? Why
don't we print the process/thread name which owns the timer
always ? [PROF/VIRTUAL] is not a property of the Timer, it
belongs into type.

3) Max-lat-at-Task:

What does this field tell ?

4) *handle:

That should be a more descriptive name, e.g. function runtime

5) Max-lat-at-func:

Is this the callback function which ran the longest time ? Why
is it named latency ? Why is it not decoded into a symbol ?

Btw, fitting the output into 80chars allows to use the tool on a non
graphical terminal as well.

Also there are other metrics of timers which are interesting and
should be retrieved by such a tool:

number of activated timers
number of canceled timers
number of expired timers

in the form of simple statistics.

The canceled timers are interesting also in a list, so we can see
which timers are canceled after which time and how long before the
expiry.

> +#ifdef TDEBUG
> +static char const *timer_state_string[] = {
> + "TIMER_INIT",
> + "TIMER_STARE",

If I _stare_ longer, I might understand it :)

> +#define SORT_KEY \
> + "timer, type, avg-timer-latency, max-timer-latency," \
> + " avg-handle-time, max-handle-time"

The code has at least two places where these strings are used. They
should be synced.

> +static char const *input_name = "perf.data";
> +static char default_sort_order[] = SORT_KEY;
> +
> +static char *sort_order = default_sort_order;
> +static int profile_cpu = -1;
> +static int print_lat;
> +static int print_handle;
> +static int bug_nr;
> +static struct perf_session *timer_session;
> +
> +static const struct option timer_options[] = {
> + OPT_STRING('i', "input", &input_name, "file",
> + "input file name"),
> + OPT_BOOLEAN('v', "verbose", &verbose,
> + "be more verbose (show symbol address, etc)"),
> + OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
> + "dump raw trace in ASCII"),
> + OPT_END()
> +};
> +
> +static const char * const timer_usage[] = {
> + "perf timer [<options>] {record|latency}",
> + NULL
> +};

Your example above uses "perf timer lat". What's correct ?

> +static const struct option latency_options[] = {
> + OPT_STRING('s', "sort", &sort_order, "key[,key2...]",
> + "sort by key(s): "SORT_KEY),

Do we really need a sort order ? A single sort key should be
sufficient.

I'd prefer to have a selector instead which lets me filter timer
types. If I debug hrtimers then I have no interest in itimers or timer
list timers.

> +enum timer_type {
> + TIMER,
> + HRTIMER,
> + ITIMER,
> +};

Hmm. I don't think that's correct. You should split the itimer type
into the various subimplementations.

> +static char const *timer_type_string[] = {
> + "timer",
> + "hrtimer",
> + "itimer",
> +};

Ditto.

> +struct sort_dimension {
> + const char *name;
> + sort_fn_t cmp;
> + struct list_head list;
> +};
> +
> +#define CMP_FUNCTION(value) \

Please use something like "field". value confused me for a while, as I
expected a real value.

> +static int cmp_##value(struct timer_info *v1, struct timer_info *v2) \
> +{ \
> + if (v1->value < v2->value) \
> + return -1; \
> + if (v1->value > v2->value) \
> + return 1; \
> + return 0; \
> +}
> +
> +#define DECLARE_SORT_DIMENSION(sort_name, field) \

That should be DEFINE_... You are defining the function, not declaring
it.

> +CMP_FUNCTION(field) \
> +static struct sort_dimension sort_##field = { \
> + .name = sort_name, \
> + .cmp = cmp_##field, \
> +}
> +
> +DECLARE_SORT_DIMENSION("timer", timer);
> +DECLARE_SORT_DIMENSION("type", type);
> +DECLARE_SORT_DIMENSION("avg-timer-latency", timer_avg_lat);
> +DECLARE_SORT_DIMENSION("max-timer-latency", timer_max_lat);
> +DECLARE_SORT_DIMENSION("avg-handle-time", handler_avg_time);
> +DECLARE_SORT_DIMENSION("max-handle-time", handler_max_time);
> +
> +static struct sort_dimension *available_sorts[] = {
> + &sort_timer,
> + &sort_type,
> + &sort_timer_avg_lat,
> + &sort_timer_max_lat,
> + &sort_handler_avg_time,
> + &sort_handler_max_time,
> +};

This indirection horrible.

#define SORT(field,_name) \
{ .func = cmp_##field, \
.name = _name, }

static struct sort_key sorts[] = {
SORT(timer, "timer"),
....
};

> +#define NB_AVAILABLE_SORTS (int)(sizeof(available_sorts) / sizeof(struct sort_dimension *))

Please use NR_ as abbreviation for number. Also the size calculation
for arrays is:

ARRAY_SIZE(available_sorts)

> +static int sort_dimension__add(const char *tok, struct list_head *list)

No double underscores please.

> +{
> + int i;
> +
> + for (i = 0; i < NB_AVAILABLE_SORTS; i++) {
> + if (!strcmp(available_sorts[i]->name, tok)) {
> + list_add_tail(&available_sorts[i]->list, list);
> +
> + return 0;
> + }
> + }
> +
> + return -1;
> +}
> +
> +static LIST_HEAD(sort_list);
> +
> +static void setup_sorting(void)
> +{
> + char *tmp, *tok, *str = strdup(sort_order);

Please hand sort_order in as an argument.

> + for (tok = strtok_r(str, ", ", &tmp);
> + tok; tok = strtok_r(NULL, ", ", &tmp)) {
> + if (sort_dimension__add(tok, &sort_list) < 0) {
> + error("Unknown --sort key: `%s'", tok);
> + usage_with_options(latency_usage, latency_options);
> + }
> + }
> +
> + free(str);
> +
> + sort_dimension__add("timer", &default_cmp);
> + sort_dimension__add("itimer-type", &default_cmp);

That obviously does not match any of the sort types.

> +}
> +
> +static struct rb_root timer_root;
> +
> +static int timer_key_cmp(struct list_head *list, struct timer_info *l,
> + struct timer_info *r)
> +{
> + struct sort_dimension *sort;
> + int ret = 0;
> +
> + BUG_ON(list_empty(list));
> +
> + list_for_each_entry(sort, list, list) {
> + ret = sort->cmp(l, r);
> + if (ret)
> + return ret;
> + }
> +
> + return ret;
> +}
> +
> +static void timer_traversal(struct rb_root *root,
> + void (*fun)(struct timer_info *))
> +{
> + struct rb_node *next;
> +
> + next = rb_first(root);
> +
> + while (next) {
> + struct timer_info *timer;
> +
> + timer = rb_entry(next, struct timer_info, node);
> + fun(timer);
> + next = rb_next(next);
> + }
> +}
> +
> +static struct timer_info *
> +__timer_search(struct rb_root *root, struct timer_info *timer,
> + struct list_head *_sort_list)
> +{
> + struct rb_node *node = root->rb_node;
> +
> + while (node) {
> + struct timer_info *timer_info;
> + int cmp;
> +
> + timer_info = container_of(node, struct timer_info, node);
> +
> + cmp = timer_key_cmp(_sort_list, timer, timer_info);
> + if (cmp > 0)
> + node = node->rb_left;
> + else if (cmp < 0)
> + node = node->rb_right;
> + else
> + return timer_info;

This looks more than odd. You search for a timer in the list by
using the compare functions which are used for sorting ?

How should that work ?

> + }
> + return NULL;
> +}
> +
> +static struct timer_info *
> +timer_search(struct timer_info *timer)
> +{
> + return __timer_search(&timer_root, timer, &default_cmp);
> +}
> +
> +static void
> +__timer_insert(struct rb_root *root, struct timer_info *data,
> + struct list_head *_sort_list)
> +{
> + struct rb_node **new = &(root->rb_node), *parent = NULL;
> +
> + while (*new) {
> + struct timer_info *this;
> + int cmp;
> +
> + this = container_of(*new, struct timer_info, node);
> + parent = *new;
> +
> + cmp = timer_key_cmp(_sort_list, data, this);
> +
> + if (cmp > 0)
> + new = &((*new)->rb_left);
> + else
> + new = &((*new)->rb_right);
> + }
> +
> + rb_link_node(&data->node, parent, new);
> + rb_insert_color(&data->node, root);
> +}
> +
> +static void timer_insert(struct timer_info *timer_info)
> +{
> + dprintf("timer %p insert...\n", timer_info->timer);
> + __timer_insert(&timer_root, timer_info, &default_cmp);
> +}
> +
> +static struct timer_info
> +*__timer_find(void *timer, enum timer_type type, int itimer_type)

As I said before, that's wrong. Enumerate the itimer subtypes in the
timer types and you get rid of all that extra itimer_type business.

> +{
> + struct timer_info *find = NULL;
> + struct timer_info timer_info = {
> + .timer = timer,
> + .itimer_type = itimer_type,
> + };
> +
> + find = timer_search(&timer_info);
> + if (find && find->type != type) {
> +
> + dprintf("find timer[%p], but type[%s] is not we expect[%s],"
> + "set to initializtion state.\n", find->timer,
> + timer_type_string[find->type], timer_type_string[type]);
> +
> + find->type = type;
> + find->bug++;
> + find->state = TIMER_INIT;

Why does a timer_search fail ? And why is fixing up the type if it
is not matching a good idea ?

> + }
> +
> + dprintf("find timer[%p] %s\n", timer, find ? "success" : "fail");
> + return find;
> +}
> +
> +static struct timer_info *
> +timer_findnew(void *timer, enum timer_type type, int itimer_type)
> +{
> + struct timer_info *find;
> +
> + find = __timer_find(timer, type, itimer_type);
> + if (find)
> + return find;
> +
> + find = zalloc(sizeof(*find));
> + if (!find)
> + die("No memory");
> +
> + find->type = type;
> + find->timer = timer;
> + find->itimer_type = itimer_type;
> + timer_insert(find);
> +
> + return find;
> +}
> +
> +static struct rb_root timer_result;
> +
> +static void sort_result(void)
> +{
> + struct rb_node *node;
> +
> + for (;;) {
> + struct timer_info *data;
> + node = rb_first(&timer_root);
> + if (!node)
> + break;
> +
> + rb_erase(node, &timer_root);
> + data = rb_entry(node, struct timer_info, node);
> + data->timer_avg_lat = (double)data->timer_total_lat /
> + (double)data->expire_nr;
> + data->handler_avg_time = (double)data->handler_total_time /
> + (double)data->expire_nr;
> + if (data->expire_nr)
> + __timer_insert(&timer_result, data, &sort_list);
> + }
> +}
> +
> +static int timer_check_set_state(struct timer_info *timer_info,
> + enum timer_state new_state)
> +{
> + enum timer_state current_state = timer_info->state;
> + int ret = 1;
> +
> + /*
> + * if current state is TIMER_INIT, it means it's the first time we
> + * catched, no need check.

Check whatfor ?

> + */
> + if (current_state == TIMER_INIT) {
> + dprintf("timer[%p] initialize, set state to %s\n",
> + timer_info->timer, timer_state_string[new_state]);
> + ret = 0;
> + }
> +
> + timer_info->state = new_state;
> + return ret;
> +}
> +
> +#define FILL_RAM_FIELD_PTR(event, field, data) \
> + field = raw_field_ptr(event, #field, data)
> +#define FILLL_RAW_FIELD_VALUE(event, field, data) \
> + field = (typeof(field))raw_field_value(event, #field, data)

I can neither figure out what FILL_RAM_FIELD means nor why
FILLL_RAW_FIELD needs 3 L.

> +static void *get_timer(enum timer_type type, struct event *event, void *data)
> +{
> + if (type == HRTIMER) {
> + void *hrtimer = NULL;
> +
> + FILL_RAM_FIELD_PTR(event, hrtimer, data);
> + return hrtimer;

Shudder.

return raw_field_ptr(event, "hrtimer", data);

> + } else {
> + void *timer = NULL;
> +
> + FILL_RAM_FIELD_PTR(event, timer, data);
> + return timer;
> + }
> +}
> +
> +static void
> +timer_hrtimer_start(enum timer_type type, void *data, struct event *event)
> +{
> + void *timer, *function = NULL;
> + u64 expires;
> + struct timer_info *timer_info;
> +
> + timer = get_timer(type, event, data);
> +
> + FILL_RAM_FIELD_PTR(event, function, data);
> + FILLL_RAW_FIELD_VALUE(event, expires, data);
> +
> + dprintf("timer-start: Timer[%p], type:%s, function:%p, expires:%llu\n",
> + timer, timer_type_string[type], function, expires);
> +
> + timer_info = timer_findnew(timer, type, MAX_ITIMER_TYPE);
> + timer_check_set_state(timer_info, TIMER_START);
> + timer_info->function = function;
> + timer_info->timer_expire_ts = expires;
> +}
> +
> +static void
> +timer_hrtimer_expires_entry(enum timer_type type, void *data,
> + struct event *event, u64 timestamp,
> + struct thread *thread)
> +{
> + void *timer;
> + int ret;
> + u64 now;
> + s64 delta;
> + struct timer_info *timer_info;
> +
> + FILLL_RAW_FIELD_VALUE(event, now, data);
> + timer = get_timer(type, event, data);
> + timer_info = timer_findnew(timer, type, MAX_ITIMER_TYPE);
> + timer_info->handler_entry_ts = timestamp;
> + ret = timer_check_set_state(timer_info, TIMER_EXPIRE_ENTRY);
> +
> + dprintf("timer-expires-entry: Timer[%p], type:%s, now:%llu, ts:%llu\n",
> + timer, timer_type_string[type], now, timestamp);
> + if (ret == 0)
> + return;
> +
> + delta = (s64)(now - timer_info->timer_expire_ts);
> + if (delta < 0) {
> + timer_info->bug++;
> + dprintf("timer-expires-entry: Timer[%p], type:%s,"
> + " timer latency < 0, bug=%d.\n", timer,
> + timer_type_string[type], timer_info->bug);
> + return ;
> + }
> +
> + timer_info->expire_nr++;
> + timer_info->timer_last_lat = delta;
> + timer_info->timer_total_lat += delta;
> + if (timer_info->timer_max_lat <= (u64)delta) {

Why can't we just make timer_max_lat s64 so we get rid of those
silly typecasts ?

> + timer_info->timer_max_lat = delta;
> + timer_info->timer_max_lat_at_ts = timestamp;
> + timer_info->timer_max_lat_at_thread = thread;

What does us the information in which thread context the latency
happend show ? Actually nothing. All it tells us that thread X was
on the CPU at that point. That's useless.

> +static void
> +itimer_state_handler(void *data, struct event *event, int this_cpu __used,
> + u64 timestamp __used, struct thread *thread)
> +{
> + u64 value_sec, value_usec, expires;
> + struct timer_info *timer_info;
> + void *timer = NULL;
> + int which;
> +
> + FILLL_RAW_FIELD_VALUE(event, value_sec, data);
> + FILLL_RAW_FIELD_VALUE(event, value_usec, data);
> + FILLL_RAW_FIELD_VALUE(event, expires, data);
> + FILLL_RAW_FIELD_VALUE(event, which, data);
> + FILL_RAM_FIELD_PTR(event, timer, data);

This is complete obfuscated, while

value_sec = get_value(data, event, "value_sec");

is obvious.

> + timer_info = timer_findnew(thread, ITIMER, which);
> +
> + /* itimer canceled, we skip this event */
> + if (!value_sec && !value_usec)
> + return ;

You throw away valuable information here about canceled timers.

> + dprintf("timer-start: Timer[%p], type:%s, task:%s, expires:%llu",
> + timer_info->timer, "itimer", thread->comm, expires);
> +
> + /* itimer started */
> + timer_info->timer_expire_ts = expires;
> + timer_check_set_state(timer_info, TIMER_START);
> + if (which == ITIMER_REAL) {
> + timer = timer_findnew(timer, HRTIMER, MAX_ITIMER_TYPE);
> + timer_info->itimer_hrtimer = timer;
> + dprintf(" hrtimer:%p\n", timer);
> + } else {
> + dprintf("\n");
> + }
> +}
> +
> +static void
> +itimer_expire_handler(void *data, struct event *event, int this_cpu __used,
> + u64 timestamp, struct thread *thread)
> +{
> + int which;
> + u64 now;
> + pid_t pid;
> + struct thread *itimer_thread;
> + struct timer_info *timer_info;
> + s64 delta = 0;

No need to initialize that.

> + int ret;

Please group identical types

int ret, which;

> +struct event_handler_unit {
> + const char *event_name;
> + void (*handler) (void *data, struct event *event, int this_cpu,
> + u64 timestamp, struct thread *thread);
> +} timer_handler[] = {
> + /* timer */
> + { "timer_start", timer_start_handler },
> + { "timer_expire_entry", timer_expire_entry_handler },
> + { "timer_expire_exit", timer_expire_exit_handler },
> +
> + /* hrtimer */
> + { "hrtimer_start", hrtimer_start_handler },
> + { "hrtimer_expire_entry", hrtimer_expire_entry_handler },
> + { "hrtimer_expire_exit", hrtimer_expire_exit_handler},
> +
> + /* itimer */
> + { "itimer_state", itimer_state_handler },
> + { "itimer_expire", itimer_expire_handler },
> +};
> +
> +static void
> +process_raw_event(event_t *raw_event __used, struct perf_session *session __used,
> + void *data, int cpu, u64 timestamp, struct thread *thread)
> +{
> + struct event *event;
> + int type;
> + int i;
> + int handler_item = ARRAY_SIZE(timer_handler);

See above.

> + type = trace_parse_common_type(data);
> + event = trace_find_event(type);
> +
> + for (i = 0; i < handler_item; i++)
> + if (!strcmp(timer_handler[i].event_name, event->name))
> + timer_handler[i].handler(data, event, cpu, timestamp, thread);
> +}
> +
> +static int read_events(void)
> +{
> + int err;

New line between variables and code.

> + timer_session = perf_session__new(input_name, O_RDONLY, 0, NULL);
> +
> + if (timer_session == NULL)

if (!timer_session)

> + return -ENOMEM;
> +
> + err = perf_session__process_events(timer_session, &event_ops);
> + perf_session__delete(timer_session);
> + return err;
> +}
> +

Thanks,

tglx