From patchwork Sat Nov 19 04:50:11 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: John Stultz X-Patchwork-Id: 83053 Delivered-To: patches@linaro.org Received: by 10.140.97.165 with SMTP id m34csp441375qge; Fri, 18 Nov 2016 20:50:24 -0800 (PST) X-Received: by 10.98.153.20 with SMTP id d20mr4245319pfe.44.1479531024253; Fri, 18 Nov 2016 20:50:24 -0800 (PST) Return-Path: Received: from mail-pg0-x22c.google.com (mail-pg0-x22c.google.com. [2607:f8b0:400e:c05::22c]) by mx.google.com with ESMTPS id o9si6510028pgc.285.2016.11.18.20.50.24 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Fri, 18 Nov 2016 20:50:24 -0800 (PST) Received-SPF: pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c05::22c as permitted sender) client-ip=2607:f8b0:400e:c05::22c; Authentication-Results: mx.google.com; dkim=pass header.i=@linaro.org; spf=pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c05::22c as permitted sender) smtp.mailfrom=john.stultz@linaro.org; dmarc=pass (p=NONE dis=NONE) header.from=linaro.org Received: by mail-pg0-x22c.google.com with SMTP id p66so109733557pga.2 for ; Fri, 18 Nov 2016 20:50:24 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro.org; s=google; h=from:to:cc:subject:date:message-id:in-reply-to:references; bh=NcAGDxF+di2vbsml0AmLI/Z7MmBlKs5Tm+WzTKp4liw=; b=NkuoqlVEtrOm1HboymW6S2jxmx9K6SDYiM/kuNDtA4j0F4IGIqE+ic0H2nzGah3is/ gAAfuIl/0J/+W5MguaSv4Rw6eLOOA4fFgPbB0cJal2yV81+43mFKo4WADKpZpSGrxtUq DRwtTFyyhjRLtHUJNdBBpGooqM02OMX7YHatA= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references; bh=NcAGDxF+di2vbsml0AmLI/Z7MmBlKs5Tm+WzTKp4liw=; b=MS+aRYmyQxTHNdsaNVM41I5LDEzlm/t7JpJp4k4S1CATM1WXXZFpggvoQLwq7cEwIm I/HyiWgY8TW+C5DZbXmHsLDgT6A7LEmG0ap684z7u1b135RDs5xxKF5v6yRjCtpfdgK1 mKch4o01/VO2mwFs6+5Ro/KzKoZXm+Ab8peqXoLtgPOAghFtznDaHLY3CVcu4+zLGuC+ dN4lDaoNMv6XbQFmziZsDFZ1pYGXPUEx/LipSStJpgLnNpTImVVJu0MWItcH/YWr9FH/ D3ZRmkLD9nWBJ2/CzWE3fKKQo/2C1iUoA55Z6NhsFPnBzNi7sEOvAihp8OrByBz8l78+ QTSQ== X-Gm-Message-State: AKaTC03g7E0pj0EDk2ta82y+ctZR13OobD/NlN0c75gtr9kAbpQdeUatd8YNk3rQVYftRdmWXsU= X-Received: by 10.98.10.198 with SMTP id 67mr4147701pfk.157.1479531023814; Fri, 18 Nov 2016 20:50:23 -0800 (PST) Return-Path: Received: from localhost.localdomain ([2601:1c2:1002:83f0:4e72:b9ff:fe99:466a]) by smtp.gmail.com with ESMTPSA id w17sm3292973pgm.18.2016.11.18.20.50.22 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Fri, 18 Nov 2016 20:50:23 -0800 (PST) From: John Stultz To: lkml Cc: Baolin Wang , Thomas Gleixner , Richard Cochran , Ingo Molnar , Steven Rostedt , John Stultz Subject: [PATCH 1/4] time: alarmtimer: Add the trcepoints for alarmtimer Date: Fri, 18 Nov 2016 20:50:11 -0800 Message-Id: <1479531014-25264-2-git-send-email-john.stultz@linaro.org> X-Mailer: git-send-email 2.7.4 In-Reply-To: <1479531014-25264-1-git-send-email-john.stultz@linaro.org> References: <1479531014-25264-1-git-send-email-john.stultz@linaro.org> 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. Cc: Thomas Gleixner Cc: Richard Cochran Cc: Ingo Molnar Cc: Steven Rostedt Acked-by: Steven Rostedt Signed-off-by: Baolin Wang Signed-off-by: John Stultz --- include/trace/events/alarmtimer.h | 92 +++++++++++++++++++++++++++++++++++++++ kernel/time/alarmtimer.c | 16 ++++++- 2 files changed, 106 insertions(+), 2 deletions(-) create mode 100644 include/trace/events/alarmtimer.h -- 2.7.4 diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h new file mode 100644 index 0000000..61ea556 --- /dev/null +++ b/include/trace/events/alarmtimer.h @@ -0,0 +1,92 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM alarmtimer + +#if !defined(_TRACE_ALARMTIMER_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_ALARMTIMER_H + +#include +#include +#include + +TRACE_DEFINE_ENUM(ALARM_REALTIME); +TRACE_DEFINE_ENUM(ALARM_BOOTTIME); + +#define show_alarm_type(type) __print_flags(type, " | ", \ + { 1 << ALARM_REALTIME, "REALTIME" }, \ + { 1 << ALARM_BOOTTIME, "BOOTTIME" }) + +TRACE_EVENT(alarmtimer_suspend, + + TP_PROTO(ktime_t expires, int flag), + + TP_ARGS(expires, flag), + + TP_STRUCT__entry( + __field(s64, expires) + __field(unsigned char, alarm_type) + ), + + TP_fast_assign( + __entry->expires = expires.tv64; + __entry->alarm_type = flag; + ), + + TP_printk("alarmtimer type:%s expires:%llu", + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires + ) +); + +DECLARE_EVENT_CLASS(alarm_class, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now), + + TP_STRUCT__entry( + __field(void *, alarm) + __field(unsigned char, alarm_type) + __field(s64, expires) + __field(s64, now) + ), + + TP_fast_assign( + __entry->alarm = alarm; + __entry->alarm_type = alarm->type; + __entry->expires = alarm->node.expires.tv64; + __entry->now = now.tv64; + ), + + TP_printk("alarmtimer:%p type:%s expires:%llu now:%llu", + __entry->alarm, + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires, + __entry->now + ) +); + +DEFINE_EVENT(alarm_class, alarmtimer_fired, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_start, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +DEFINE_EVENT(alarm_class, alarmtimer_cancel, + + TP_PROTO(struct alarm *alarm, ktime_t now), + + TP_ARGS(alarm, now) +); + +#endif /* _TRACE_ALARMTIMER_H */ + +/* This part must be outside protection */ +#include diff --git a/kernel/time/alarmtimer.c b/kernel/time/alarmtimer.c index 12dd190..8084e0c 100644 --- a/kernel/time/alarmtimer.c +++ b/kernel/time/alarmtimer.c @@ -26,6 +26,9 @@ #include #include +#define CREATE_TRACE_POINTS +#include + /** * struct alarm_base - Alarm timer bases * @lock: Lock for syncrhonized access to the base @@ -194,6 +197,7 @@ static enum hrtimer_restart alarmtimer_fired(struct hrtimer *timer) } spin_unlock_irqrestore(&base->lock, flags); + trace_alarmtimer_fired(alarm, base->gettime()); return ret; } @@ -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, type = 0; 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; + 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, type); + /* Set alarm, if in the past reject suspend briefly to handle */ ret = rtc_timer_start(rtc, &rtctimer, now, ktime_set(0, 0)); if (ret < 0) @@ -342,6 +350,8 @@ void alarm_start(struct alarm *alarm, ktime_t start) alarmtimer_enqueue(base, alarm); hrtimer_start(&alarm->timer, alarm->node.expires, HRTIMER_MODE_ABS); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_start(alarm, base->gettime()); } EXPORT_SYMBOL_GPL(alarm_start); @@ -390,6 +400,8 @@ int alarm_try_to_cancel(struct alarm *alarm) if (ret >= 0) alarmtimer_dequeue(base, alarm); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_cancel(alarm, base->gettime()); return ret; } EXPORT_SYMBOL_GPL(alarm_try_to_cancel);