From patchwork Mon Nov 21 11:55:36 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "\(Exiting\) Baolin Wang" X-Patchwork-Id: 83214 Delivered-To: patch@linaro.org Received: by 10.182.1.168 with SMTP id 8csp1484348obn; Mon, 21 Nov 2016 04:01:32 -0800 (PST) X-Received: by 10.13.250.3 with SMTP id k3mr12659978ywf.276.1479729692590; Mon, 21 Nov 2016 04:01:32 -0800 (PST) Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id y132si4646325ywd.406.2016.11.21.04.01.32; Mon, 21 Nov 2016 04:01:32 -0800 (PST) Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67; Authentication-Results: mx.google.com; dkim=pass header.i=@linaro.org; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE dis=NONE) header.from=linaro.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754058AbcKUMB3 (ORCPT + 26 others); Mon, 21 Nov 2016 07:01:29 -0500 Received: from mail-pf0-f178.google.com ([209.85.192.178]:35732 "EHLO mail-pf0-f178.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753457AbcKUMB1 (ORCPT ); Mon, 21 Nov 2016 07:01:27 -0500 Received: by mail-pf0-f178.google.com with SMTP id i88so64224105pfk.2 for ; Mon, 21 Nov 2016 04:01:27 -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; bh=bMUHVvsN5mnXJVCnpZWz3c24OR00rRvEfl19FgUgsoQ=; b=ME1Voz/Rz5mthh8jGn05iNdB6sCW4r13ZSj5OLLbfEVYwIz16OcUPsWlqsKCEbVj0F R2B6JHDYyodFvJH/iO5O3S4ZqdbTHVQUccYBGAqveUUXd16a5e3hW8KIMGHUriTPgqjE EuY4LAUNNLU4KUYUIvJhslOlAQfDCaXsDEVtE= 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; bh=bMUHVvsN5mnXJVCnpZWz3c24OR00rRvEfl19FgUgsoQ=; b=enUuwRoLlLJTCWIYP239u9qC+YFV5YNKyts3QpbzTlTaTd569tohb5Qs+oLqkcXtdh lnY232G7B7+CsyyFm+giMcTQs1VMeWqp2karWEt85tso9tt8Cf7wzPCvzGr1WLTVmRcN tMdv9OtdpI7DTBexDTdKjSPSwhD3NPhG9w9obYjZcJDhjkR6WNpTUwuaybzkD2JI6xf+ bZpPjrSfcjkLwpoX+P5B99xfEMfr8h9KGh756SKGrQRSCHgIcFW1tzv1FCSml2DzwgFN dzfHO8YF645JBPcPEX+U8RMcJ67chhRGwgcc2KhSb7Eu7QITFoQc0b8Tp0ZO9HejVxU5 XjPw== X-Gm-Message-State: AKaTC03QqM7G3GzLzZaYgVTYAmIdeWw5XGqcM2qfR/4FAXfBhWbdF8lreOb2hCjO6z/5r3zT X-Received: by 10.98.202.211 with SMTP id y80mr17545512pfk.154.1479729365016; Mon, 21 Nov 2016 03:56:05 -0800 (PST) Received: from baolinwangubtpc.spreadtrum.com ([175.111.195.49]) by smtp.gmail.com with ESMTPSA id p26sm19163898pgn.11.2016.11.21.03.56.02 (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Mon, 21 Nov 2016 03:56:04 -0800 (PST) From: Baolin Wang To: rostedt@goodmis.org, mingo@redhat.com, john.stultz@linaro.org, tglx@linutronix.de Cc: baolin.wang@linaro.org, broonie@kernel.org, linux-kernel@vger.kernel.org Subject: [PATCH v5] time: alarmtimer: Add the tracepoints for alarmtimer Date: Mon, 21 Nov 2016 19:55:36 +0800 Message-Id: <50ab9eeb41c6d409b48696e43b6d257bfb38b290.1479720458.git.baolin.wang@linaro.org> X-Mailer: git-send-email 1.7.9.5 Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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. Signed-off-by: Baolin Wang Acked-by: Steven Rostedt --- Changes since v4: - Initialize 'type' to -1 and rename it in alarmtimer_suspend(). - Fix typo in subject line. --- Changes since v3: - Remove the "ALARM_" prefix in the string. - Add the ACK by Steven Rostedt. Changes since v2: - Save time as s64 type. - Remove 'process_name' parameter and add 'now' parameter. - Rename the trace event name. - Remove restart trace event. - Other optimization. --- 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 -- 1.7.9.5 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..4590f23 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, 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); + /* 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);