[PATCH] mtd: mtdoops: optionally dump boottime

[PATCH] mtd: mtdoops: optionally dump boottime

[Stefan M Schaeckeler]

Optionally dump boottime on the mtd device in the form of

<0>[   0.000000] Boot time mm/dd/yyyy hh:mm:ss

Time-stamps of oops messages are in seconds since boottime. Recording also
the boottime helps correlating oopses with other events having occured at
the same time. This correlation will be otherwise lost after (multiple)
reboots.

Signed-off-by: Stefan M Schaeckeler <sschaeck@cisco.com>
---
 drivers/mtd/mtdoops.c | 38 +++++++++++++++++++++++++++++++++++---
 1 file changed, 35 insertions(+), 3 deletions(-)

diff --git a/drivers/mtd/mtdoops.c b/drivers/mtd/mtdoops.c
index 9f25111..11f93aa 100644
--- a/drivers/mtd/mtdoops.c
+++ b/drivers/mtd/mtdoops.c
@@ -54,6 +54,11 @@ module_param(dump_oops, int, 0600);
 MODULE_PARM_DESC(dump_oops,
 		"set to 1 to dump oopses, 0 to only dump panics (default 1)");
 
+static bool dump_boottime = false;
+module_param(dump_boottime, bool, 0400);
+MODULE_PARM_DESC(dump_boottime,
+		"set to 1 to dump boottime, 0 to disable (default 0)");
+
 static struct mtdoops_context {
 	struct kmsg_dumper dump;
 
@@ -69,6 +74,10 @@ static struct mtdoops_context {
 	void *oops_buf;
 } oops_cxt;
 
+/* fake kernel message syslog level and monotonic timestamp */
+#define boottime_prefix "<0>[   0.000000] Boot time "
+static char boottime[100] = {0};
+
 static void mark_page_used(struct mtdoops_context *cxt, int page)
 {
 	set_bit(page, cxt->oops_page_used);
@@ -285,13 +294,17 @@ static void mtdoops_do_dump(struct kmsg_dumper *dumper,
 {
 	struct mtdoops_context *cxt = container_of(dumper,
 			struct mtdoops_context, dump);
+	u8 boot_len = strlen(boottime); /* 0 if dump_boottime is not set */
 
 	/* Only dump oopses if dump_oops is set */
 	if (reason == KMSG_DUMP_OOPS && !dump_oops)
 		return;
 
-	kmsg_dump_get_buffer(dumper, true, cxt->oops_buf + MTDOOPS_HEADER_SIZE,
-			     record_size - MTDOOPS_HEADER_SIZE, NULL);
+	strncpy(cxt->oops_buf + MTDOOPS_HEADER_SIZE, boottime, boot_len);
+
+	kmsg_dump_get_buffer(dumper, true, cxt->oops_buf + MTDOOPS_HEADER_SIZE +
+			     boot_len, record_size - (MTDOOPS_HEADER_SIZE +
+			     boot_len), NULL);
 
 	/* Panics must be written immediately */
 	if (reason != KMSG_DUMP_OOPS)
@@ -350,7 +363,13 @@ static void mtdoops_notify_add(struct mtd_info *mtd)
 	cxt->mtd = mtd;
 	cxt->oops_pages = (int)mtd->size / record_size;
 	find_next_position(cxt);
-	printk(KERN_INFO "mtdoops: Attached to MTD device %d\n", mtd->index);
+	if (dump_boottime) {
+	    printk(KERN_INFO "mtdoops: Attached to MTD device %d "
+		   "dumping boottime\n", mtd->index);
+	} else {
+	    printk(KERN_INFO "mtdoops: Attached to MTD device %d "
+		   "not dumping boottime\n", mtd->index);
+	}
 }
 
 static void mtdoops_notify_remove(struct mtd_info *mtd)
@@ -379,6 +398,19 @@ static int __init mtdoops_init(void)
 	struct mtdoops_context *cxt = &oops_cxt;
 	int mtd_index;
 	char *endp;
+	struct timespec64 bt;
+	struct tm tm_val;
+
+	if (dump_boottime) {
+	    /* Precompute boot time ahead of an oops */
+	    getboottime64(&bt);
+	    time_to_tm(bt.tv_sec, 0, &tm_val);
+
+	    snprintf(boottime, sizeof(boottime),
+		     boottime_prefix "%02d/%02d/%4d %02d:%02d:%02d\n",
+		     tm_val.tm_mon + 1, tm_val.tm_mday, tm_val.tm_year + 1900,
+		     tm_val.tm_hour, tm_val.tm_min, tm_val.tm_sec);
+	}
 
 	if (strlen(mtddev) == 0) {
 		printk(KERN_ERR "mtdoops: mtd device (mtddev=name/number) must be supplied\n");
-- 
2.10.3.dirty

Re: [PATCH] mtd: mtdoops: optionally dump boottime

[Richard Weinberger]

Stefan,

Am Sonntag, 20. Mai 2018, 05:39:40 CEST schrieb Stefan M Schaeckeler:
> Optionally dump boottime on the mtd device in the form of
> 
> <0>[   0.000000] Boot time mm/dd/yyyy hh:mm:ss
> 
> Time-stamps of oops messages are in seconds since boottime. Recording also
> the boottime helps correlating oopses with other events having occured at
> the same time. This correlation will be otherwise lost after (multiple)
> reboots.

I get the use-case, but why is this only for mtdoops?
IMHO this needs to go into generic code such that all kmsg dumpers can
benefit from it.

Thanks,
//richard

Re: [PATCH] mtd: mtdoops: optionally dump boottime

[kbuild test robot]

[-- Attachment #1: Type: text/plain, Size: 3317 bytes --]

Hi Stefan,

Thank you for the patch! Perhaps something to improve:

[auto build test WARNING on mtd/master]
[also build test WARNING on v4.17-rc5 next-20180517]
[if your patch is applied to the wrong git tree, please drop us a note to help improve the system]

url:    https://github.com/0day-ci/linux/commits/Stefan-M-Schaeckeler/mtd-mtdoops-optionally-dump-boottime/20180521-030143
base:   git://git.infradead.org/linux-mtd.git master
config: x86_64-randconfig-x011-201820 (attached as .config)
compiler: gcc-7 (Debian 7.3.0-16) 7.3.0
reproduce:
        # save the attached .config to linux build tree
        make ARCH=x86_64 

All warnings (new ones prefixed by >>):

   drivers//mtd/mtdoops.c: In function 'mtdoops_init':
>> drivers//mtd/mtdoops.c:78:25: warning: format '%d' expects argument of type 'int', but argument 6 has type 'long int' [-Wformat=]
    #define boottime_prefix "<0>[   0.000000] Boot time "
                            ^
>> drivers//mtd/mtdoops.c:410:8: note: in expansion of macro 'boottime_prefix'
           boottime_prefix "%02d/%02d/%4d %02d:%02d:%02d\n",
           ^~~~~~~~~~~~~~~
   drivers//mtd/mtdoops.c:410:37: note: format string is defined here
           boottime_prefix "%02d/%02d/%4d %02d:%02d:%02d\n",
                                      ~~^
                                      %4ld

vim +/boottime_prefix +410 drivers//mtd/mtdoops.c

   395	
   396	static int __init mtdoops_init(void)
   397	{
   398		struct mtdoops_context *cxt = &oops_cxt;
   399		int mtd_index;
   400		char *endp;
   401		struct timespec64 bt;
   402		struct tm tm_val;
   403	
   404		if (dump_boottime) {
   405		    /* Precompute boot time ahead of an oops */
   406		    getboottime64(&bt);
   407		    time_to_tm(bt.tv_sec, 0, &tm_val);
   408	
   409		    snprintf(boottime, sizeof(boottime),
 > 410			     boottime_prefix "%02d/%02d/%4d %02d:%02d:%02d\n",
   411			     tm_val.tm_mon + 1, tm_val.tm_mday, tm_val.tm_year + 1900,
   412			     tm_val.tm_hour, tm_val.tm_min, tm_val.tm_sec);
   413		}
   414	
   415		if (strlen(mtddev) == 0) {
   416			printk(KERN_ERR "mtdoops: mtd device (mtddev=name/number) must be supplied\n");
   417			return -EINVAL;
   418		}
   419		if ((record_size & 4095) != 0) {
   420			printk(KERN_ERR "mtdoops: record_size must be a multiple of 4096\n");
   421			return -EINVAL;
   422		}
   423		if (record_size < 4096) {
   424			printk(KERN_ERR "mtdoops: record_size must be over 4096 bytes\n");
   425			return -EINVAL;
   426		}
   427	
   428		/* Setup the MTD device to use */
   429		cxt->mtd_index = -1;
   430		mtd_index = simple_strtoul(mtddev, &endp, 0);
   431		if (*endp == '\0')
   432			cxt->mtd_index = mtd_index;
   433	
   434		cxt->oops_buf = vmalloc(record_size);
   435		if (!cxt->oops_buf) {
   436			printk(KERN_ERR "mtdoops: failed to allocate buffer workspace\n");
   437			return -ENOMEM;
   438		}
   439		memset(cxt->oops_buf, 0xff, record_size);
   440	
   441		INIT_WORK(&cxt->work_erase, mtdoops_workfunc_erase);
   442		INIT_WORK(&cxt->work_write, mtdoops_workfunc_write);
   443	
   444		register_mtd_user(&mtdoops_notifier);
   445		return 0;
   446	}
   447	

---
0-DAY kernel test infrastructure                Open Source Technology Center
https://lists.01.org/pipermail/kbuild-all                   Intel Corporation

[-- Attachment #2: .config.gz --]
[-- Type: application/gzip, Size: 32915 bytes --]

Re: [PATCH] mtd: mtdoops: optionally dump boottime

[Richard Weinberger]

Stefan,

Am Montag, 21. Mai 2018, 04:29:24 CEST schrieb Stefan Schaeckeler:
> Hello Richard and others,
> 
> > I get the use-case, but why is this only for mtdoops?
> 
> Powerpc's nvram module also stores oops messages and does so by adding an
> additional timestamp, as well (search for kmsg_dump_get_buffer() in
> arch/powerpc/kernel/nvram_64.c).

Just one more reason to make it generic.
 
> This timestamp is the number of seconds since 1970 and stored as a 64 bit
> integer in the nvram header. Basically, the last kmesg timestamp is a few ms
> less than this additionally stored timestamp. Recording boottime would be more
> elegant, I guess.
> 
> 
> > IMHO this needs to go into generic code such that all kmsg dumpers can
> > benefit from it.
> 
> This would be not that easy:
> 
> #1 kmsg_dump_get_buffer(...size...) returns the most recent <size> bytes.
> Consecutive calls return older chunks. It would be natural to return the
> boottime as the first line, e.g. in the last call, but some clients such as
> mtdoops call kmsg_dump_get_buffer() only once. The returned buffer may be
> complete including boottime, or not.
> 
> #2 consistency with other clients: nvram_64.c has the same requirement of
> storing a kind of wall-time but does it in a completely different way: no
> readable ascii text timestamp preprended to the kmsg buffer but a 64 bit
> timestamp in its header. Note, I don't think we should make mtdoops behave like
> nvram_64.c by storing the timestamp as a 64 bit integer (in its header) b/c
> most people do a cat or string of the mtd device /dev/mtdX and a 64 bit integer
> would just read as garbage.

I think this is the perfect opportunity to talk with other kmesg dump users on
how to add a timestamp.
As last resort we can always do it in our own way but I think making it generic
is at lest worth a try...

> I hope we can have separate implementations for recording additional
> timestamps. Later, I'll send a patch with stylistic changes unless we
> completely disagree on how to move forward.

Both #1 and #2 aren't show-stoppers.

Thanks,
//richard

Re: [PATCH] mtd: mtdoops: optionally dump boottime

[Stefan Schaeckeler]

Hello Richard and others,

> I get the use-case, but why is this only for mtdoops?

Powerpc's nvram module also stores oops messages and does so by adding an
additional timestamp, as well (search for kmsg_dump_get_buffer() in
arch/powerpc/kernel/nvram_64.c).

This timestamp is the number of seconds since 1970 and stored as a 64 bit
integer in the nvram header. Basically, the last kmesg timestamp is a few ms
less than this additionally stored timestamp. Recording boottime would be more
elegant, I guess.


> IMHO this needs to go into generic code such that all kmsg dumpers can
> benefit from it.

This would be not that easy:

#1 kmsg_dump_get_buffer(...size...) returns the most recent <size> bytes.
Consecutive calls return older chunks. It would be natural to return the
boottime as the first line, e.g. in the last call, but some clients such as
mtdoops call kmsg_dump_get_buffer() only once. The returned buffer may be
complete including boottime, or not.

#2 consistency with other clients: nvram_64.c has the same requirement of
storing a kind of wall-time but does it in a completely different way: no
readable ascii text timestamp preprended to the kmsg buffer but a 64 bit
timestamp in its header. Note, I don't think we should make mtdoops behave like
nvram_64.c by storing the timestamp as a 64 bit integer (in its header) b/c
most people do a cat or string of the mtd device /dev/mtdX and a 64 bit integer
would just read as garbage.

I hope we can have separate implementations for recording additional
timestamps. Later, I'll send a patch with stylistic changes unless we
completely disagree on how to move forward.

 Stefan