From patchwork Mon Dec 18 22:01:06 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 180666 Return-Path: Delivered-To: ouuuleilei@gmail.com Received: by 2002:a05:7300:24d3:b0:fb:cd0c:d3e with SMTP id r19csp1557518dyi; Mon, 18 Dec 2023 14:00:37 -0800 (PST) X-Google-Smtp-Source: AGHT+IGlfSW76ziXNewzU1TzvjzP775/OQaEC6KSOHa2xAoNRW+pa2rJ5mTRsoT/rHN4qSCLPNp2 X-Received: by 2002:a05:6358:7e42:b0:170:c36a:a2bb with SMTP id p2-20020a0563587e4200b00170c36aa2bbmr10395239rwm.17.1702936836979; Mon, 18 Dec 2023 14:00:36 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1702936836; cv=none; d=google.com; s=arc-20160816; b=CYFYn8bze96tdZCj5atIUXJRoQd7VJciGA4oOwZpi17ZyWLf+YqshDtn9y+9Ag4ttT IP3KWn3RRcBPXiO+dKythB4dXvfGn7CcDV1ofc0zoifWTBZLCJYYJucgnLbg7ViX3UbM fJaK1DhSfw7EPKa+YgtdzyM5ohYatJgwSKEfKcB1kgS2gRJ0FxAcfGcUKARZKqVm7P/8 mq18j6jPc5YH0fBKcr3rveE/bIeBpsKmf0MeJVkV1ZguOR6etsJNXYZMlmYOq5Musa79 LoWZG0i+aP0kpAYQXyUpyp4gyfCaN7Q7WR/UUOKZ0l2V/n7gxQs9KozjcsV1j34sFlua 2UmQ== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=content-transfer-encoding:mime-version:list-unsubscribe :list-subscribe:list-id:precedence:message-id:subject:cc:to:from :date; bh=hAORJLA5wu8ANqpujf3B0vN/kqKU/V1jCq3KooqEKak=; fh=S/OrYSeOA1aSrBSqnLKrkyLzV3RDOIc0IFkfjbF7p6w=; b=DM3sckjkMuqQJXeMK6CWv5VYh/VAeo0fqTUiYny7+4CUww5rnpiDLY8Xm9W/tsZtR9 ECqozafm0SEpC1DgujxVjwL0J+pjxL4fTJaWSlW8ka4ljz5msTlm1wY/IBw0/rbnC4vI ZjKUu11+dRcWSlRwj5d9gC4XPAIx/9OR9FsLEpFwKpA90YHjcC2+5YLc3Rrtai1nDr4d IBZuQkAiwYik2OnL63BRGjCei7mOt7zd5qfikAy/3wYkn9EHF4E/YzSYGJcnwR4dK98W G58Py8P7nyjlo01ySsnQ/K/OVTRf8rlnxn9X41iYXXGDXnkYRaJkxMiX8Zwsq/EY+xsh ljrg== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel+bounces-4434-ouuuleilei=gmail.com@vger.kernel.org designates 147.75.48.161 as permitted sender) smtp.mailfrom="linux-kernel+bounces-4434-ouuuleilei=gmail.com@vger.kernel.org" Received: from sy.mirrors.kernel.org (sy.mirrors.kernel.org. [147.75.48.161]) by mx.google.com with ESMTPS id g4-20020aa78744000000b006d44cf230b2si4069474pfo.138.2023.12.18.14.00.36 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Mon, 18 Dec 2023 14:00:36 -0800 (PST) Received-SPF: pass (google.com: domain of linux-kernel+bounces-4434-ouuuleilei=gmail.com@vger.kernel.org designates 147.75.48.161 as permitted sender) client-ip=147.75.48.161; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-kernel+bounces-4434-ouuuleilei=gmail.com@vger.kernel.org designates 147.75.48.161 as permitted sender) smtp.mailfrom="linux-kernel+bounces-4434-ouuuleilei=gmail.com@vger.kernel.org" Received: from smtp.subspace.kernel.org (wormhole.subspace.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by sy.mirrors.kernel.org (Postfix) with ESMTPS id 0B5AAB23CC1 for ; Mon, 18 Dec 2023 22:00:28 +0000 (UTC) Received: from localhost.localdomain (localhost.localdomain [127.0.0.1]) by smtp.subspace.kernel.org (Postfix) with ESMTP id 6D28F74E13; Mon, 18 Dec 2023 22:00:12 +0000 (UTC) X-Original-To: linux-kernel@vger.kernel.org Received: from smtp.kernel.org (aws-us-west-2-korg-mail-1.web.codeaurora.org [10.30.226.201]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id E79FF73460; Mon, 18 Dec 2023 22:00:10 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 07C78C433C9; Mon, 18 Dec 2023 22:00:09 +0000 (UTC) Date: Mon, 18 Dec 2023 17:01:06 -0500 From: Steven Rostedt To: LKML , Linux Trace Kernel Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Joel Fernandes Subject: [PATCH v2] ring-buffer: Add interrupt information to dump of data sub-buffer Message-ID: <20231218170106.46fe24a7@gandalf.local.home> X-Mailer: Claws Mail 3.19.1 (GTK+ 2.24.33; x86_64-pc-linux-gnu) Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 X-getmail-retrieved-from-mailbox: INBOX X-GMAIL-THRID: 1785656810276250907 X-GMAIL-MSGID: 1785658696530281685 From: "Steven Rostedt (Google)" When the ring buffer timestamp verifier triggers, it dumps the content of the sub-buffer. But currently it only dumps the timestamps and the offset of the data as well as the deltas. It would be even more informative if the event data also showed the interrupt context level it was in. That is, if each event showed that the event was written in normal, softirq, irq or NMI context. Then a better idea about how the events may have been interrupted from each other. As the payload of the ring buffer is really a black box of the ring buffer, just assume that if the payload is larger than a trace entry, that it is a trace entry. As trace entries have the interrupt context information saved in a flags field, look at that location and report the output of the flags. If the payload is not a trace entry, there's no way to really know, and the information will be garbage. But that's OK, because this is for debugging only (this output is not used in production as the buffer check that calls it causes a huge overhead to the tracing). This information, when available, is crucial for debugging timestamp issues. If it's garbage, it will also be pretty obvious that its garbage too. As this output usually happens in kselftests of the tracing code, the user will know what the payload is at the time. Suggested-by: Joel Fernandes (Google) Signed-off-by: Steven Rostedt (Google) --- Changes since v1: https://lore.kernel.org/all/20231218163117.74292291@gandalf.local.home/ - Added irq context for the current context (where the warning is printed) kernel/trace/ring_buffer.c | 82 +++++++++++++++++++++++++++++++++++--- 1 file changed, 77 insertions(+), 5 deletions(-) diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c index 3eda81ed7d7e..7841d6520998 100644 --- a/kernel/trace/ring_buffer.c +++ b/kernel/trace/ring_buffer.c @@ -3225,6 +3225,76 @@ EXPORT_SYMBOL_GPL(ring_buffer_unlock_commit); #define CHECK_FULL_PAGE 1L #ifdef CONFIG_RING_BUFFER_VALIDATE_TIME_DELTAS + +static const char *show_irq_str(int bits) +{ + const char *type[] = { + ".", // 0 + "s", // 1 + "h", // 2 + "Hs", // 3 + "n", // 4 + "Ns", // 5 + "Nh", // 6 + "NHs", // 7 + }; + + return type[bits]; +} + +/* Assume this is an trace event */ +static const char *show_flags(struct ring_buffer_event *event) +{ + struct trace_entry *entry; + int bits = 0; + + if (rb_event_data_length(event) - RB_EVNT_HDR_SIZE < sizeof(*entry)) + return "X"; + + entry = ring_buffer_event_data(event); + + if (entry->flags & TRACE_FLAG_SOFTIRQ) + bits |= 1; + + if (entry->flags & TRACE_FLAG_HARDIRQ) + bits |= 2; + + if (entry->flags & TRACE_FLAG_NMI) + bits |= 4; + + return show_irq_str(bits); +} + +static const char *show_irq(struct ring_buffer_event *event) +{ + struct trace_entry *entry; + + if (rb_event_data_length(event) - RB_EVNT_HDR_SIZE < sizeof(*entry)) + return ""; + + entry = ring_buffer_event_data(event); + if (entry->flags & TRACE_FLAG_IRQS_OFF) + return "d"; + return ""; +} + +static const char *show_interrupt_level(void) +{ + unsigned long pc = preempt_count(); + unsigned char level = 0; + + if (pc & SOFTIRQ_OFFSET) + level |= 1; + + if (pc & HARDIRQ_MASK) + level |= 2; + + if (pc & NMI_MASK) + level |= 4; + + return show_irq_str(level); +} + static void dump_buffer_page(struct buffer_data_page *bpage, struct rb_event_info *info, unsigned long tail) @@ -3264,8 +3334,9 @@ static void dump_buffer_page(struct buffer_data_page *bpage, case RINGBUF_TYPE_DATA: ts += event->time_delta; - pr_warn(" 0x%x: [%lld] delta:%d\n", - e, ts, event->time_delta); + pr_warn(" 0x%x: [%lld] delta:%d %s%s\n", + e, ts, event->time_delta, + show_flags(event), show_irq(event)); break; default: @@ -3347,7 +3418,8 @@ static void check_buffer(struct ring_buffer_per_cpu *cpu_buffer, } } if ((full && ts > info->ts) || - (!full && ts + info->delta != info->ts)) { + (!full && ts + info->delta != info->ts) || + e > 0xfa0) { /* If another report is happening, ignore this one */ if (atomic_inc_return(&ts_dump) != 1) { atomic_dec(&ts_dump); @@ -3356,11 +3428,11 @@ static void check_buffer(struct ring_buffer_per_cpu *cpu_buffer, atomic_inc(&cpu_buffer->record_disabled); /* There's some cases in boot up that this can happen */ WARN_ON_ONCE(system_state != SYSTEM_BOOTING); - pr_warn("[CPU: %d]TIME DOES NOT MATCH expected:%lld actual:%lld delta:%lld before:%lld after:%lld%s\n", + pr_warn("[CPU: %d]TIME DOES NOT MATCH expected:%lld actual:%lld delta:%lld before:%lld after:%lld%s context:%s\n", cpu_buffer->cpu, ts + info->delta, info->ts, info->delta, info->before, info->after, - full ? " (full)" : ""); + full ? " (full)" : "", show_interrupt_level()); dump_buffer_page(bpage, info, tail); atomic_dec(&ts_dump); /* Do not re-enable checking */