Received: by 2002:a25:1506:0:0:0:0:0 with SMTP id 6csp466507ybv; Thu, 13 Feb 2020 04:00:19 -0800 (PST) X-Google-Smtp-Source: APXvYqz5EAhCMXieXZEZbOeMlK7cPKbZ4pqNgAlTMcOg7o2YtfhxRkngHhNVtI0sOqZgX/0WU/ZY X-Received: by 2002:a9d:1284:: with SMTP id g4mr6215076otg.47.1581595219745; Thu, 13 Feb 2020 04:00:19 -0800 (PST) ARC-Seal: i=1; a=rsa-sha256; t=1581595219; cv=none; d=google.com; s=arc-20160816; b=oGYu7/eJPcE/KCjrMRyiHwqj2jK3bVCC4AtKUQhuVgku0j5Km/BfWcp0hE609ySaEy HSQOB4GA5nKHU7kU58JbZfi4atQ667dVBTIoTpIBIHA9MiXrEZX6pU/IN4+WVSMTM3nn h7cEkaHeDRmZ2DsfO5rIEwsHo3m6cveB2wqVRCMoJ1fP/Sk6Hiy9O2sQUI1bg/E5xR+A Cqufv7VnCClAISftIufIhhtAshRTbu0j5iXSoCoaCaN+AwzMnqSxNxJEo3CjTh0Oy8xm Na+HgXD3HAN2nwFmDlMPygon7EdE/RxXCksSwe6Fb8DBQX0cn3YgGOoFvRgkOWt6ES1Z 4mXQ== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:sender:user-agent:in-reply-to :content-disposition:mime-version:references:message-id:subject:cc :to:from:date:dkim-signature; bh=xnv9vcJaJ4RlveRKToDkYvSVpq7pujagpdh/v4epNFU=; b=YlRNCYrs0oiK37c1nS66ZXFD+SSIFqkig/uK/X/2gRPYHRq/GAIqjMXF2W0b+V2WFB oxxfw+hjwd/fIBYOV2Mm6Qsekf7y8RfzmKD1KcNUEH3kAeTpfYvmXI0bEja+jPTXDg7U BUMyI5pXJI4kC01yzr0ty14a5+YDhZ0mAOLTLkD2Cx2NTWloy1R+KDF1f2lVA057oJQX CQfTsz3ryPTvoK8k3I+bGORtuS/z/LoGmJrZG/qScro98x0Fuw/yaHvhMOBAKPRoqyCy sy3b1m0A4jtrAQyIS1nA2qOxKmP4dUctNFcjBwSS47F91fysMZJ3Ae8CjWVhVH/rGVLL kmiQ== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@gmail.com header.s=20161025 header.b=MvgDCrN6; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=QUARANTINE dis=NONE) header.from=gmail.com Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id x16si1066763otk.13.2020.02.13.04.00.06; Thu, 13 Feb 2020 04:00:19 -0800 (PST) Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67; Authentication-Results: mx.google.com; dkim=pass header.i=@gmail.com header.s=20161025 header.b=MvgDCrN6; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=QUARANTINE dis=NONE) header.from=gmail.com Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1729880AbgBMMAB (ORCPT + 99 others); Thu, 13 Feb 2020 07:00:01 -0500 Received: from mail-pj1-f65.google.com ([209.85.216.65]:55035 "EHLO mail-pj1-f65.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729531AbgBMMAB (ORCPT ); Thu, 13 Feb 2020 07:00:01 -0500 Received: by mail-pj1-f65.google.com with SMTP id dw13so2292970pjb.4 for ; Thu, 13 Feb 2020 04:00:00 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=date:from:to:cc:subject:message-id:references:mime-version :content-disposition:in-reply-to:user-agent; bh=xnv9vcJaJ4RlveRKToDkYvSVpq7pujagpdh/v4epNFU=; b=MvgDCrN6Rt30rPxtVLP6viebK9w3JJ359bCVm42oY401byO1RpR1SfyVW1fORNChy1 xT/CgOuKHsn6gU8qSn7pR9o/y3HRWLevdwEi2DUcq5eMtUDU2e/lPsnhYUVtuSl33wxu 68DxPa+lSNwqgFHa5SqImkj1C0tHnulKnghv0fHz4C0fu3X8wK6nm8K4eXlXZG8BPBur U80udLDF2WT2KWlw11aajMcdsVwgrbIKjY+hsUlVG6fsjDQ/+GfLD20lMPms5wj65cAP FBZ/40HMh/Ma9CIqfqWVL0tjQCpK/PrIm5P8ApVcMMqYMlBqXjdzuTUg7qkp0tQ8Fz7z yLeQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:date:from:to:cc:subject:message-id:references :mime-version:content-disposition:in-reply-to:user-agent; bh=xnv9vcJaJ4RlveRKToDkYvSVpq7pujagpdh/v4epNFU=; b=tKksojxykBE5tfp8h0weUH8lyavc0hlRwnK9YU1Mf1ORWt27BdIasfPNLiWB8kNNbM rt7Rg4hVMHU9OM8mb1ItMVQqh95UhHmSBMrok15EyzmIvO4AAx0x4ifIVQULfgo7OoqH 1YxAH1ax42aVAUIfoByUtZD8dNQSQMPd1IVo1Ex+4fLu3aUYOF7wmVJB13DizYYnPQg4 VV2gXibCUi9Dmr+Vy0GrTKlZAXhiNgF8cOlcYuPKyj8DrXkVFAnW6FzgwIDofCG/Lc5U beAI0qTodkRkhNHZ0523AFqjUwFW09wgOZEgApsdnaTVWvPggucJUyPmZG5Ri88D6Dl8 6/RQ== X-Gm-Message-State: APjAAAVJHdy9T2cjZkWkReqKQExtGPCf95ahVHF6AXRxdUNDmpHH2KSG mEXOYMhiP9tBnP3y3e3SxAw= X-Received: by 2002:a17:90a:8a8f:: with SMTP id x15mr4879055pjn.87.1581595200123; Thu, 13 Feb 2020 04:00:00 -0800 (PST) Received: from localhost ([2401:fa00:8f:203:5bbb:c872:f2b1:f53b]) by smtp.gmail.com with ESMTPSA id e4sm2797045pgg.94.2020.02.13.03.59.58 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 13 Feb 2020 03:59:59 -0800 (PST) Date: Thu, 13 Feb 2020 20:59:57 +0900 From: Sergey Senozhatsky To: John Ogness Cc: Sergey Senozhatsky , Petr Mladek , Peter Zijlstra , Sergey Senozhatsky , Steven Rostedt , Linus Torvalds , Greg Kroah-Hartman , Andrea Parri , Thomas Gleixner , kexec@lists.infradead.org, linux-kernel@vger.kernel.org Subject: Re: [PATCH 2/2] printk: use the lockless ringbuffer Message-ID: <20200213115957.GC36551@google.com> References: <20200128161948.8524-1-john.ogness@linutronix.de> <20200128161948.8524-3-john.ogness@linutronix.de> <20200213090757.GA36551@google.com> <87v9oarfg4.fsf@linutronix.de> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <87v9oarfg4.fsf@linutronix.de> User-Agent: Mutt/1.10.1 (2018-07-13) Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On (20/02/13 10:42), John Ogness wrote: > On 2020-02-13, Sergey Senozhatsky wrote: > >> - while (user->seq == log_next_seq) { > >> + if (!prb_read_valid(prb, user->seq, r)) { > >> if (file->f_flags & O_NONBLOCK) { > >> ret = -EAGAIN; > >> logbuf_unlock_irq(); > >> @@ -890,30 +758,26 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf, > >> > >> logbuf_unlock_irq(); > >> ret = wait_event_interruptible(log_wait, > >> - user->seq != log_next_seq); > >> + prb_read_valid(prb, user->seq, r)); > >> if (ret) > >> goto out; > >> logbuf_lock_irq(); > >> } > >> > >> - if (user->seq < log_first_seq) { > >> - /* our last seen message is gone, return error and reset */ > >> - user->idx = log_first_idx; > >> - user->seq = log_first_seq; > >> + if (user->seq < r->info->seq) { > >> + /* the expected message is gone, return error and reset */ > >> + user->seq = r->info->seq; > >> ret = -EPIPE; > >> logbuf_unlock_irq(); > >> goto out; > >> } > > > > Sorry, why doesn't this do something like > > > > if (user->seq < prb_first_seq(prb)) { > > /* the expected message is gone, return error and reset */ > > user->seq = prb_first_seq(prb); > > ret = -EPIPE; > > ... > > } > > Here prb_read_valid() was successful, so a record _was_ read. The > kerneldoc for the prb_read_valid() says: Hmm, yeah. That's true. OK, something weird... I ran some random printk-pressure test (mostly printks from IRQs; + some NMI printk-s, but they are routed through nmi printk-safe buffers; + some limited number of printk-safe printk-s, routed via printk-safe buffer (so, once again, IRQ); + user-space journalctl -f syslog reader), and after the test 'cat /dev/kmsg' is terminally broken [..] cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe cat /dev/kmsg cat: /dev/kmsg: Broken pipe [..] dmesg works. Reading from /dev/kmsg - doesn't; it did work, however, before the test. So I printed seq numbers from devksmg read to a seq buffer and dumped it via procfs, just seq numbers before we adjust user->seq (set to r->seq) and after + offt += snprintf(BUF + offt, + sizeof(BUF) - offt, + "%s: devkmsg_read() error %llu %llu %llu\n", + current->comm, + user->seq, + r->info->seq, + prb_first_seq(prb)); ... systemd-journal: devkmsg_read() error 1979235 1979236 1979236 systemd-journal: corrected seq 1979236 1979236 systemd-journal: devkmsg_read() error 1979237 1979243 1979243 systemd-journal: corrected seq 1979243 1979243 systemd-journal: devkmsg_read() error 1979244 1979250 1979250 systemd-journal: corrected seq 1979250 1979250 systemd-journal: devkmsg_read() error 1979251 1979257 1979257 systemd-journal: corrected seq 1979257 1979257 systemd-journal: devkmsg_read() error 1979258 1979265 1979265 systemd-journal: corrected seq 1979265 1979265 systemd-journal: devkmsg_read() error 1979266 1979272 1979272 systemd-journal: corrected seq 1979272 1979272 systemd-journal: devkmsg_read() error 1979272 1979273 1979273 systemd-journal: corrected seq 1979273 1979273 systemd-journal: devkmsg_read() error 1979274 1979280 1979280 systemd-journal: corrected seq 1979280 1979280 systemd-journal: devkmsg_read() error 1979281 1982465 1980933 systemd-journal: corrected seq 1982465 1982465 cat: devkmsg_read() error 1980987 1982531 1980987 cat: corrected seq 1982531 1982531 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981015 1982563 1981015 cat: corrected seq 1982563 1982563 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981080 1982633 1981080 cat: corrected seq 1982633 1982633 cat: devkmsg_read() error 1981095 1982652 1981095 cat: corrected seq 1982652 1982652 cat: devkmsg_read() error 1981095 1982652 1981095 cat: corrected seq 1982652 1982652 cat: devkmsg_read() error 1981095 1982652 1981095 cat: corrected seq 1982652 1982652 cat: devkmsg_read() error 1981095 1982652 1981095 cat: corrected seq 1982652 1982652 cat: devkmsg_read() error 1981095 1982652 1981095 cat: corrected seq 1982652 1982652 cat: devkmsg_read() error 1981095 1982652 1981095 cat: corrected seq 1982652 1982652 cat: devkmsg_read() error 1981095 1982652 1981095 cat: corrected seq 1982652 1982652 ... What's up with that user->seq counter? -ss