From patchwork Thu Sep 5 11:39:55 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: =?utf-8?b?SsO8cmdlbiBHcm/Dnw==?= X-Patchwork-Id: 11132813 Return-Path: Received: from mail.kernel.org (pdx-korg-mail-1.web.codeaurora.org [172.30.200.123]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 8F4D516B1 for ; Thu, 5 Sep 2019 11:41:33 +0000 (UTC) Received: from lists.xenproject.org (lists.xenproject.org [192.237.175.120]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 69D0022CF7 for ; Thu, 5 Sep 2019 11:41:33 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 69D0022CF7 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=suse.com Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=xen-devel-bounces@lists.xenproject.org Received: from localhost ([127.0.0.1] helo=lists.xenproject.org) by lists.xenproject.org with esmtp (Exim 4.89) (envelope-from ) id 1i5q7h-0001mF-1l; Thu, 05 Sep 2019 11:40:21 +0000 Received: from all-amaz-eas1.inumbo.com ([34.197.232.57] helo=us1-amaz-eas2.inumbo.com) by lists.xenproject.org with esmtp (Exim 4.89) (envelope-from ) id 1i5q7g-0001lu-DA for xen-devel@lists.xenproject.org; Thu, 05 Sep 2019 11:40:20 +0000 X-Inumbo-ID: e4783720-cfd1-11e9-abc8-12813bfff9fa Received: from mx1.suse.de (unknown [195.135.220.15]) by us1-amaz-eas2.inumbo.com (Halon) with ESMTPS id e4783720-cfd1-11e9-abc8-12813bfff9fa; Thu, 05 Sep 2019 11:40:00 +0000 (UTC) X-Virus-Scanned: by amavisd-new at test-mx.suse.de Received: from relay2.suse.de (unknown [195.135.220.254]) by mx1.suse.de (Postfix) with ESMTP id A11E9AF05; Thu, 5 Sep 2019 11:39:59 +0000 (UTC) From: Juergen Gross To: xen-devel@lists.xenproject.org Date: Thu, 5 Sep 2019 13:39:55 +0200 Message-Id: <20190905113955.24870-5-jgross@suse.com> X-Mailer: git-send-email 2.16.4 In-Reply-To: <20190905113955.24870-1-jgross@suse.com> References: <20190905113955.24870-1-jgross@suse.com> Subject: [Xen-devel] [PATCH v5 4/4] xen: add per-cpu buffer option to debugtrace X-BeenThere: xen-devel@lists.xenproject.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Xen developer discussion List-Unsubscribe: , List-Post: List-Help: List-Subscribe: , Cc: Juergen Gross , Stefano Stabellini , Wei Liu , Konrad Rzeszutek Wilk , George Dunlap , Andrew Cooper , Ian Jackson , Tim Deegan , Julien Grall , Jan Beulich MIME-Version: 1.0 Errors-To: xen-devel-bounces@lists.xenproject.org Sender: "Xen-devel" debugtrace is normally writing trace entries into a single trace buffer. There are cases where this is not optimal, e.g. when hunting a bug which requires writing lots of trace entries and one cpu is stuck. This will result in other cpus filling the trace buffer and finally overwriting the interesting trace entries of the hanging cpu. In order to be able to debug such situations add the capability to use per-cpu trace buffers. This can be selected by specifying the debugtrace boot parameter with the modifier "cpu:", like: debugtrace=cpu:16 At the same time switch the parsing function to accept size modifiers (e.g. 4M or 1G). Printing out the trace entries is done for each buffer in order to minimize the effort needed during printing. As each entry is prefixed with its sequence number sorting the entries can easily be done when analyzing them. Signed-off-by: Juergen Gross Reviewed-by: Jan Beulich --- V2: - only allocate buffer if not already done so V4: - unsigned int -> unsigned long (Jan Beulich) - replace check for bytes < PAGE_SIZE by !bytes (Jan Beulich) - print info which buffer allocation failed (Jan Beulich) - replace switch by if in cpu notifier handler (Jan Beulich) V5: - don't silently ignore trailing characters when parsing buffer size (Jan Beulich) - limit scope of some variables (Jan Beulich) - adjust error message format (Jan Beulich) --- docs/misc/xen-command-line.pandoc | 7 +- xen/common/debugtrace.c | 159 +++++++++++++++++++++++++++++--------- 2 files changed, 126 insertions(+), 40 deletions(-) diff --git a/docs/misc/xen-command-line.pandoc b/docs/misc/xen-command-line.pandoc index 7c72e31032..832797e2e2 100644 --- a/docs/misc/xen-command-line.pandoc +++ b/docs/misc/xen-command-line.pandoc @@ -644,12 +644,13 @@ over the PCI busses sequentially) or by PCI device (must be on segment 0). Limits the number lines printed in Xen stack traces. ### debugtrace -> `= ` +> `= [cpu:]` > Default: `128` -Specify the size of the console debug trace buffer in KiB. The debug -trace feature is only enabled in debugging builds of Xen. +Specify the size of the console debug trace buffer. By specifying `cpu:` +additionally a trace buffer of the specified size is allocated per cpu. +The debug trace feature is only enabled in debugging builds of Xen. ### dma_bits > `= ` diff --git a/xen/common/debugtrace.c b/xen/common/debugtrace.c index 0eeb1a77c5..3467fc7363 100644 --- a/xen/common/debugtrace.c +++ b/xen/common/debugtrace.c @@ -6,6 +6,7 @@ #include +#include #include #include #include @@ -26,34 +27,74 @@ struct debugtrace_data { }; static struct debugtrace_data *dt_data; +static DEFINE_PER_CPU(struct debugtrace_data *, dt_cpu_data); -static unsigned int debugtrace_kilobytes = 128; +static unsigned long debugtrace_bytes = 128 << 10; +static bool debugtrace_per_cpu; static bool debugtrace_used; static char debugtrace_last_entry_buf[DEBUG_TRACE_ENTRY_SIZE]; static DEFINE_SPINLOCK(debugtrace_lock); -integer_param("debugtrace", debugtrace_kilobytes); -static void debugtrace_dump_worker(void) +static int __init debugtrace_parse_param(const char *s) { - if ( !debugtrace_used ) + unsigned long bytes; + + if ( !strncmp(s, "cpu:", 4) ) + { + debugtrace_per_cpu = true; + s += 4; + } + bytes = parse_size_and_unit(s, &s); + + if ( *s ) + return -EINVAL; + + debugtrace_bytes = bytes; + + return 0; +} +custom_param("debugtrace", debugtrace_parse_param); + +static void debugtrace_dump_buffer(struct debugtrace_data *data, + const char *which) +{ + if ( !data ) return; - printk("debugtrace_dump() starting\n"); + printk("debugtrace_dump() %s buffer starting\n", which); /* Print oldest portion of the ring. */ - if ( dt_data->buf[dt_data->prd] != '\0' ) - console_serial_puts(&dt_data->buf[dt_data->prd], - dt_data->bytes - dt_data->prd); + if ( data->buf[data->prd] != '\0' ) + console_serial_puts(&data->buf[data->prd], data->bytes - data->prd); /* Print youngest portion of the ring. */ - dt_data->buf[dt_data->prd] = '\0'; - console_serial_puts(&dt_data->buf[0], dt_data->prd); + data->buf[data->prd] = '\0'; + console_serial_puts(&data->buf[0], data->prd); - memset(dt_data->buf, '\0', dt_data->bytes); - dt_data->prd = 0; - debugtrace_last_entry_buf[0] = 0; + memset(data->buf, '\0', data->bytes); + data->prd = 0; + + printk("debugtrace_dump() %s buffer finished\n", which); +} + +static void debugtrace_dump_worker(void) +{ + unsigned int cpu; + + if ( !debugtrace_used ) + return; + + debugtrace_dump_buffer(dt_data, "global"); - printk("debugtrace_dump() finished\n"); + for ( cpu = 0; cpu < nr_cpu_ids; cpu++ ) + { + char buf[16]; + + snprintf(buf, sizeof(buf), "cpu %u", cpu); + debugtrace_dump_buffer(per_cpu(dt_cpu_data, cpu), buf); + } + + debugtrace_last_entry_buf[0] = 0; } static void debugtrace_toggle(void) @@ -93,28 +134,33 @@ void debugtrace_dump(void) static void debugtrace_add_to_buf(char *buf) { + struct debugtrace_data *data; char *p; + data = debugtrace_per_cpu ? this_cpu(dt_cpu_data) : dt_data; + for ( p = buf; *p != '\0'; p++ ) { - dt_data->buf[dt_data->prd++] = *p; - if ( dt_data->prd == dt_data->bytes ) - dt_data->prd = 0; + data->buf[data->prd++] = *p; + if ( data->prd == data->bytes ) + data->prd = 0; } } void debugtrace_printk(const char *fmt, ...) { static char buf[DEBUG_TRACE_ENTRY_SIZE]; - static unsigned int count, last_count; + static unsigned int count, last_count, last_cpu; static unsigned long last_prd; char cntbuf[24]; va_list args; unsigned long flags; unsigned int nr; + struct debugtrace_data *data; - if ( !dt_data ) + data = debugtrace_per_cpu ? this_cpu(dt_cpu_data) : dt_data; + if ( !data ) return; debugtrace_used = true; @@ -134,16 +180,19 @@ void debugtrace_printk(const char *fmt, ...) } else { - if ( strcmp(buf, debugtrace_last_entry_buf) ) + unsigned int cpu = debugtrace_per_cpu ? smp_processor_id() : 0; + + if ( strcmp(buf, debugtrace_last_entry_buf) || cpu != last_cpu ) { - last_prd = dt_data->prd; + last_prd = data->prd; last_count = ++count; + last_cpu = cpu; safe_strcpy(debugtrace_last_entry_buf, buf); snprintf(cntbuf, sizeof(cntbuf), "%u ", count); } else { - dt_data->prd = last_prd; + data->prd = last_prd; snprintf(cntbuf, sizeof(cntbuf), "%u-%u ", last_count, ++count); } debugtrace_add_to_buf(cntbuf); @@ -158,34 +207,70 @@ static void debugtrace_key(unsigned char key) debugtrace_toggle(); } -static int __init debugtrace_init(void) +static void debugtrace_alloc_buffer(struct debugtrace_data **ptr, + unsigned int cpu) { int order; - unsigned long kbytes, bytes; struct debugtrace_data *data; - /* Round size down to next power of two. */ - while ( (kbytes = (debugtrace_kilobytes & (debugtrace_kilobytes-1))) != 0 ) - debugtrace_kilobytes = kbytes; - - bytes = debugtrace_kilobytes << 10; - if ( bytes == 0 ) - return 0; + if ( !debugtrace_bytes || *ptr ) + return; - order = get_order_from_bytes(bytes); + order = get_order_from_bytes(debugtrace_bytes); data = alloc_xenheap_pages(order, 0); if ( !data ) - return -ENOMEM; + { + if ( debugtrace_per_cpu ) + printk("CPU%u: failed to allocate debugtrace buffer\n", cpu); + else + printk("failed to allocate debugtrace buffer\n"); + return; + } + + debugtrace_bytes = PAGE_SIZE << order; + memset(data, '\0', debugtrace_bytes); + data->bytes = debugtrace_bytes - sizeof(*data); - bytes = PAGE_SIZE << order; - memset(data, '\0', bytes); + *ptr = data; +} + +static int debugtrace_cpu_callback(struct notifier_block *nfb, + unsigned long action, void *hcpu) +{ + unsigned int cpu = (unsigned long)hcpu; - data->bytes = bytes - sizeof(*data); - dt_data = data; + /* Buffers are only ever allocated, never freed. */ + if ( action == CPU_UP_PREPARE ) + debugtrace_alloc_buffer(&per_cpu(dt_cpu_data, cpu), cpu); + + return 0; +} + +static struct notifier_block debugtrace_nfb = { + .notifier_call = debugtrace_cpu_callback +}; + +static int __init debugtrace_init(void) +{ + unsigned long bytes; + unsigned int cpu; + + /* Round size down to next power of two. */ + while ( (bytes = (debugtrace_bytes & (debugtrace_bytes - 1))) != 0 ) + debugtrace_bytes = bytes; register_keyhandler('T', debugtrace_key, "toggle debugtrace to console/buffer", 0); + if ( debugtrace_per_cpu ) + { + for_each_online_cpu ( cpu ) + debugtrace_alloc_buffer(&per_cpu(dt_cpu_data, cpu), cpu); + register_cpu_notifier(&debugtrace_nfb); + } + else + debugtrace_alloc_buffer(&dt_data, 0); + return 0; } __initcall(debugtrace_init);