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

[Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>]

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