From patchwork Tue Dec 19 14:32:43 2023 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steven Rostedt X-Patchwork-Id: 181031 Return-Path: Delivered-To: ouuuleilei@gmail.com Received: by 2002:a05:7300:24d3:b0:fb:cd0c:d3e with SMTP id r19csp1991980dyi; Tue, 19 Dec 2023 06:55:22 -0800 (PST) X-Google-Smtp-Source: AGHT+IED3mnoNVnk9Lj7MFMmH/fzER2NgvChGhyxmp63u/0uUJ4SbofEEFFzgFE/W0lfcD+4JjWn X-Received: by 2002:a05:6e02:12c4:b0:35f:b33b:cb97 with SMTP id i4-20020a056e0212c400b0035fb33bcb97mr3652188ilm.39.1702997722572; Tue, 19 Dec 2023 06:55:22 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1702997722; cv=none; d=google.com; s=arc-20160816; b=ZoUB6dRae99TsdWjYiuQ5oY4l6nsxHObZiFOAZzuaEs14GsUXIp3IX1cQZ4vHYNH7z zL2Jyy+vE1Iu4ELINNFOsmc8NDcG/s28CzMopaqNBTEpcTLRoKGSMWiFpkwXwtMb9cKU ZBbjz6OdlL3yiEJTNp424ftnKIpyqIqPdkOtjMWsq6iuRVPIdmsfbtDO0f4Up2rHFUUK DmiH0aFgDcXAJjbdZjDIltXWVEIYamf2SUVE9JPr4n241Nq0Wx1bdbBAen5e1MRWOlPQ LFC9b4Gr1t+sSmrS5vcf1CXhYhb/oCK17Zu/GcJGk1ZpyuLkzY7LE7tZiXNxh51JyUV+ 9a9Q== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=mime-version:list-unsubscribe:list-subscribe:list-id:precedence :references:subject:cc:to:from:date:user-agent:message-id; bh=4b6ntQA4NSK4+vvJGujnHgRB8A1dWt2OJG2xl7E8Aow=; fh=mTYg3JJ8i2GBNLFt8qb4bgYwOyk0kmrOzICLbi6qJ1c=; b=egHZg5fT21BkWdT1iu1l5Wc5rkMr1Bc1Cix81m/YtBbrAJ7eFCdNi+XHVf8EsZ989O Qu/im3fxOoASVGsMUKJBL7QZuKm+2+CIBgkY42m2UC/xXUtr85lPPs1BX9bvPg5LIOij fUXbWVX/zWVY0tXMSASLQWoc0Cgoet6qkALx/LuhBEXbDjBl5Gsrb04E1iHvscwEPGBj iNY0cbvCX+KjTOp7Amxk+fsrvlUsfcfiZJKxB2vQDmr+FOhxxNnmdgHYFpcXLArtZwX1 QuhsTUVIY6eFC91aEfmIWxqqb6ZVSAs1/0/Hy2wBtuSjuDa/3MFYONLSas6qzgrpt2c2 gVWw== ARC-Authentication-Results: i=1; mx.google.com; spf=pass (google.com: domain of linux-kernel+bounces-5385-ouuuleilei=gmail.com@vger.kernel.org designates 2604:1380:45e3:2400::1 as permitted sender) smtp.mailfrom="linux-kernel+bounces-5385-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 q8-20020a632a08000000b005c69365abadsi5303759pgq.499.2023.12.19.06.55.22 for (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Tue, 19 Dec 2023 06:55:22 -0800 (PST) Received-SPF: pass (google.com: domain of linux-kernel+bounces-5385-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-5385-ouuuleilei=gmail.com@vger.kernel.org designates 2604:1380:45e3:2400::1 as permitted sender) smtp.mailfrom="linux-kernel+bounces-5385-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 5769328A534 for ; Tue, 19 Dec 2023 14:36:39 +0000 (UTC) Received: from localhost.localdomain (localhost.localdomain [127.0.0.1]) by smtp.subspace.kernel.org (Postfix) with ESMTP id 8D48720B10; Tue, 19 Dec 2023 14:32:06 +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 D95992629C for ; Tue, 19 Dec 2023 14:32:02 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id BDDF6C433C9; Tue, 19 Dec 2023 14:32:02 +0000 (UTC) Received: from rostedt by gandalf with local (Exim 4.97) (envelope-from ) id 1rFb9Z-00000003MIS-3kKA; Tue, 19 Dec 2023 09:33:01 -0500 Message-ID: <20231219143301.661736978@goodmis.org> User-Agent: quilt/0.67 Date: Tue, 19 Dec 2023 09:32:43 -0500 From: Steven Rostedt To: linux-kernel@vger.kernel.org Cc: Masami Hiramatsu , Mark Rutland , Mathieu Desnoyers , Andrew Morton Subject: [for-next][PATCH 10/10] ring-buffer: Check if absolute timestamp goes backwards References: <20231219143233.204534014@goodmis.org> 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: 1785722539628126093 X-GMAIL-MSGID: 1785722539628126093 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. Link: https://lore.kernel.org/linux-trace-kernel/20231219074732.18b092d4@gandalf.local.home Cc: Masami Hiramatsu Cc: Mark Rutland Cc: Mathieu Desnoyers 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));