Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer

[Baolin Wang]

On 29 November 2016 at 20:06, Thomas Gleixner <tglx@xxxxxxxxxxxxx> wrote:
> On Mon, 28 Nov 2016, John Stultz wrote:
>
>> From: Baolin Wang <baolin.wang@xxxxxxxxxx>
>>
>> For system debugging, we sometimes want to know who sets one
>> alarm timer, the time of the timer, when the timer started and
>> fired and so on. Thus adding tracepoints can help us trace the
>> alarmtimer information.
>>
>> For example, when we debug the system supend/resume, if the
>> system is always resumed by RTC alarm, we can find out which
>> process set the alarm timer to resume system by below trace log:
>>
>> ......
>>
>> Binder:3292_2-3304  [000] d..2 149.981123: alarmtimer_cancel:
>> alarmtimer:ffffffc1319a7800 type:REALTIME
>> expires:1325463120000000000 now:1325376810370370245
>>
>> Binder:3292_2-3304  [000] d..2   149.981136: alarmtimer_start:
>> alarmtimer:ffffffc1319a7800 type:REALTIME
>> expires:1325376840000000000 now:1325376810370384591
>>
>> Binder:3292_9-3953  [000] d..2   150.212991: alarmtimer_cancel:
>> alarmtimer:ffffffc1319a5a00 type:BOOTTIME
>> expires:179552000000 now:150154008122
>>
>> Binder:3292_9-3953  [000] d..2   150.213006: alarmtimer_start:
>> alarmtimer:ffffffc1319a5a00 type:BOOTTIME
>> expires:179551000000 now:150154025622
>>
>> ......
>>
>> system_server-3000  [002] ...1  162.701940: alarmtimer_suspend:
>> alarmtimer type:REALTIME expires:1325376839802714584
>> ......
>>
>> >From the trace log, we can find out the 'Binder:3292_2' process
>> set one alarm timer which resumes the system.
>
> To be honest. I have a hard time to figure out that Binder:3292_2 armed the
> timer.
>
>         suspend: expires:1325376839802714584
> Binder  start:   expires:1325376840000000000
>
> That does not make any sense at all. And this is a result of how that
> suspend tracepoint got glued into alarmtimer_suspend():
>
>> @@ -222,7 +226,7 @@ static int alarmtimer_suspend(struct device *dev)
>>       ktime_t min, now;
>>       unsigned long flags;
>>       struct rtc_device *rtc;
>> -     int i;
>> +     int i, min_type = -1;
>>       int ret;
>>
>>       spin_lock_irqsave(&freezer_delta_lock, flags);
>> @@ -247,8 +251,10 @@ static int alarmtimer_suspend(struct device *dev)
>>               if (!next)
>>                       continue;
>>               delta = ktime_sub(next->expires, base->gettime());
>> -             if (!min.tv64 || (delta.tv64 < min.tv64))
>> +             if (!min.tv64 || (delta.tv64 < min.tv64)) {
>>                       min = delta;
>> +                     min_type = i;
>> +             }
>>       }
>>       if (min.tv64 == 0)
>>               return 0;
>> @@ -264,6 +270,8 @@ static int alarmtimer_suspend(struct device *dev)
>>       now = rtc_tm_to_ktime(tm);
>>       now = ktime_add(now, min);
>>
>> +     trace_alarmtimer_suspend(now, min_type);
>
> So first we calculate the relative expiry time from now, add it to the RTC
> and then print out the sum. That's utter crap especially if the first
> expiring timer is based on CLOCK_BOOTTIME. Even with CLOCK_REALTIME you do
> not get matching expiry time as you can see above.
>
> Now looking at the other possibility to arm the resume time: freezer_delta.
> That's even more undebuggable because the freezer time is stored as
> relative timeout without any type information. How is one supposed to map
> that back to an alarm timer start?
>
> Find below a revamped version (untested) of this including a proper written
> changelog.
>
> Thanks,
>
>         tglx
>
> 8<--------------
> Subject: time/alarmtimer: Add tracepoints for alarmtimer
> From: John Stultz <john.stultz@xxxxxxxxxx>
> Date: Mon, 28 Nov 2016 14:35:21 -0800
>
> From: Baolin Wang <baolin.wang@xxxxxxxxxx>
>
> Alarm timers are one of the mechanisms to wake up a system from suspend,
> but there exist no tracepoints to analyse which process/thread armed an
> alarmtimer.
>
> Add tracepoints for start/cancel/expire of individual alarm timers and one
> for tracing the suspend time decision when to resume the system.
>
> The following trace excerpt illustrates the new mechanism:
>
> Binder:3292_2-3304  [000] d..2 149.981123: alarmtimer_cancel:
> alarmtimer:ffffffc1319a7800 type:REALTIME
> expires:1325463120000000000 now:1325376810370370245
>
> Binder:3292_2-3304  [000] d..2   149.981136: alarmtimer_start:
> alarmtimer:ffffffc1319a7800 type:REALTIME
> expires:1325376840000000000 now:1325376810370384591
>
> Binder:3292_9-3953  [000] d..2   150.212991: alarmtimer_cancel:
> alarmtimer:ffffffc1319a5a00 type:BOOTTIME
> expires:179552000000 now:150154008122
>
> Binder:3292_9-3953  [000] d..2   150.213006: alarmtimer_start:
> alarmtimer:ffffffc1319a5a00 type:BOOTTIME
> expires:179551000000 now:150154025622
>
> system_server-3000  [002] ...1  162.701940: alarmtimer_suspend:
> alarmtimer type:REALTIME expires:1325376840000000000
>
> The wakeup time which is selected at suspend time allows to map it back to
> the task arming the timer: Binder:3292_2.
>
> [ tglx: Store real alarm timer expiry time instead of some useless RTC
>         relative information, add proper type information for wakeups which
>         are handled via the clock_nanosleep/freezer and massage the
>         changelog. ]
>
> Signed-off-by: Baolin Wang <baolin.wang@xxxxxxxxxx>
> Signed-off-by: John Stultz <john.stultz@xxxxxxxxxx>
> Acked-by: Steven Rostedt <rostedt@xxxxxxxxxxx>
> Cc: Prarit Bhargava <prarit@xxxxxxxxxx>
> Cc: Richard Cochran <richardcochran@xxxxxxxxx>
> Link: http://lkml.kernel.org/r/1480372524-15181-5-git-send-email-john.stultz@xxxxxxxxxx
> Signed-off-by: Thomas Gleixner <tglx@xxxxxxxxxxxxx>

Tested-by: Baolin Wang <baolin.wang@xxxxxxxxxx>

-- 
Baolin.wang
Best Regards