From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757773AbcLACeY (ORCPT ); Wed, 30 Nov 2016 21:34:24 -0500 Received: from mail-yb0-f170.google.com ([209.85.213.170]:35898 "EHLO mail-yb0-f170.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754816AbcLACeW (ORCPT ); Wed, 30 Nov 2016 21:34:22 -0500 MIME-Version: 1.0 In-Reply-To: References: <1480372524-15181-1-git-send-email-john.stultz@linaro.org> <1480372524-15181-5-git-send-email-john.stultz@linaro.org> From: Baolin Wang Date: Thu, 1 Dec 2016 10:34:21 +0800 Message-ID: Subject: Re: [PATCH 4/7] time: alarmtimer: Add the tracepoints for alarmtimer To: Thomas Gleixner Cc: John Stultz , lkml , Richard Cochran , Prarit Bhargava , Ingo Molnar , Steven Rostedt Content-Type: text/plain; charset=UTF-8 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 29 November 2016 at 20:06, Thomas Gleixner wrote: > On Mon, 28 Nov 2016, John Stultz wrote: > >> From: Baolin Wang >> >> 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 > Date: Mon, 28 Nov 2016 14:35:21 -0800 > > From: Baolin Wang > > 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 > Signed-off-by: John Stultz > Acked-by: Steven Rostedt > Cc: Prarit Bhargava > Cc: Richard Cochran > Link: http://lkml.kernel.org/r/1480372524-15181-5-git-send-email-john.stultz@linaro.org > Signed-off-by: Thomas Gleixner Tested-by: Baolin Wang -- Baolin.wang Best Regards