Re: [PATCH v6 4/4] tracing: Histogram for delayed hrtimer offsets

From: Thomas Gleixner
Date: Fri Sep 09 2016 - 09:33:06 EST


On Thu, 8 Sep 2016, Binoy Jayan wrote:
> On 8 September 2016 at 12:40, Thomas Gleixner <tglx@xxxxxxxxxxxxx> wrote:
> >> +#ifdef CONFIG_DELAYED_TIMER_OFFSETS_HIST
> >> + ktime_t praecox;
> >> +#endif
> >
> > And of course documenting new struct members is optional, correct? I'm
> > really looking forward for the explanation of that variable name.
>
> It marks the start time when a process is scheduled to be woken up as the
> result of expiry of the hrtimer. Will be mentioning it in the comments.

That's wrong. It only contains the start time when the timer was not
expired at the point where it is started. Otherwise it's set to 0.

Random explanations are worse than no explanation at all.

> >> +#ifdef CONFIG_DELAYED_TIMER_OFFSETS_HIST
> >> +static inline void latency_hrtimer_timing_start(struct hrtimer *timer,
> >> + struct hrtimer_clock_base *new_base,
> >> + ktime_t tim)
> >> +{
> >> + if (unlikely(trace_latency_hrtimer_interrupt_enabled())) {
> >> + ktime_t now = new_base->get_time();
> >> +
> >> + if (ktime_to_ns(tim) < ktime_to_ns(now))
> >> + timer->praecox = now;
> >> + else
> >> + timer->praecox = ktime_set(0, 0);
> >
> > What's the whole point of this? You're adding an extra get_time() call into
> > that path. What for? Comments in the code are overrated, right?
>
> Will add comments here.

I rather prefer to get an explanation in this mail thread so it can be
discussed before you send out the next version.

> >> + latency = ktime_to_ns(ktime_sub(basenow,
> >> + ktime_to_ns(timer->praecox) ?
> >> + timer->praecox : hrtimer_get_expires(timer)));
> >> + task = timer->function == hrtimer_wakeup ?
> >> + container_of(timer, struct hrtimer_sleeper,
> >> + timer)->task : NULL;
> >
> > This is a complete horrible hack. You're tying the task evaluation into a
> > single instance of hrtimer users. What's the justification for this and why
> > do you need task at all?
>
> If I am understanding it not wrongly, I was trying to mark the time when
> and hrtimer is started or restarted and the time when the same expires.
> The expiry time is compared against the time now and the actual expiry.
> The task indicates the task woken up as a result of the timer expiry.

You are explaining what the code does and you are explaining it wrong. But
you don't answer my question at all.

> >
> >> + if (latency > 0)
> >> + trace_latency_hrtimer_interrupt((u64) latency, task);
> >
> > And how should latency become < 0 ever? hrtimer interrupt guarantees to
> > never expire timers prematurely.
>
> Not sure why, but I have seen some negative values here.

The you better investigate that matter instead of adding band aids to the
code.

> > Neither the changelog nor the code contain any information about how that
> > thing is to be used and what the actual value of the stored information
> > is.
> >
> > No way that this ad hoc statistics hackery which we carry in RT for a well
> > known reason is going to go upstream without proper justification and a
> > weel thought out and documented functionality.
> >
>
> As Carsten has mentioned in his patch, this latency alone is not useful enough
> without the process latency which occur due to the disabled interrupts/preemtion
> or because of a timer missing its deadline. Since the process latency histogram
> needed tracepoints in scheduler code which is discouraged, I haven't gotten
> around to do it yet. I've been trying to calculate latencies by making
> use of kprobes
> events and tracing_maps but I was finding it little tricky.

How is that related to my question?

If that thing has no value on its own, why are you trying to push it?

I don't care if you find it tricky. If you want this patch merged, then you
have to supply information

- What it does

- Why it is useful

- How it can be used

- What is the output and how can it be analyzed

- What are the limitations

Thanks,

tglx