From patchwork Thu Aug 18 08:47:39 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: 74139 Delivered-To: patch@linaro.org Received: by 10.140.29.52 with SMTP id a49csp238778qga; Thu, 18 Aug 2016 01:49:53 -0700 (PDT) X-Received: by 10.66.76.9 with SMTP id g9mr1994744paw.51.1471510193050; Thu, 18 Aug 2016 01:49:53 -0700 (PDT) Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id x20si1468691pal.165.2016.08.18.01.49.52; Thu, 18 Aug 2016 01:49:53 -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 S1753632AbcHRItu (ORCPT + 27 others); Thu, 18 Aug 2016 04:49:50 -0400 Received: from mail-pa0-f46.google.com ([209.85.220.46]:35491 "EHLO mail-pa0-f46.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753180AbcHRIts (ORCPT ); Thu, 18 Aug 2016 04:49:48 -0400 Received: by mail-pa0-f46.google.com with SMTP id i5so4620909pat.2 for ; Thu, 18 Aug 2016 01:48: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=yMK1IF1DT81fxZuVWkDuxvJk6u92tuePdGr2ornePR8=; b=kGyxUTGLakuo0ZhsQVV1UZPF2jWqFU9oAu5Vza2gvB7OCWlSeSvImA239IKcX0LgsQ DdXncV147YLQeqdVF0QDSQLs20C0wTfBj9cII541YmwJIU9TAvVQli4qEko1Cvo8Jp3O AiNMLr1HGeCngEICgCxbd9V1fRPNQbgolM7bo= 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=yMK1IF1DT81fxZuVWkDuxvJk6u92tuePdGr2ornePR8=; b=fOr6t8GBmNrf+Gp2Q1ZuQUeA5CQ9gDZBZCyAyG5USXEUy9MUXAPFctA2AfU8YmWfpq OUz9QcHTxe9kAlR749z01ZX6KE8lq5pXEHOFXxScSIZ5P5a9S/kcSsSzsbzqe7L804bZ C4Ix1dNegPf4oqnmdR2SsZiVcDQG6MrlGptmxS6S67/x+KUatzkNfMqgeCP9nijZztNa l2n+SCT9tI9I36VjonK+MHy/Vuoo2N6r3iI/xKFtrabTUfQsTVKicCS1d8V59tqk6zgZ j0FD+1DIUDBO5KxKyfANiMah+MQI9Y1utfnGBSvrMqBQkN+XWybhvhMQC5UW+pVOudSg EbAg== X-Gm-Message-State: AEkoouuTadzfMP4rxcZIuzuaXaIxUjA37ySeukGaMLKUtZy5J3UkK+NTiOTGlG88yf/jwJv2 X-Received: by 10.66.78.5 with SMTP id x5mr2062457paw.108.1471510122490; Thu, 18 Aug 2016 01:48:42 -0700 (PDT) Received: from baolinwangubtpc.spreadtrum.com ([175.111.195.49]) by smtp.gmail.com with ESMTPSA id i7sm2181355paf.9.2016.08.18.01.48.39 (version=TLS1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Thu, 18 Aug 2016 01:48:41 -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 v2] time: alarmtimer: Add the trcepoints for alarmtimer Date: Thu, 18 Aug 2016 16:47:39 +0800 Message-Id: <5ad46ec54f3af856044b8293d84d6da2b62b1c2d.1471508284.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 usually 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:2976_6-3473 [005] d..2 1076.587732: alarmtimer_start: process:Binder:2976_6 alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1 0:20:35 Binder:2976_7-3480 [002] d..2 1076.592707: alarmtimer_cancel: process:Binder:2976_7 alarmtimer type:ALARM_BOOTTIME expires:1325463060000000000 time: 2012-1-2 0:11:0 Binder:2976_7-3480 [002] d..2 1076.592731: alarmtimer_start: process:Binder:2976_7 alarmtimer type:ALARM_BOOTTIME expires:1325378040000000000 time: 2012-1-1 0:34:0 system_server-2976 [003] d..2 1076.605587: alarmtimer_cancel: process:system_server alarmtimer type:ALARM_BOOTTIME expires:1234154000000 time: 1970-1-1 0:20:35 system_server-2976 [003] d..2 1076.605608: alarmtimer_start: process:system_server alarmtimer type:ALARM_BOOTTIME expires:1234155000000 time: 1970-1-1 0:20:35 system_server-3000 [002] ...1 1087.737565: alarmtimer_suspend: alarmtimer type:ALARM_BOOTTIME expires time: 2012-1-1 0:34:0 ...... >From the trace log, we can find out the 'Binder:2976_7' process set one alarm timer which resumes the system. Signed-off-by: Baolin Wang --- Changes since v1: - Fix the kbuild error. - Modify the changelog with adding trace log. --- include/trace/events/alarmtimer.h | 134 +++++++++++++++++++++++++++++++++++++ kernel/time/alarmtimer.c | 21 +++++- 2 files changed, 152 insertions(+), 3 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..eea4e12 --- /dev/null +++ b/include/trace/events/alarmtimer.h @@ -0,0 +1,134 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM alarmtimer + +#if !defined(_TRACE_ALARMTIMER_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_ALARMTIMER_H + +#include +#include +#include + +#define show_alarm_type(type) __print_flags(type, " | ", \ + { 1 << ALARM_REALTIME, "ALARM_REALTIME" }, \ + { 1 << ALARM_BOOTTIME, "ALARM_BOOTTIME" }) + +DECLARE_EVENT_CLASS(alarm_setting, + + TP_PROTO(struct rtc_time *rtc_time, int flag), + + TP_ARGS(rtc_time, flag), + + TP_STRUCT__entry( + __field(unsigned int, second) + __field(unsigned int, minute) + __field(unsigned int, hour) + __field(unsigned int, day) + __field(unsigned int, mon) + __field(unsigned int, year) + __field(unsigned int, alarm_type) + ), + + TP_fast_assign( + __entry->second = rtc_time->tm_sec; + __entry->minute = rtc_time->tm_min; + __entry->hour = rtc_time->tm_hour; + __entry->day = rtc_time->tm_mday; + __entry->mon = rtc_time->tm_mon; + __entry->year = rtc_time->tm_year; + __entry->alarm_type = flag; + ), + + TP_printk("alarmtimer type:%s expires time: %u-%u-%u %u:%u:%u", + show_alarm_type((1 << __entry->alarm_type)), + __entry->year + 1900, + __entry->mon + 1, + __entry->day, + __entry->hour, + __entry->minute, + __entry->second + ) +); + +DEFINE_EVENT(alarm_setting, alarmtimer_suspend, + + TP_PROTO(struct rtc_time *time, int flag), + + TP_ARGS(time, flag) +); + +DECLARE_EVENT_CLASS(alarm_processing, + + TP_PROTO(struct alarm *alarm, char *process_name), + + TP_ARGS(alarm, process_name), + + TP_STRUCT__entry( + __field(unsigned long long, expires) + __field(unsigned int, second) + __field(unsigned int, minute) + __field(unsigned int, hour) + __field(unsigned int, day) + __field(unsigned int, mon) + __field(unsigned int, year) + __field(unsigned int, alarm_type) + __string(name, process_name) + ), + + TP_fast_assign( + __entry->expires = alarm->node.expires.tv64; + __entry->second = rtc_ktime_to_tm(alarm->node.expires).tm_sec; + __entry->minute = rtc_ktime_to_tm(alarm->node.expires).tm_min; + __entry->hour = rtc_ktime_to_tm(alarm->node.expires).tm_hour; + __entry->day = rtc_ktime_to_tm(alarm->node.expires).tm_mday; + __entry->mon = rtc_ktime_to_tm(alarm->node.expires).tm_mon; + __entry->year = rtc_ktime_to_tm(alarm->node.expires).tm_year; + __entry->alarm_type = alarm->type; + __assign_str(name, process_name); + ), + + TP_printk("process:%s alarmtimer type:%s expires:%llu " + "time: %u-%u-%u %u:%u:%u", + __get_str(name), + show_alarm_type((1 << __entry->alarm_type)), + __entry->expires, + __entry->year + 1900, + __entry->mon + 1, + __entry->day, + __entry->hour, + __entry->minute, + __entry->second + ) +); + +DEFINE_EVENT(alarm_processing, alarmtimer_fired, + + TP_PROTO(struct alarm *alarm, char *process_name), + + TP_ARGS(alarm, process_name) +); + +DEFINE_EVENT(alarm_processing, alarmtimer_start, + + TP_PROTO(struct alarm *alarm, char *process_name), + + TP_ARGS(alarm, process_name) +); + +DEFINE_EVENT(alarm_processing, alarmtimer_restart, + + TP_PROTO(struct alarm *alarm, char *process_name), + + TP_ARGS(alarm, process_name) +); + +DEFINE_EVENT(alarm_processing, alarmtimer_cancel, + + TP_PROTO(struct alarm *alarm, char *process_name), + + TP_ARGS(alarm, process_name) +); + +#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..866d668 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, NULL); return ret; } @@ -218,11 +222,11 @@ EXPORT_SYMBOL_GPL(alarm_expires_remaining); */ static int alarmtimer_suspend(struct device *dev) { - struct rtc_time tm; + struct rtc_time tm, tm_set; 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,9 @@ static int alarmtimer_suspend(struct device *dev) now = rtc_tm_to_ktime(tm); now = ktime_add(now, min); + tm_set = rtc_ktime_to_tm(now); + trace_alarmtimer_suspend(&tm_set, 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 +351,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, current->comm); } EXPORT_SYMBOL_GPL(alarm_start); @@ -369,6 +380,8 @@ void alarm_restart(struct alarm *alarm) hrtimer_restart(&alarm->timer); alarmtimer_enqueue(base, alarm); spin_unlock_irqrestore(&base->lock, flags); + + trace_alarmtimer_restart(alarm, current->comm); } EXPORT_SYMBOL_GPL(alarm_restart); @@ -390,6 +403,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, current->comm); return ret; } EXPORT_SYMBOL_GPL(alarm_try_to_cancel);