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

Xiao Guangrong
2009-12-16T05:58:22Z

Hi Thomas,

Sorry for many mistakes(typos and bad ideas) in this patch, i'll cook it
more and be careful later. Thanks very much.

Thomas Gleixner wrote:
> 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.

OK, i'll change ns to ms, and for timer, the unit is HZ, do we have the
way to read kernel HZ in userspace? if not, i'll export HZ by proc/debugfs
or other way

>
> 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.

Um, but not every timer has it's owner task, for example, if we start
a timer in interrupt handle function, this timer in not owns any tasks.
And itimer is started by userspace task so we can get it's owner, that
why i print hex address for timer/hrtimer, and print task name for itimer.

>
> 3) Max-lat-at-Task:
>
> What does this field tell ?

It means that which task in running when the maximum latency occurs.
but, as you noticed, this is useless, i'll remove it in next version
patch.

>
> 4) *handle:
>
> That should be a more descriptive name, e.g. function runtime
>

OK, will fix

> 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 ?

it's my typo, i'll export it using right/better way

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

OK, will fix

> 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.
>

OK. will support it

> 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.
>

Um, i'll cook timer tracepoints to get the time when timer canceled,
and support this function.

>> +static const char * const timer_usage[] = {
>> + "perf timer [<options>] {record|latency}",
>> + NULL
>> +};
>
> Your example above uses "perf timer lat". What's correct ?
>

Actually, we only compare frontal 3 characters:
strncmp(argv[0], "lat", 3)

And 'perf sched' and other commands also use this way.

>> +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 think it's necessary.

for example, if we interest in timer's max latency, then we can
use '-s max-timer-latency' to sort it.

And, if it has many timer with the some max latency, then we can
use '-s max-timer-latency,avg-timer-latency' to sort

> 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.
>

OK, will support this filter

>> +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.
>

Sorry for my stupid question:
'sort_order' is a global variable and setup_sorting() only called
one time, why need hand sort_order in as an argument?

>> +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 ?
>

We put/get timer in a rb-tree base on the specify order, for example:
we default use this order:

sort_dimension__add("timer", &default_cmp);
sort_dimension__add("itimer-type", &default_cmp);

if timer_info->timer is bigger, we put it to left child, littler to right
child, if the timer_info->timer is the same, then we compare
timer_info->itimer_type.

>> +{
>> + 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 ?
>

We search timer base on timer_info->timer and timer_info->itimer_type(not timer_info->type),
if we find the timer's type is changed(for example, the timer is "ITIMER" before, and change
to "HRTIMER" later), is should a bug. this case is hardly to happen but should catch it.

>> +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);
>

Yeah, it's a clear way.

>> +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.
>

Sorry, i cannot get this. As i understand:

#define FILL_RAW_FIELD_VALUE(event, field, data) \
field = (typeof(field))raw_field_value(event, #field, data)

After FILL_RAW_FIELD_VALUE(event, value_sec, data) expanded, it's:
value_sec = raw_field_value(event, "value_sec", data)

Why it's wrong? :-(

>> + 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.
>

We are not catch *_cancel event in this patch, i'll catch it to support
'number of canceled timers' in the next version.

Thanks,
Xiao