From patchwork Tue Dec 19 12:47:32 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 180929 Return-Path: Delivered-To: ouuuleilei@gmail.com Received: by 2002:a05:7300:24d3:b0:fb:cd0c:d3e with SMTP id r19csp1920116dyi; Tue, 19 Dec 2023 05:05:12 -0800 (PST) X-Google-Smtp-Source: AGHT+IFjmYGqM2C2t04jIia9VmFfRYUTdl5N9HsPgW/xXGCdsC2Natp1cvl90Fv8q4IMmT35p6D6 X-Received: by 2002:a05:6a00:93a9:b0:6d8:2ad6:57f9 with SMTP id ka41-20020a056a0093a900b006d82ad657f9mr1814114pfb.8.1702991111883; Tue, 19 Dec 2023 05:05:11 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1702991111; cv=none; d=google.com; s=arc-20160816; b=rdtkN03otdd1L/QuvIHhNbtEn+Nt8ejHTk+FDpBT30hV5txzgFkRpYtUxQAsWh3NQc C39DyYv24DkG541rfHzs95MTUkIogXP8zTh6kQN5FxSi8wy5UUytGfeM5fz1F5iJuQGw ZN5XPp8VqgVLHWcIRPNcJj3COVGpymR1QMNZGs2p/ITLaD+j9KDr8SId/YaaMx756WFs seeM8Y0jNe1etGYPuOYjaGzKXAy5ACq3bgrEOgMp7RNMbdDxzzLlnQbGdxVHtqB23lz7 /TkO9mE+AhiWrQl8RPiLkuAAqHKptezLxSPPtRCkp6anVEcRAqSY+L5yszY1c4N9cukj fEjA== 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=Ibrs53lCXFunK32nn+1udDuPpJSdJeSIHOixvV5IJ5s=; fh=R8JZsVKDlS7lXIAvTNV55bsjlDBI0i4sqiOYXO4tZQA=; b=ZE5H8LhFuCjHgSe5DmJXgF3yPO4/kbwQW81cII/pStBEca/tS5RYS+KCZKIseo1R+j M05TYfj5TuCrmhNuI+936ECcMoOVo4JLTiXeOtixurFClUFNbLhGVxC2e/3qzS5Axl4G AVXI6qcmA+Y0RGfcYlaKhSND6bnBxwC+Cz/++Kg3wB+NcFxkiOFVKg7nMNUwNdeYSUQy Yj8cXYWNzJXw26F0cKj4/xxDRuEFTQo8hErkLxr1l9vkSV63hPTMPodD8v6oGGVnmPM/ Y28odMYh74xkwmvK2P+OESdfYnGjxDmbV1N217Zp2QhdQRbw+hkLpITqCR43NMaYTQIz Dbfg== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel+bounces-5198-ouuuleilei=gmail.com@vger.kernel.org designates 2604:1380:45e3:2400::1 as permitted sender) smtp.mailfrom="linux-kernel+bounces-5198-ouuuleilei=gmail.com@vger.kernel.org" Received: from sv.mirrors.kernel.org (sv.mirrors.kernel.org. [2604:1380:45e3:2400::1]) by mx.google.com with ESMTPS id o16-20020a056a00215000b006cb7f9ddbd5si5890977pfk.321.2023.12.19.05.05.11 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Tue, 19 Dec 2023 05:05:11 -0800 (PST) Received-SPF: pass (google.com: domain of linux-kernel+bounces-5198-ouuuleilei=gmail.com@vger.kernel.org designates 2604:1380:45e3:2400::1 as permitted sender) client-ip=2604:1380:45e3:2400::1; Authentication-Results: mx.google.com; spf=pass (google.com: domain of linux-kernel+bounces-5198-ouuuleilei=gmail.com@vger.kernel.org designates 2604:1380:45e3:2400::1 as permitted sender) smtp.mailfrom="linux-kernel+bounces-5198-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 sv.mirrors.kernel.org (Postfix) with ESMTPS id 5F30028A203 for ; Tue, 19 Dec 2023 12:48:36 +0000 (UTC) Received: from localhost.localdomain (localhost.localdomain [127.0.0.1]) by smtp.subspace.kernel.org (Postfix) with ESMTP id B776219BCB; Tue, 19 Dec 2023 12:46:37 +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 E4910199AD; Tue, 19 Dec 2023 12:46:35 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id B191AC433C7; Tue, 19 Dec 2023 12:46:34 +0000 (UTC) Date: Tue, 19 Dec 2023 07:47:32 -0500 From: Steven Rostedt To: LKML , Linux Trace Kernel Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers Subject: [PATCH] ring-buffer: Check if absolute timestamp goes backwards Message-ID: <20231219074732.18b092d4@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: 1785678528554080598 X-GMAIL-MSGID: 1785715608430672308 From: "Steven Rostedt (Google)" The check_buffer() which checks the timestamps of the ring buffer sub-buffer page, when enabled, only checks if the adding of deltas of the events from the last absolute timestamp or the timestamp of the sub-buffer page adds up to the current event. What it does not check is if the absolute timestamp causes the time of the events to go backwards, as that can cause issues elsewhere. Test for the timestamp going backwards too. This also fixes a slight issue where if the warning triggers at boot up (because of the resetting of the tsc), it will disable all further checks, even those that are after boot Have it continue checking if the warning was ignored during boot up. Signed-off-by: Steven Rostedt (Google) --- kernel/trace/ring_buffer.c | 46 +++++++++++++++++++++++--------------- 1 file changed, 28 insertions(+), 18 deletions(-) diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c index c0cc45482e1e..f7dc74e45ebf 100644 --- a/kernel/trace/ring_buffer.c +++ b/kernel/trace/ring_buffer.c @@ -3309,6 +3309,23 @@ static void dump_buffer_page(struct buffer_data_page *bpage, static DEFINE_PER_CPU(atomic_t, checking); static atomic_t ts_dump; +#define buffer_warn_return(fmt, ...) \ + do { \ + /* If another report is happening, ignore this one */ \ + if (atomic_inc_return(&ts_dump) != 1) { \ + atomic_dec(&ts_dump); \ + goto out; \ + } \ + atomic_inc(&cpu_buffer->record_disabled); \ + pr_warn(fmt, ##__VA_ARGS__); \ + dump_buffer_page(bpage, info, tail); \ + atomic_dec(&ts_dump); \ + /* There's some cases in boot up that this can happen */ \ + if (WARN_ON_ONCE(system_state != SYSTEM_BOOTING)) \ + /* Do not re-enable checking */ \ + return; \ + } while (0) + /* * Check if the current event time stamp matches the deltas on * the buffer page. @@ -3362,7 +3379,12 @@ static void check_buffer(struct ring_buffer_per_cpu *cpu_buffer, case RINGBUF_TYPE_TIME_STAMP: delta = rb_event_time_stamp(event); - ts = rb_fix_abs_ts(delta, ts); + delta = rb_fix_abs_ts(delta, ts); + if (delta < ts) { + buffer_warn_return("[CPU: %d]ABSOLUTE TIME WENT BACKWARDS: last ts: %lld absolute ts: %lld\n", + cpu_buffer->cpu, ts, delta); + } + ts = delta; break; case RINGBUF_TYPE_PADDING: @@ -3379,23 +3401,11 @@ static void check_buffer(struct ring_buffer_per_cpu *cpu_buffer, } if ((full && ts > info->ts) || (!full && ts + info->delta != info->ts)) { - /* If another report is happening, ignore this one */ - if (atomic_inc_return(&ts_dump) != 1) { - atomic_dec(&ts_dump); - goto out; - } - 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 context:%s\n", - cpu_buffer->cpu, - ts + info->delta, info->ts, info->delta, - info->before, info->after, - full ? " (full)" : "", show_interrupt_level()); - dump_buffer_page(bpage, info, tail); - atomic_dec(&ts_dump); - /* Do not re-enable checking */ - return; + buffer_warn_return("[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)" : "", show_interrupt_level()); } out: atomic_dec(this_cpu_ptr(&checking));