From patchwork Thu Jun 1 17:33:55 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Dario Faggioli X-Patchwork-Id: 9760709 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 6E4BA60363 for ; Thu, 1 Jun 2017 17:36:17 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 59E1027F17 for ; Thu, 1 Jun 2017 17:36:17 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 4EBB62851A; Thu, 1 Jun 2017 17:36:17 +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 4F84327F17 for ; Thu, 1 Jun 2017 17:36:14 +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 1dGTz1-0008Pl-Lf; Thu, 01 Jun 2017 17:34:03 +0000 Received: from mail6.bemta5.messagelabs.com ([195.245.231.135]) by lists.xenproject.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dGTz0-0008PL-PP for xen-devel@lists.xenproject.org; Thu, 01 Jun 2017 17:34:02 +0000 Received: from [85.158.139.211] by server-10.bemta-5.messagelabs.com id E4/B8-01734-A0050395; Thu, 01 Jun 2017 17:34:02 +0000 X-Brightmail-Tracker: H4sIAAAAAAAAA+NgFvrFIsWRWlGSWpSXmKPExsXiVRvkpMsWYBB pcPErk8X3LZOZHBg9Dn+4whLAGMWamZeUX5HAmnH+/UfGgmfuFVd2HmBuYNxr0sXIxSEkMINR Ys2y76wgDovAGlaJwytbGEEcCYFLrBIb9+xm6WLkBHLiJNbN3cwGYZdLzPw3gwnEFhJQkbi5f RUTxKivjBKrb74EaxAW0JM4cvQHO4QdIDFp6UpWEJtNwEDizY69YLaIgJLEvVWTwZqZBY4ySu zaux9sA4uAqsTq1U/BBvEK+Egc7z/ADGJzCvhKTDp1hhFis4/Et18TwK4QFZCTWHm5hRWiXlD i5MwnQL0cQEM1Jdbv0gcJMwvIS2x/O4d5AqPILCRVsxCqZiGpWsDIvIpRozi1qCy1SNfISC+p KDM9oyQ3MTNH19DAVC83tbg4MT01JzGpWC85P3cTIzAG6hkYGHcw7mn3O8QoycGkJMq7QN4gU ogvKT+lMiOxOCO+qDQntfgQowwHh5IE7wU/oJxgUWp6akVaZg4wGmHSEhw8SiK8KSBp3uKCxN zizHSI1ClGY44Nq9d/YeKYdGD7FyYhlrz8vFQpcV52f6BSAZDSjNI8uEGwJHGJUVZKmJeRgYF BiKcgtSg3swRV/hWjOAejkjBvLshCnsy8Erh9r4BOYQI65cU2fZBTShIRUlINjD5Hk+a6a9d9 XClzYPXz87lKtQGPTol7di/LN5XK3Ojj8E504Y+jCVUzpnS03Ho/K3GB94rHky7JlXgYrjoV6 b8qekGAYvXqBX79pfbR+x+UCtpl/IosfP8oPMT4cTFHx97HKW9Ne45yZrP+jlWVyrzrGzvHZV 9tzPS4wNON13e7XcyueRETrsRSnJFoqMVcVJwIAPxHb20NAwAA X-Env-Sender: raistlin.df@gmail.com X-Msg-Ref: server-8.tower-206.messagelabs.com!1496338437!101309604!1 X-Originating-IP: [74.125.82.66] X-SpamReason: No, hits=0.0 required=7.0 tests=SUBJECT_RANDOMQ X-StarScan-Received: X-StarScan-Version: 9.4.19; banners=-,-,- X-VirusChecked: Checked Received: (qmail 34084 invoked from network); 1 Jun 2017 17:33:58 -0000 Received: from mail-wm0-f66.google.com (HELO mail-wm0-f66.google.com) (74.125.82.66) by server-8.tower-206.messagelabs.com with AES128-GCM-SHA256 encrypted SMTP; 1 Jun 2017 17:33:58 -0000 Received: by mail-wm0-f66.google.com with SMTP id g15so13028010wmc.2 for ; Thu, 01 Jun 2017 10:33:57 -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=bUtxI3pRkTi26PqjUeWdKVzPtav90p8R/lqgVOf+p6s=; b=myhw1Z0BJe/2tsdTNBFXJiWTj+bFO4Qo2JEfclbJkYMgmgz9LmHI2Nd0x56IcrwMpt MNPTxEq3nehpo89GiqihFdioh4/ntFGagowjj6QQZiTufgEDnQ0ISGN9ILj/uSyIvnp2 NbJvEYJ1bdBgAt5U6ikU8DEaxR7ddKX3Phz0PhWZE5u33Mq+Y/UnFnug4/crVadpY4H+ gxIpUlgVlCi6qy6JbX4UR9XKxB7Yt1wnZHm46s5kCONfAd5iISv6thAvqvO0tLdRzaHj pwG5zSc9B/bSaQmzrg7WH9PFw603Ih/bRzXcpMJnDKPScChiLqWqe0V2isePIwCE2qF/ iMxw== 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=bUtxI3pRkTi26PqjUeWdKVzPtav90p8R/lqgVOf+p6s=; b=HNQmyHONrwEL9XrC4NplEEMtN0dk2fth1yTwARyK30ZwrIOoXUHJCjB911iw0OzntQ mAXukMF+uflV0NhMIDSLv98rjQZtPG52kvAd4doBfXaveL0aIhE93kwrLpfMTlYf60oP 5mh3am/kpsQspsRk5OFsmZMeIwFhkjZ/p/Pwk+9HzHPxD4up3xVzXgBEh/xbJtE9yIqL apRrwvxqqCyM/E8WhhMy/6m1H61JBB3bOBj4L+AT4LizA/Ecjmg5PgZYP/Jv/6sHaNI1 3XtCMJeayPdGUa9MIj7rG/zARqIRdoKB9RlQog+JwolG6UhV7QANPbg6irVudSXOaH/p o6VQ== X-Gm-Message-State: AODbwcBzgmF/nGzh69xIvZSPrfz3cB0fAXH29c7OB4YU7eRFaWpMm1nY TY1Cm4cbZ4dhabVA X-Received: by 10.28.32.19 with SMTP id g19mr182174wmg.123.1496338437612; Thu, 01 Jun 2017 10:33:57 -0700 (PDT) Received: from Solace.fritz.box ([80.66.223.25]) by smtp.gmail.com with ESMTPSA id c8sm16050wmd.5.2017.06.01.10.33.56 (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Thu, 01 Jun 2017 10:33:57 -0700 (PDT) From: Dario Faggioli To: xen-devel@lists.xenproject.org Date: Thu, 01 Jun 2017 19:33:55 +0200 Message-ID: <149633843555.12814.16573412358602741145.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: George Dunlap , Wei Liu , Ian Jackson , Jan Beulich , Andrew Cooper Subject: [Xen-devel] [PATCH 03/15] xen/tools: tracing: several improvements on IRQs tracing 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 More specifically: - the handling of the TRC_HW_IRQ_HANDLED is fixed, both in xentrace_format and in xenalyze; - simple events for recording when we enter and exit the do_IRQ function, as well as when we deal with a guest IRQ, are added; - tracing of IRQs handled with direct vectors is also added. With all the above, a trace will now look like this (using xenalyze): 0.001299072 .x- d32768v5 irq_enter, irq 80000000 0.001299072 .x- d32768v5 irq_direct, vec fa, handler = 0xffff82d08026d7e4 0.001300014 .x- d32768v5 raise_softirq nr 0 0.001300487 .x- d32768v5 irq_exit irq 80000000, in_irq = 0 Or like this: 0.049437892 -|- d32767v12 irq_enter, irq 4 0.049437892 -|- d32767v12 irq_handled irq 4, 85428 cycles 0.049474336 -|- d32767v12 irq_exit irq 4, status = 0x0, in_irq = 0 Making it much easier to figure out when interrupt processing start, what it does and when it ends. Signed-off-by: Dario Faggioli --- Cc: George Dunlap Cc: Ian Jackson Cc: Wei Liu Cc: Jan Beulich Cc: Andrew Cooper --- tools/xentrace/formats | 6 ++++ tools/xentrace/xenalyze.c | 56 +++++++++++++++++++++++++++++++++++----- xen/arch/x86/irq.c | 61 +++++++++++++++++++++++++++++++++++++------- xen/include/public/trace.h | 4 +++ 4 files changed, 109 insertions(+), 18 deletions(-) diff --git a/tools/xentrace/formats b/tools/xentrace/formats index 8b31780..00c29b8 100644 --- a/tools/xentrace/formats +++ b/tools/xentrace/formats @@ -197,7 +197,11 @@ 0x00802005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) move_vector [ irq = %(1)d had vector 0x%(2)x on CPU%(3)d ] 0x00802006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) assign_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ] 0x00802007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) bogus_vector [ 0x%(1)x ] -0x00802008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_irq [ irq = %(1)d, began = %(2)dus, ended = %(3)dus ] +0x00802008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) irq_handled [ irq = %(1)d, dur = 0x%(3)08x%(2)08x ] +0x00802009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) direct_vector [ vector 0x%(1)x, handler = 0x%(3)08x%(2)08x ] +0x0080200a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_irq [ irq = %(1)d ] +0x0080200b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_guest_irq [ irq = %(1)d ] +0x0080200c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) irq_exit [ irq = %(1)d, status = 0x%(2)x, in_irq = %(3)d ] 0x00084001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hpet create [ tn = %(1)d, irq = %(2)d, delta = 0x%(4)08x%(3)08x, period = 0x%(6)08x%(5)08x ] 0x00084002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit create [ delta = 0x%(1)016x, period = 0x%(2)016x ] diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c index fa608ad..063eee7 100644 --- a/tools/xentrace/xenalyze.c +++ b/tools/xentrace/xenalyze.c @@ -8380,19 +8380,45 @@ void irq_process(struct pcpu_info *p) { } break; } - case TRC_HW_IRQ_HANDLED: + case TRC_HW_IRQ_ENTER: + case TRC_HW_IRQ_GUEST: { struct { - int irq, start_tsc, end_tsc; + int32_t irq; } *r = (typeof(r))ri->d; - int arctime; - arctime = r->end_tsc - r->start_tsc; if ( opt.dump_all ) { - printf(" %s irq_handled irq %x %d (%d,%d)\n", - ri->dump_header, - r->irq, arctime, r->start_tsc, r->end_tsc); + printf(" %s irq_%s, irq %x\n", ri->dump_header, + ri->event == TRC_HW_IRQ_ENTER ? "enter" : "guest", r->irq); + } + break; + } + case TRC_HW_IRQ_DIRECT_VECTOR: + { + struct { + uint32_t vec; + uint64_t handler; + } __attribute__((packed)) *r = (typeof(r))ri->d; + + if ( opt.dump_all ) + { + printf(" %s irq_direct, vec %x, handler = %p\n", + ri->dump_header, r->vec, (void*)r->handler); + } + break; + } + case TRC_HW_IRQ_HANDLED: + { + struct { + int32_t irq; + uint64_t arctime; + } __attribute__((packed)) *r = (typeof(r))ri->d; + + if ( opt.dump_all ) + { + printf(" %s irq_handled irq %x, %"PRIu64" cycles\n", + ri->dump_header, r->irq, r->arctime); } if ( opt.scatterplot_irq ) { @@ -8407,6 +8433,22 @@ void irq_process(struct pcpu_info *p) { } break; } + case TRC_HW_IRQ_EXIT: + { + struct { + int32_t irq, status; + uint32_t in_irq; + } *r = (typeof(r))ri->d; + + if ( opt.dump_all ) + { + printf(" %s irq_exit irq %x", ri->dump_header, r->irq); + if ( r->status != -1 ) + printf(", status = 0x%x", r->status); + printf(", in_irq = %d\n", r->in_irq); + } + break; + } case TRC_HW_IRQ_ASSIGN_VECTOR: { struct { diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c index 676ba52..f5d9302 100644 --- a/xen/arch/x86/irq.c +++ b/xen/arch/x86/irq.c @@ -100,11 +100,15 @@ static void trace_irq_mask(u32 event, int irq, int vector, cpumask_t *mask) unsigned int irq:16, vec:16; unsigned int mask[6]; } d; + + if ( likely(!tb_init_done) ) + return; + d.irq = irq; d.vec = vector; memset(d.mask, 0, sizeof(d.mask)); memcpy(d.mask, mask, min(sizeof(d.mask), sizeof(cpumask_t))); - trace_var(event, 1, sizeof(d), &d); + __trace_var(event, 1, sizeof(d), &d); } static int __init __bind_irq_vector(int irq, int vector, const cpumask_t *cpu_mask) @@ -804,23 +808,54 @@ void alloc_direct_apic_vector( spin_unlock(&lock); } +static inline void trace_irq_handled(int irq, uint64_t time) +{ + struct __packed { + int32_t irq; + uint64_t time; + } d; + + if ( likely(!tb_init_done) ) + return; + + d.irq = irq; + d.time = time; + __trace_var(TRC_HW_IRQ_HANDLED, 0, sizeof(d), &d); +} + void do_IRQ(struct cpu_user_regs *regs) { struct irqaction *action; - uint32_t tsc_in; - struct irq_desc *desc; + uint64_t tsc_in = 0; + struct irq_desc *desc = NULL; unsigned int vector = (u8)regs->entry_vector; int irq = __get_cpu_var(vector_irq[vector]); struct cpu_user_regs *old_regs = set_irq_regs(regs); perfc_incr(irqs); this_cpu(irq_count)++; + TRACE_1D(TRC_HW_IRQ_ENTER, irq); irq_enter(); - if (irq < 0) { - if (direct_apic_vector[vector] != NULL) { + if (irq < 0) + { + if (direct_apic_vector[vector] != NULL) + { + if ( unlikely(tb_init_done) ) + { + struct __packed { + uint32_t vec; + uint64_t handler; + } d; + + d.vec = vector; + d.handler = (uint64_t)direct_apic_vector[vector]; + __trace_var(TRC_HW_IRQ_DIRECT_VECTOR, 0, sizeof(d), &d); + } (*direct_apic_vector[vector])(regs); - } else { + } + else + { const char *kind = ", LAPIC"; if ( apic_isr_read(vector) ) @@ -884,9 +919,13 @@ void do_IRQ(struct cpu_user_regs *regs) desc->rl_quantum_start = now; } - tsc_in = tb_init_done ? get_cycles() : 0; + if ( unlikely(tb_init_done) ) + { + __trace_var(TRC_HW_IRQ_GUEST, 0, sizeof(irq), &irq); + tsc_in = get_cycles(); + } __do_IRQ_guest(irq); - TRACE_3D(TRC_HW_IRQ_HANDLED, irq, tsc_in, get_cycles()); + trace_irq_handled(irq, get_cycles() - tsc_in); goto out_no_end; } @@ -907,9 +946,10 @@ void do_IRQ(struct cpu_user_regs *regs) { desc->status &= ~IRQ_PENDING; spin_unlock_irq(&desc->lock); - tsc_in = tb_init_done ? get_cycles() : 0; + if ( unlikely(tb_init_done) ) + tsc_in = get_cycles(); action->handler(irq, action->dev_id, regs); - TRACE_3D(TRC_HW_IRQ_HANDLED, irq, tsc_in, get_cycles()); + trace_irq_handled(irq, get_cycles() - tsc_in); spin_lock_irq(&desc->lock); } @@ -922,6 +962,7 @@ void do_IRQ(struct cpu_user_regs *regs) spin_unlock(&desc->lock); out_no_unlock: irq_exit(); + TRACE_3D(TRC_HW_IRQ_EXIT, irq, desc == NULL ? -1 : desc->status, in_irq()); set_irq_regs(old_regs); } diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h index 7f2e891..f66a7af 100644 --- a/xen/include/public/trace.h +++ b/xen/include/public/trace.h @@ -271,6 +271,10 @@ #define TRC_HW_IRQ_ASSIGN_VECTOR (TRC_HW_IRQ + 0x6) #define TRC_HW_IRQ_UNMAPPED_VECTOR (TRC_HW_IRQ + 0x7) #define TRC_HW_IRQ_HANDLED (TRC_HW_IRQ + 0x8) +#define TRC_HW_IRQ_DIRECT_VECTOR (TRC_HW_IRQ + 0x9) +#define TRC_HW_IRQ_ENTER (TRC_HW_IRQ + 0xA) +#define TRC_HW_IRQ_GUEST (TRC_HW_IRQ + 0xB) +#define TRC_HW_IRQ_EXIT (TRC_HW_IRQ + 0xC) /* * Event Flags