From patchwork Thu Jun 1 17:35:16 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Dario Faggioli X-Patchwork-Id: 9760735 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 3A7DE60363 for ; Thu, 1 Jun 2017 17:37:42 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 24AD3204BD for ; Thu, 1 Jun 2017 17:37:42 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 1721028518; Thu, 1 Jun 2017 17:37:42 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-3.6 required=2.0 tests=BAYES_00,DKIM_SIGNED, RCVD_IN_DNSWL_MED,RCVD_IN_SORBS_SPAM,T_DKIM_INVALID autolearn=ham version=3.3.1 Received: from lists.xenproject.org (lists.xenproject.org [192.237.175.120]) (using TLSv1.2 with cipher AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 6AC00204BD for ; Thu, 1 Jun 2017 17:37:40 +0000 (UTC) Received: from localhost ([127.0.0.1] helo=lists.xenproject.org) by lists.xenproject.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dGU0I-0000p7-TW; Thu, 01 Jun 2017 17:35:22 +0000 Received: from mail6.bemta3.messagelabs.com ([195.245.230.39]) by lists.xenproject.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dGU0H-0000ni-N3 for xen-devel@lists.xenproject.org; Thu, 01 Jun 2017 17:35:21 +0000 Received: from [85.158.137.68] by server-3.bemta-3.messagelabs.com id 6D/0D-01985-95050395; Thu, 01 Jun 2017 17:35:21 +0000 X-Brightmail-Tracker: H4sIAAAAAAAAA+NgFnrPIsWRWlGSWpSXmKPExsXiVRvkrBseYBB p8G+thcX3LZOZHBg9Dn+4whLAGMWamZeUX5HAmrHx5wLWgpteFa+ez2NpYDxl2cXIxSEkMJNR YtHir4xdjJwcLAJrWCV2na8AsSUELrFKnDupAWHHScxfdIodwq6UuDH7MTOILSSgInFz+yomC Psbo8SOnQEgtrCAnsSRoz/YIWwNiTf/foDVsAkYSLzZsZcVxBYRUJK4t2oyWJwZpHfjkmKIG1 QlLk3bBBbnFfCR6DkxhQ3E5hTwlZh06gwjxC4fiW+/JoDViArISay83MIKUS8ocXLmE5YuRg6 gmZoS63fpQ4yXl9j+dg7zBEaRWUiqZiFUzUJStYCReRWjenFqUVlqka6JXlJRZnpGSW5iZo6u oYGxXm5qcXFiempOYlKxXnJ+7iZGYOAzAMEOxsYvTocYJTmYlER5F8gbRArxJeWnVGYkFmfEF 5XmpBYfYpTh4FCS4L3gB5QTLEpNT61Iy8wBxiBMWoKDR0mENwUkzVtckJhbnJkOkTrFqMsx6c D2L0xCLHn5ealS4rxLQYoEQIoySvPgRsDSwSVGWSlhXkago4R4ClKLcjNLUOVfMYpzMCoJ8z4 BmcKTmVcCt+kV0BFMQEe82KYPckRJIkJKqoGR3W/VulBPg2mqdye7T5zie27pgntxMzTXvL69 24hhO/+rGJYZcyU6P+VJcAU0RZvFKOe/v30ktLR3d6fJ5C8tjw1fOWnc/BAhYOQk2uM9KeTnE oXP3xtk4zx0thfZCk81eHxVb2ZunadeYNObba/Lq/OFpr95GujS2Bn1tPDtlZj832dPOH1TYi nOSDTUYi4qTgQAgGTGRAIDAAA= X-Env-Sender: raistlin.df@gmail.com X-Msg-Ref: server-16.tower-31.messagelabs.com!1496338519!96065834!1 X-Originating-IP: [74.125.82.67] X-SpamReason: No, hits=0.0 required=7.0 tests= X-StarScan-Received: X-StarScan-Version: 9.4.19; banners=-,-,- X-VirusChecked: Checked Received: (qmail 26737 invoked from network); 1 Jun 2017 17:35:19 -0000 Received: from mail-wm0-f67.google.com (HELO mail-wm0-f67.google.com) (74.125.82.67) by server-16.tower-31.messagelabs.com with AES128-GCM-SHA256 encrypted SMTP; 1 Jun 2017 17:35:19 -0000 Received: by mail-wm0-f67.google.com with SMTP id d127so13021775wmf.1 for ; Thu, 01 Jun 2017 10:35:19 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=sender:subject:from:to:cc:date:message-id:in-reply-to:references :user-agent:mime-version:content-transfer-encoding; bh=Hx6ctBfvw0NyegeJ9LuaNB2Le0vqidZt6smrkN88L2M=; b=YtXNPnhHZFhhgxJOadL3oo12Nz7jQ0BfaYIyhl+n2gYKAh0fflTO2+yvtimArEWPov vEnTZ0OnkvIOu4TYxNCZfFDAFV+rcQdd9rqmmA4PRjz7XYnXPGiBQK5pcS9uwucdbhc8 UsYOZn9RgZCPIBqpvhDF1C4SgYTpDVhuKvF7YNQ7nycyWNdDMg0es2AhqjxPloNe0lGn P8SGgvqVizobqS2qhglDjYI4AO9hzMys66D5uMO6BqWTlNN71kZu3Qjjh839wCvHDBfM Xp8G82YZd0lOj1VJFcaF5GhBMbgq+wLcsLnCd1vARde17Mh3yO8v9mb/Sciv893UFBsw AxLA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:sender:subject:from:to:cc:date:message-id :in-reply-to:references:user-agent:mime-version :content-transfer-encoding; bh=Hx6ctBfvw0NyegeJ9LuaNB2Le0vqidZt6smrkN88L2M=; b=sP/vElOWnIAynymW0v68E1WPGZZxuwNALL0yYQ7+113SPq02l6a+Pfk/tp1NkfisF1 FQwCpxMlGjxjW7Rdfu3IWUZ+fv4DL47g/EHcpVRg2+3pOyfac2N1YdNCJVJb895rjv1r WZMLhLgtOH2dcIHVhSgILDBjtt/qUyumSu6PpR+XoOibSEBmOwJAjKR/VXfvEtlZ7xOu xri1EZdGSffcfVhlKx0qC4XQBjHCKcnsKiNJqzRbpsnXA1Ya7ICXGGBj0b9GH0EQfS2V F0ufN4jCHeX+MLS7Kbk2es7qxLq2rWnxMqzN1OhgRAyTWmNzgc9tOpXrFxkmxCa/McSd 2cRg== X-Gm-Message-State: AODbwcC6v5kdkFCVzWC5pc3JqrJGbK8iWCIq+efQaUyfuNb+B7vdP4pN wC9n/GxnsubgWA== X-Received: by 10.223.134.46 with SMTP id 43mr2513691wrv.123.1496338519505; Thu, 01 Jun 2017 10:35:19 -0700 (PDT) Received: from Solace.fritz.box ([80.66.223.25]) by smtp.gmail.com with ESMTPSA id s10sm24451wmb.8.2017.06.01.10.35.17 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 01 Jun 2017 10:35:18 -0700 (PDT) From: Dario Faggioli To: xen-devel@lists.xenproject.org Date: Thu, 01 Jun 2017 19:35:16 +0200 Message-ID: <149633851685.12814.14195195446339149924.stgit@Solace.fritz.box> In-Reply-To: <149633614204.12814.14390287626133023934.stgit@Solace.fritz.box> References: <149633614204.12814.14390287626133023934.stgit@Solace.fritz.box> User-Agent: StGit/0.17.1-dirty MIME-Version: 1.0 Cc: Stefano Stabellini , George Dunlap , Andrew Cooper , Tim Deegan , Jan Beulich Subject: [Xen-devel] [PATCH 14/15] xen: trace timers X-BeenThere: xen-devel@lists.xen.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: Xen developer discussion List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Errors-To: xen-devel-bounces@lists.xen.org Sender: "Xen-devel" X-Virus-Scanned: ClamAV using ClamSMTP Making it possible generate events showing the activity and the behavior of timers. Gate this with its specific Kconfig option (under CONFIG_TRACING), and keep it in disabled state by default. --- Cc: George Dunlap Cc: Andrew Cooper Cc: Jan Beulich Cc: Konrad Rzeszutek Wilk Cc: Stefano Stabellini Cc: Tim Deegan --- xen/Kconfig.debug | 9 +++ xen/common/timer.c | 158 ++++++++++++++++++++++++++++++++++++++++++-- xen/include/public/trace.h | 12 +++ 3 files changed, 173 insertions(+), 6 deletions(-) diff --git a/xen/Kconfig.debug b/xen/Kconfig.debug index f7b2e06..e363435 100644 --- a/xen/Kconfig.debug +++ b/xen/Kconfig.debug @@ -140,6 +140,15 @@ config TRACE_TASKLETS Make it possible to generate events related to scheduling, queueing and running of tasklets within Xen. ++config TRACE_TIMERS + bool "Trace when timers are armed and fires" if EXPERT = "y" + default n + depends on TRACING + ---help--- + Makes it possible to generate events related to the timers + subsystems, such as, creation, initialization, queueing, + firing and removal of timers. + config VERBOSE_DEBUG bool "Verbose debug messages" default DEBUG diff --git a/xen/common/timer.c b/xen/common/timer.c index d9ff669..8daeeb3 100644 --- a/xen/common/timer.c +++ b/xen/common/timer.c @@ -43,6 +43,136 @@ static DEFINE_RCU_READ_LOCK(timer_cpu_read_lock); DEFINE_PER_CPU(s_time_t, timer_deadline); +#ifdef CONFIG_TRACE_TIMERS +static inline void trace_rm_entry(const struct timer *t) +{ + struct { + uint64_t addr; + uint16_t status, cpu; + } d; + + if ( likely(!tb_init_done) ) + return; + + d.addr = (uint64_t)t; + d.cpu = t->cpu; + d.status = t->status; + __trace_var(TRC_XEN_TIMER_RMENTRY, 0, sizeof(d), &d); +} +static inline void trace_add_entry(const struct timer *t) +{ + struct { + uint64_t addr; + uint16_t status, cpu; + } d; + + if ( likely(!tb_init_done) ) + return; + + d.addr = (uint64_t)t; + d.cpu = t->cpu; + d.status = t->status; + __trace_var(TRC_XEN_TIMER_ADDENTRY, 0, sizeof(d), &d); +} +static inline void trace_set(const struct timer *t) +{ + struct { + uint64_t addr, addr_fn; + int64_t expires_in; + } d; + + if ( likely(!tb_init_done) ) + return; + + d.addr = (uint64_t)t; + d.addr_fn = (uint64_t)t->function; + d.expires_in = t->expires - NOW(); + __trace_var(TRC_XEN_TIMER_SET, 1, sizeof(d), &d); +} +static inline void trace_stop(const struct timer *t) +{ + uint64_t addr; + + if ( likely(!tb_init_done) ) + return; + + addr = (uint64_t)t; + __trace_var(TRC_XEN_TIMER_STOP, 0, sizeof(addr), &addr); +} +static inline void trace_migrate(const struct timer *t, unsigned int cpu) +{ + struct { + uint64_t addr; + uint16_t new_cpu, old_cpu; + } d; + + if ( likely(!tb_init_done) ) + return; + + d.addr = (uint64_t)t; + d.old_cpu = t->cpu; + d.new_cpu = cpu; + __trace_var(TRC_XEN_TIMER_MIGRATE, 0, sizeof(d), &d); +} +static inline void trace_kill(const struct timer *t) +{ + uint64_t addr; + + if ( likely(!tb_init_done) ) + return; + + addr = (uint64_t)t; + __trace_var(TRC_XEN_TIMER_KILL, 0, sizeof(addr), &addr); +} +static inline void trace_exec(const struct timer *t) +{ + struct { + uint64_t addr; + int64_t tardiness; + } d; + + if ( likely(!tb_init_done) ) + return; + + d.addr = (uint64_t)t; + d.tardiness = NOW() - t->expires; + __trace_var(TRC_XEN_TIMER_EXEC, 1, sizeof(d), &d); +} +static inline void trace_reprogr(s_time_t n, s_time_t d) +{ + uint64_t deadline = d - n; + + if ( likely(!tb_init_done) ) + return; + + __trace_var(TRC_XEN_TIMER_REPRGR, 1, sizeof(deadline), &deadline); +} +static inline void trace_hoverfl(unsigned int old_lim, unsigned int new_lim) +{ + struct { + uint16_t new_limit, old_limit; + } d; + + if ( likely(!tb_init_done) ) + return; + + d.old_limit = old_lim; + d.new_limit = new_lim; + __trace_var(TRC_XEN_TIMER_EXEC, 0, sizeof(d), &d); +} +#define trace_hoverfl(o, n) TRACE_2D(TRC_XEN_TIMER_HOVERFL, o, n) +#else /* !TRACE_TIMERS */ +#define trace_rm_entry(t) do {} while ( 0 ) +#define trace_add_entry(t) do {} while ( 0 ) +#define trace_set(t) do {} while ( 0 ) +#define trace_stop(t) do {} while ( 0 ) +#define trace_migrate(t, c) do {} while ( 0 ) +#define trace_kill(t) do {} while ( 0 ) +#define trace_exec(t) do {} while ( 0 ) +#define trace_reprogr(n, d) do {} while ( 0 ) +#define trace_hoverfl(o, n) do {} while ( 0 ) +#endif /* TRACE_TIMERS */ + /**************************************************************************** * HEAP OPERATIONS. */ @@ -175,6 +305,8 @@ static int remove_entry(struct timer *t) struct timers *timers = &per_cpu(timers, t->cpu); int rc; + trace_rm_entry(t); + switch ( t->status ) { case TIMER_STATUS_in_heap: @@ -204,11 +336,14 @@ static int add_entry(struct timer *t) t->status = TIMER_STATUS_in_heap; rc = add_to_heap(timers->heap, t); if ( t->heap_offset != 0 ) - return rc; + goto out; /* Fall back to adding to the slower linked list. */ t->status = TIMER_STATUS_in_list; - return add_to_list(&timers->list, t); + rc = add_to_list(&timers->list, t); + out: + trace_add_entry(t); + return rc; } static inline void activate_timer(struct timer *timer) @@ -307,6 +442,8 @@ void set_timer(struct timer *timer, s_time_t expires) if ( !timer_lock_irqsave(timer, flags) ) return; + trace_set(timer); + if ( active_timer(timer) ) deactivate_timer(timer); @@ -325,6 +462,8 @@ void stop_timer(struct timer *timer) if ( !timer_lock_irqsave(timer, flags) ) return; + trace_stop(timer); + if ( active_timer(timer) ) deactivate_timer(timer); @@ -335,7 +474,6 @@ void stop_timer(struct timer *timer) void migrate_timer(struct timer *timer, unsigned int new_cpu) { unsigned int old_cpu; - bool_t active; unsigned long flags; rcu_read_lock(&timer_cpu_read_lock); @@ -369,15 +507,16 @@ void migrate_timer(struct timer *timer, unsigned int new_cpu) rcu_read_unlock(&timer_cpu_read_lock); - active = active_timer(timer); - if ( active ) + trace_migrate(timer, new_cpu); + + if ( active_timer(timer) ) deactivate_timer(timer); list_del(&timer->inactive); write_atomic(&timer->cpu, new_cpu); list_add(&timer->inactive, &per_cpu(timers, new_cpu).inactive); - if ( active ) + if ( active_timer(timer) ) activate_timer(timer); spin_unlock(&per_cpu(timers, old_cpu).lock); @@ -395,6 +534,8 @@ void kill_timer(struct timer *timer) if ( !timer_lock_irqsave(timer, flags) ) return; + trace_kill(timer); + if ( active_timer(timer) ) deactivate_timer(timer); @@ -421,6 +562,7 @@ static void execute_timer(struct timers *ts, struct timer *t) ts->running = t; spin_unlock_irq(&ts->lock); + trace_exec(t); (*fn)(data); spin_lock_irq(&ts->lock); ts->running = NULL; @@ -443,6 +585,7 @@ static void timer_softirq_action(void) int old_limit = GET_HEAP_LIMIT(heap); int new_limit = ((old_limit + 1) << 4) - 1; struct timer **newheap = xmalloc_array(struct timer *, new_limit + 1); + if ( newheap != NULL ) { spin_lock_irq(&ts->lock); @@ -454,6 +597,7 @@ static void timer_softirq_action(void) xfree(heap); heap = newheap; } + trace_hoverfl(old_limit, new_limit); } spin_lock_irq(&ts->lock); @@ -495,6 +639,8 @@ static void timer_softirq_action(void) this_cpu(timer_deadline) = (deadline == STIME_MAX) ? 0 : MAX(deadline, now + timer_slop); + trace_reprogr(now, this_cpu(timer_deadline)); + if ( !reprogram_timer(this_cpu(timer_deadline)) ) raise_softirq(TIMER_SOFTIRQ); diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h index acee7d5..9983ce8 100644 --- a/xen/include/public/trace.h +++ b/xen/include/public/trace.h @@ -97,6 +97,7 @@ #define TRC_XEN_RCU 0x01001000 /* RCU traces */ #define TRC_XEN_SIRQ 0x01002000 /* Traces relating to softirqs */ #define TRC_XEN_TSKLT 0x01004000 /* Traces relating to tasklets */ +#define TRC_XEN_TIMER 0x01008000 /* Trace relating to timer events */ /* Trace events per class */ #define TRC_LOST_RECORDS (TRC_GEN + 1) @@ -308,6 +309,17 @@ #define TRC_XEN_TASKLET_INIT (TRC_XEN_TSKLT + 0x5) #define TRC_XEN_TASKLET_MIGR (TRC_XEN_TSKLT + 0x6) +/* Trace events for timers */ +#define TRC_XEN_TIMER_RMENTRY (TRC_XEN_TIMER + 0x1) +#define TRC_XEN_TIMER_ADDENTRY (TRC_XEN_TIMER + 0x2) +#define TRC_XEN_TIMER_SET (TRC_XEN_TIMER + 0x3) +#define TRC_XEN_TIMER_STOP (TRC_XEN_TIMER + 0x4) +#define TRC_XEN_TIMER_MIGRATE (TRC_XEN_TIMER + 0x5) +#define TRC_XEN_TIMER_KILL (TRC_XEN_TIMER + 0x6) +#define TRC_XEN_TIMER_EXEC (TRC_XEN_TIMER + 0x7) +#define TRC_XEN_TIMER_REPRGR (TRC_XEN_TIMER + 0x8) +#define TRC_XEN_TIMER_HOVERFL (TRC_XEN_TIMER + 0x9) + /* * Event Flags *