From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752156AbdIRAqs (ORCPT ); Sun, 17 Sep 2017 20:46:48 -0400 Received: from mail-pg0-f51.google.com ([74.125.83.51]:56823 "EHLO mail-pg0-f51.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751556AbdIRAqq (ORCPT ); Sun, 17 Sep 2017 20:46:46 -0400 X-Google-Smtp-Source: ADKCNb72J+9drgU+91evlkytmtrCcmDUC8+ENELjMCmiWO/FGHS6RMoUipicx7mGsZ54zLVqDwXliQ== Date: Mon, 18 Sep 2017 09:46:41 +0900 From: Sergey Senozhatsky To: Linus Torvalds Cc: Sergey Senozhatsky , Petr Mladek , Sergey Senozhatsky , Joe Perches , Steven Rostedt , Pavel Machek , Jan Kara , Andrew Morton , Jiri Slaby , Andreas Mohr , Tetsuo Handa , Linux Kernel Mailing List Subject: Re: printk: what is going on with additional newlines? Message-ID: <20170918004641.GA3161@jagdpanzerIV.localdomain> References: <20170830022528.GA17968@jagdpanzerIV.localdomain> <1504060296.2786.8.camel@perches.com> <20170830024703.GA17175@jagdpanzerIV.localdomain> <20170905094452.GE8741@pathway.suse.cz> <20170905095900.GC2066@jagdpanzerIV.localdomain> <20170905122154.GG8741@pathway.suse.cz> <20170905134228.GE521@jagdpanzerIV.localdomain> <20170906075554.GI8741@pathway.suse.cz> <20170917062608.GA512@tigerII.localdomain> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.9.0 (2017-09-02) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Hello Linus, On (09/17/17 08:35), Linus Torvalds wrote: > On Sat, Sep 16, 2017 at 11:26 PM, Sergey Senozhatsky > wrote: > > > > so... I think we don't have to update 'struct printk_log'. we can store > > that "extended data" at the beginning of every message, right after the > > prefix. > > No, we really can't. That just means that all the tools would have to > be changed to get the normal messages without the extra crud. And > since it will have lost the difference, that's not even easy to do. well, that extra crud is meant to be there only when people explicitly enable CONFIG_PRINTK_ADD_EXTRA_CRUD_PLEASE. so it's a debugging option. > So this is exactly the wrong way around. > > If people want to see the extra data, it really should be extra data > that you can get with a new interface from the kernel logs. Not a > "let's just a add it to all lines and make every line uglier and > harder to read. there is another reason why I think that, yes, we probably better do it some other way. and the reason is that not every message that looks like !PREFIX (does not start with KERN_SOH_ASCII) is _actually_ a !PREFIX message. the normal/usual way is to have something like printk(KERN_SOH_ASCII %d " foo bar / %s %s\n", "foo", "bar"); but some messages look like printk("%s", KERN_SOH_ASCII %d "foo bar\n"); so we end up having a "normal" message with KERN_SOH_ASCII %d at offsets 0 and 1 in the resulting text, but only after we do vscnprintf() in vprintk_emit(). so the proposed _pre-processing_ is complicated. post-processing -- the one we do in vprintk_emit() -- is still simple. that's why last night I thought that may be we can do something more radical - double the number of logbuf lines. IOW, every time we do log_store(facility, level, lflags, 0, dict, dictlen, text, text_len) we also will do static char ext_data[...]; size_t ext_sz = sprintf(ext_data, .....); log_store(facility, level, lflags, 0, dict, dictlen, ext_data, ext_sz); so every message will now have "extra message" before (or after) it. we do log_store() under logbuf lock, so no other messages should appear (um, hopefully). every extra message will contain "[extra:" text, so it'll be possible to filter it out... but, once again, the extra stuff is printed only when people ask for it. we are currently looking at lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@redhat.com which will definitely break some user space tools (well, if enabled in .config); so I thought that may be that "helpful" timestamp can go as extra payload. p.s. while I'm not entire sold on the whole timestamps in printk help resolve issues thing. first, printk() can spin on logbuf lock before it will read the timestamp. second, between printk()->va_start->vprintk_func->{...this_cpu_read...}->vprintk_emit->logbuf_lock->... and printk_get_ts() many things can happen - irq, preemption, etc. - so timestamp that we take under ->logbuf_lock is of somewhat questionable accurateness. -ss