From patchwork Wed Aug 31 21:50:22 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: John Stultz X-Patchwork-Id: 75133 Delivered-To: patches@linaro.org Received: by 10.140.29.52 with SMTP id a49csp552942qga; Wed, 31 Aug 2016 14:50:38 -0700 (PDT) X-Received: by 10.98.17.152 with SMTP id 24mr21012216pfr.13.1472680231507; Wed, 31 Aug 2016 14:50:31 -0700 (PDT) Return-Path: Received: from mail-pf0-x22b.google.com (mail-pf0-x22b.google.com. [2607:f8b0:400e:c00::22b]) by mx.google.com with ESMTPS id e2si1755644pfk.26.2016.08.31.14.50.31 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Wed, 31 Aug 2016 14:50:31 -0700 (PDT) Received-SPF: pass (google.com: domain of john.stultz@linaro.org designates 2607:f8b0:400e:c00::22b as permitted sender) client-ip=2607:f8b0:400e:c00::22b; 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:c00::22b as permitted sender) smtp.mailfrom=john.stultz@linaro.org; dmarc=pass (p=NONE dis=NONE) header.from=linaro.org Received: by mail-pf0-x22b.google.com with SMTP id g202so438829pfb.0 for ; Wed, 31 Aug 2016 14:50:31 -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:in-reply-to:references; bh=/aQzLgXMbiUPK636LOriIMyA9QFqHRABaOEEGaF30g8=; b=Vy3N5VtEprDlh1vTtRUHFqKyYb7Am02qeA0riNen6daAr2xpblZkBNRCTEgmTKcCeq 8rpC0Shf15ZlS6sU8VsXuSbus3szEyVIfG8D4WDfGJCUvEHAO9mjsY8TIrcza2M10Tyk zipZnrdgpjwUvJ9QpXG3twPcgxQP4O8p44CFk= 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=/aQzLgXMbiUPK636LOriIMyA9QFqHRABaOEEGaF30g8=; b=S8NaBZ+vjQ+ygWPmkkbL8RZx5d+2t7LklWTKfFPeXOtlQbarcqbzUK15UhDwYiwVFW inUkmZvFyjByWqaC+pGBQb6jVdh593CJsHG6QKhi3D7Ybjmp9k9FVM5X+JFuB6LVqgYA HZueXdNeI5jIF+oA4OuLa4Y2kFfJ0Yix/Tf8cnXH17oX81Ts8TdNq28tCO5af0KHE7EZ 2PE5pXGSc0H+NJIXnTyRg/3nv3JiqeuAWrL4PpM9SleBJielpmJllAgiGlJ9zSO3JaMg hI+q96L8wt0rIErnsGQQ18bvcfkQmqsUeLkHC8OqP1NcG1GLzVIrG5NMO+x1bom/nkZZ 7AYQ== X-Gm-Message-State: AE9vXwMlbYABtcjfAZfT+BHhp580RUhUPA4u79eirt+32EpQjgnTjyOge4VHMg9WFFZ8kUQ/d08= X-Received: by 10.98.75.219 with SMTP id d88mr20912884pfj.91.1472680231164; Wed, 31 Aug 2016 14:50:31 -0700 (PDT) Return-Path: Received: from localhost.localdomain (c-73-67-244-238.hsd1.or.comcast.net. [73.67.244.238]) by smtp.gmail.com with ESMTPSA id a21sm1881772pfe.81.2016.08.31.14.50.30 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 31 Aug 2016 14:50:30 -0700 (PDT) From: John Stultz To: lkml Cc: Baolin Wang , Thomas Gleixner , Ingo Molnar , Richard Cochran , Prarit Bhargava , Steven Rostedt , John Stultz Subject: [PATCH 6/6] time: alarmtimer: Add tracepoints for alarmtimers Date: Wed, 31 Aug 2016 14:50:22 -0700 Message-Id: <1472680222-21060-7-git-send-email-john.stultz@linaro.org> X-Mailer: git-send-email 1.9.1 In-Reply-To: <1472680222-21060-1-git-send-email-john.stultz@linaro.org> References: <1472680222-21060-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: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. Cc: Thomas Gleixner Cc: Ingo Molnar Cc: Richard Cochran Cc: Prarit Bhargava Cc: Steven Rostedt Acked-by: Steven Rostedt Signed-off-by: Baolin Wang [jstultz: tweaked commit message] Signed-off-by: John Stultz --- include/trace/events/alarmtimer.h | 137 ++++++++++++++++++++++++++++++++++++++ kernel/time/alarmtimer.c | 23 ++++++- 2 files changed, 157 insertions(+), 3 deletions(-) create mode 100644 include/trace/events/alarmtimer.h -- 1.9.1 diff --git a/include/trace/events/alarmtimer.h b/include/trace/events/alarmtimer.h new file mode 100644 index 0000000..6a34bc9 --- /dev/null +++ b/include/trace/events/alarmtimer.h @@ -0,0 +1,137 @@ +#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" }) + +DECLARE_EVENT_CLASS(alarm_setting, + + TP_PROTO(struct rtc_time *rtc_time, int flag), + + TP_ARGS(rtc_time, flag), + + TP_STRUCT__entry( + __field(unsigned char, second) + __field(unsigned char, minute) + __field(unsigned char, hour) + __field(unsigned char, day) + __field(unsigned char, mon) + __field(unsigned short, year) + __field(unsigned char, 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: %hu-%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 char, second) + __field(unsigned char, minute) + __field(unsigned char, hour) + __field(unsigned char, day) + __field(unsigned char, mon) + __field(unsigned short, year) + __field(unsigned char, 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: %hu-%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..7cd15eb 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,11 @@ static int alarmtimer_suspend(struct device *dev) now = rtc_tm_to_ktime(tm); now = ktime_add(now, min); + if (trace_alarmtimer_suspend_enabled()) { + 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 +353,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 +382,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 +405,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);