From patchwork Tue Oct 11 10:48:16 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: 77473 Delivered-To: patch@linaro.org Received: by 10.140.97.247 with SMTP id m110csp292614qge; Tue, 11 Oct 2016 03:56:49 -0700 (PDT) X-Received: by 10.107.11.98 with SMTP id v95mr5050186ioi.145.1476183408916; Tue, 11 Oct 2016 03:56:48 -0700 (PDT) Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id m81si3552157pfi.25.2016.10.11.03.56.48; Tue, 11 Oct 2016 03:56:48 -0700 (PDT) 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 S1752854AbcJKK4p (ORCPT + 27 others); Tue, 11 Oct 2016 06:56:45 -0400 Received: from mail-pa0-f50.google.com ([209.85.220.50]:33284 "EHLO mail-pa0-f50.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751788AbcJKK4o (ORCPT ); Tue, 11 Oct 2016 06:56:44 -0400 Received: by mail-pa0-f50.google.com with SMTP id vu5so13258718pab.0 for ; Tue, 11 Oct 2016 03:56:43 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro.org; s=google; h=from:to:cc:subject:date:message-id; bh=v3QPczMRiP6G7VDa6jI9itlM9Dp5uMXxlvtB6ptpuEI=; b=al+wVO1EQQZJCWNmsg6Qukr9fTCv3MpNLA2aBIW97Yractf5YngJXJuu4q1XYoP//C xOKUcwPUR8K3ugTAJS9tbBBdO7iMLa8F3wE6BLF+zzEsn22Eb5Du0rwseaOxBBA6qdvU iDwyLbFgCqxoXMbRV/vLbazM6iTX9Fjat4QhQ= 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=v3QPczMRiP6G7VDa6jI9itlM9Dp5uMXxlvtB6ptpuEI=; b=A+oO40TCW4U9UnHhCKUOgi1c6MENtdHVbYPq3rNCNb8mgneiV6qc9cy2sG6vLdgNrx xKd9LHoEu9MJzwmCI9DOir13g/2WD/cb+RmMAd5WBj+BYHJVh18KJMu9+9VT4Anqs2lR nrrIPTJHaRzIYe4eg+hKb95k07jeLmnoP06AonKo7sBiux6iL0zlDifWLbH0oco5B3fI TvxqRJmCr0HlGwq1OQZIcbrjb6ggUZsnMYccdCRAJEQ2QHo7LPF9dC5sPkItTHwFSf1T vBqaeWrkJi4In8fPr6CfcNyR5DOE46QGw7GuBA8XpW8myGstmnALIbJcd8TGrBms16So +K5Q== X-Gm-Message-State: AA6/9Rns6P6/GkjUwyKgFD5dUSoglRHWecD3M+edUgV1zUpNhXB+a6V4wbKBNVV5xzoB4pRe X-Received: by 10.66.156.229 with SMTP id wh5mr5819673pab.137.1476182931553; Tue, 11 Oct 2016 03:48:51 -0700 (PDT) Received: from baolinwangubtpc.spreadtrum.com ([175.111.195.49]) by smtp.gmail.com with ESMTPSA id fl4sm3616625pad.39.2016.10.11.03.48.49 (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 11 Oct 2016 03:48:51 -0700 (PDT) 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 v3] time: alarmtimer: Add the trcepoints for alarmtimer Date: Tue, 11 Oct 2016 18:48:16 +0800 Message-Id: <98ebf1ca60f0af8a4e56b67bedd197e0b4e85c0a.1476182683.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:ALARM_REALTIME expires:1325463120000000000 now:1325376810370370245 Binder:3292_2-3304 [000] d..2 149.981136: alarmtimer_start: alarmtimer:ffffffc1319a7800 type:ALARM_REALTIME expires:1325376840000000000 now:1325376810370384591 Binder:3292_9-3953 [000] d..2 150.212991: alarmtimer_cancel: alarmtimer:ffffffc1319a5a00 type:ALARM_BOOTTIME expires:179552000000 now:150154008122 Binder:3292_9-3953 [000] d..2 150.213006: alarmtimer_start: alarmtimer:ffffffc1319a5a00 type:ALARM_BOOTTIME expires:179551000000 now:150154025622 ...... system_server-3000 [002] ...1 1087.737565: alarmtimer_suspend: alarmtimer type:ALARM_BOOTTIME 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 --- 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 Acked-by: Steven Rostedt diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h new file mode 100644 index 0000000..4c92a3e --- /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, "ALARM_REALTIME" }, \ + { 1 << ALARM_BOOTTIME, "ALARM_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 c3aad68..4e10dad 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);