early_printk accessing __log_buf

early_printk accessing __log_buf

[Robin Getz]

Quick question:

I am currently setting up an early_printk for the Blackfin - & I'm populating
an early fault interrupt handler at the same time. This allows things like
catching interrupts, or faults before the kernel has had a chance to
enable it's standard interrupt/fault handlers which happen midway 
through the boot process.

I would like to be able to print out the standard __log_buf from my early
fault handler - so everyone can see where things are when they died. In
most situations - printk has dumped some info to the log_buf, and it is
normally handy to see figure out what is going on.

However - __log_buf & associated pointers are declared as static in
kernel/printk.c - so they can't be accessed by external files.

I would normally use do_syslog([23],...) to read from the buffer - 
but these crashes happens before the kernel is fully initialized,
so spin_lock_irq, cond_resched, or wait_event_interruptible
will cause problems...

Although there are other solutions - I would prefer to just don't declare them
as static when EARLY_PRINTK is defined. This way if something bad happens - 
everyone can dump out the standard buffers to assist in debugging...

===================================================================
--- linux-2.6.x/kernel/printk.c (revision 3400)
+++ linux-2.6.x/kernel/printk.c (working copy)
@@ -117,7 +117,12 @@

 #ifdef CONFIG_PRINTK

+#ifdef CONFIG_EARLY_PRINTK
+char __log_buf[__LOG_BUF_LEN];
+#else
 static char __log_buf[__LOG_BUF_LEN];
+#endif
+
 static char *log_buf = __log_buf;
 static int log_buf_len = __LOG_BUF_LEN;
 static unsigned long logged_chars; /* Number of chars produced since last read+clear operation */

Thoughts?

-Robin

Re: early_printk accessing __log_buf

[Andrew Morton]

On Wed, 18 Jul 2007 17:56:43 -0400
Robin Getz <rgetz@blackfin.uclinux.org> wrote:

> Quick question:
> 
> I am currently setting up an early_printk for the Blackfin - & I'm populating
> an early fault interrupt handler at the same time. This allows things like
> catching interrupts, or faults before the kernel has had a chance to
> enable it's standard interrupt/fault handlers which happen midway 
> through the boot process.
> 
> I would like to be able to print out the standard __log_buf from my early
> fault handler - so everyone can see where things are when they died. In
> most situations - printk has dumped some info to the log_buf, and it is
> normally handy to see figure out what is going on.
> 
> However - __log_buf & associated pointers are declared as static in
> kernel/printk.c - so they can't be accessed by external files.
> 
> I would normally use do_syslog([23],...) to read from the buffer - 
> but these crashes happens before the kernel is fully initialized,
> so spin_lock_irq, cond_resched, or wait_event_interruptible
> will cause problems...
> 
> Although there are other solutions - I would prefer to just don't declare them
> as static when EARLY_PRINTK is defined. This way if something bad happens - 
> everyone can dump out the standard buffers to assist in debugging...

Being able to get at the log buffer from external debug-style code is a
fairly common requirement.

> ===================================================================
> --- linux-2.6.x/kernel/printk.c (revision 3400)
> +++ linux-2.6.x/kernel/printk.c (working copy)
> @@ -117,7 +117,12 @@
> 
>  #ifdef CONFIG_PRINTK
> 
> +#ifdef CONFIG_EARLY_PRINTK
> +char __log_buf[__LOG_BUF_LEN];
> +#else
>  static char __log_buf[__LOG_BUF_LEN];
> +#endif
> +
>  static char *log_buf = __log_buf;
>  static int log_buf_len = __LOG_BUF_LEN;
>  static unsigned long logged_chars; /* Number of chars produced since last read+clear operation */
> 

erk.  There isn't much point in making something externally accessible
without also declaring it in a header file.  And callers will need to be
able to get at log_buf_len too, I guess.

I'd suggest that any interface into here should be via function calls, not
via direct access to printk internals: think up some nice
copy_me_some_of_the_log_buffer() interface.

Re: early_printk accessing __log_buf

[Robin Getz]

On Wed 18 Jul 2007 18:16, Andrew Morton pondered:
> 
> I'd suggest that any interface into here should be via function calls,
> not via direct access to printk internals: think up some nice
> copy_me_some_of_the_log_buffer() interface.

If so - I would still like to put it in:
 - ifdef CONFIG_EARLY_PRINTK
 - and define as __init

so that people don't use it when they shouldn't (when the kernel is up an 
running).

Something simple like - early_copy_log_buff(void *dest, size_t n) 

copies n bytes from log_buf to memory area dest. Returns number of bytes that 
could not be copied. Can find out how many bytes are in the log_buff by 
calling with zero size.

This is not destructive to existing interfaces (log_start and con_start are 
not updated/used). This should ensure that if booting does work - that normal 
messages come out the standard method.

Any other suggestions?

-Robin

Re: early_printk accessing __log_buf

[Mike Frysinger]

On 7/18/07, Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> On Wed 18 Jul 2007 18:16, Andrew Morton pondered:
> > I'd suggest that any interface into here should be via function calls,
> > not via direct access to printk internals: think up some nice
> > copy_me_some_of_the_log_buffer() interface.
>
> If so - I would still like to put it in:
>  - ifdef CONFIG_EARLY_PRINTK
>  - and define as __init
>
> so that people don't use it when they shouldn't (when the kernel is up an
> running).
>
> Something simple like - early_copy_log_buff(void *dest, size_t n)
>
> copies n bytes from log_buf to memory area dest. Returns number of bytes that
> could not be copied. Can find out how many bytes are in the log_buff by
> calling with zero size.
>
> This is not destructive to existing interfaces (log_start and con_start are
> not updated/used). This should ensure that if booting does work - that normal
> messages come out the standard method.
>
> Any other suggestions?

maybe something as cheesy as early_get_log_buf() ?  that way you dont
have to do any buffer management, you can just operate read-only on
the string ...
-mike

Re: early_printk accessing __log_buf

[Robin Getz]

On Wed 18 Jul 2007 19:53, Mike Frysinger pondered:
> On 7/18/07, Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> > On Wed 18 Jul 2007 18:16, Andrew Morton pondered:
> > > I'd suggest that any interface into here should be via function calls,
> > > not via direct access to printk internals: think up some nice
> > > copy_me_some_of_the_log_buffer() interface.
> >
> > If so - I would still like to put it in:
> >  - ifdef CONFIG_EARLY_PRINTK
> >  - and define as __init
> >
> > so that people don't use it when they shouldn't (when the kernel is up an
> > running).
> >
> > Something simple like - early_copy_log_buff(void *dest, size_t n)
> >
> > copies n bytes from log_buf to memory area dest. Returns number of bytes that
> > could not be copied. Can find out how many bytes are in the log_buff by
> > calling with zero size.
> >
> > This is not destructive to existing interfaces (log_start and con_start are
> > not updated/used). This should ensure that if booting does work - that normal
> > messages come out the standard method.
> >
> > Any other suggestions?
> 
> maybe something as cheesy as early_get_log_buf() ?  that way you dont
> have to do any buffer management, you can just operate read-only on
> the string ...

I actually thought I might just do something like:

  char *c;
  while (early_copy_log_buff(c, 1))
	out_early_serial_byte(c);

that way - I don't need to be very complex in the arch code.

That is about as cheesy/easy as I could think of...

-Robin

Re: early_printk accessing __log_buf

[Andrew Morton]

On Wed, 18 Jul 2007 23:37:34 -0400 Robin Getz <rgetz@blackfin.uclinux.org> wrote:

> On Wed 18 Jul 2007 19:53, Mike Frysinger pondered:
> > On 7/18/07, Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> > > On Wed 18 Jul 2007 18:16, Andrew Morton pondered:
> > > > I'd suggest that any interface into here should be via function calls,
> > > > not via direct access to printk internals: think up some nice
> > > > copy_me_some_of_the_log_buffer() interface.
> > >
> > > If so - I would still like to put it in:
> > >  - ifdef CONFIG_EARLY_PRINTK
> > >  - and define as __init
> > >
> > > so that people don't use it when they shouldn't (when the kernel is up an
> > > running).
> > >
> > > Something simple like - early_copy_log_buff(void *dest, size_t n)
> > >
> > > copies n bytes from log_buf to memory area dest. Returns number of bytes that
> > > could not be copied. Can find out how many bytes are in the log_buff by
> > > calling with zero size.
> > >
> > > This is not destructive to existing interfaces (log_start and con_start are
> > > not updated/used). This should ensure that if booting does work - that normal
> > > messages come out the standard method.
> > >
> > > Any other suggestions?
> > 
> > maybe something as cheesy as early_get_log_buf() ?  that way you dont
> > have to do any buffer management, you can just operate read-only on
> > the string ...
> 
> I actually thought I might just do something like:
> 
>   char *c;
>   while (early_copy_log_buff(c, 1))
> 	out_early_serial_byte(c);
> 
> that way - I don't need to be very complex in the arch code.
> 
> That is about as cheesy/easy as I could think of...
> 

Let's forget the "early" stuff - there are applications of this at
oops-time as well, and that's as late as it gets ;)


How about

	int log_buf_read(int index, char *my_char);

You pass it a zero to start off, and it returns 0 or -1 if `index' is out
of bounds.

Probably we'd also need a log_buf_size(int) to find out how much is in there
at present (for people who want to read the last 1000 bytes).


Something simple and general, anyway.

Re: early_printk accessing __log_buf

[Andrew Morton]

On Wed, 18 Jul 2007 19:39:46 -0400
Robin Getz <rgetz@blackfin.uclinux.org> wrote:

> On Wed 18 Jul 2007 18:16, Andrew Morton pondered:
> > 
> > I'd suggest that any interface into here should be via function calls,
> > not via direct access to printk internals: think up some nice
> > copy_me_some_of_the_log_buffer() interface.
> 
> If so - I would still like to put it in:
>  - ifdef CONFIG_EARLY_PRINTK
>  - and define as __init
> 
> so that people don't use it when they shouldn't (when the kernel is up an 
> running).
> 
> Something simple like - early_copy_log_buff(void *dest, size_t n) 
> 
> copies n bytes from log_buf to memory area dest. Returns number of bytes that 
> could not be copied. Can find out how many bytes are in the log_buff by 
> calling with zero size.
> 
> This is not destructive to existing interfaces (log_start and con_start are 
> not updated/used). This should ensure that if booting does work - that normal 
> messages come out the standard method.
> 
> Any other suggestions?
> 

When I was at $EARLIER_EMPLOYER, we had code in there to copy the last
kilobyte-odd of the log buffer into flash when the box oopsed.

So there's one instance proof that something more general would be needed. 
Probably there are others, but they'll mainly be in the consumer/embedded
area, and those sorts of engineers don't read this mailing list much.

Re: early_printk accessing __log_buf

[Stephane Couture]

Andrew Morton wrote:
> On Wed, 18 Jul 2007 19:39:46 -0400
> Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> 
>> On Wed 18 Jul 2007 18:16, Andrew Morton pondered:
>>> I'd suggest that any interface into here should be via function calls,
>>> not via direct access to printk internals: think up some nice
>>> copy_me_some_of_the_log_buffer() interface.
>> If so - I would still like to put it in:
>>  - ifdef CONFIG_EARLY_PRINTK
>>  - and define as __init
>>
>> so that people don't use it when they shouldn't (when the kernel is up an 
>> running).
>>
>> Something simple like - early_copy_log_buff(void *dest, size_t n) 
>>
>> copies n bytes from log_buf to memory area dest. Returns number of bytes that 
>> could not be copied. Can find out how many bytes are in the log_buff by 
>> calling with zero size.
>>
>> This is not destructive to existing interfaces (log_start and con_start are 
>> not updated/used). This should ensure that if booting does work - that normal 
>> messages come out the standard method.
>>
>> Any other suggestions?
>>
> 
> When I was at $EARLIER_EMPLOYER, we had code in there to copy the last
> kilobyte-odd of the log buffer into flash when the box oopsed.
> 
> So there's one instance proof that something more general would be needed. 
> Probably there are others, but they'll mainly be in the consumer/embedded
> area, and those sorts of engineers don't read this mailing list much.
> 

We log everything to SRAM so having the option to select the buffer 
destination address would be nice.  My crude way of doing it:

--- 2.6.21/kernel/printk.c@@/main/1      2007-04-27 05:34:35.000000000
-0400
+++ 2.6.21/kernel/printk.c@@/main/2      2007-05-01 02:27:18.000000000 -0400
@@ -94,7 +94,12 @@
   */
  static unsigned long log_start;        /* Index into log_buf: next 
char to be read by syslog() */
  static unsigned long con_start;        /* Index into log_buf: next 
char to be sent to consoles */
+#ifndef CONFIG_LOG_BUF_ALTERNATE_ADRS
  static unsigned long log_end;  /* Index into log_buf: 
most-recently-written-char + 1 */
+#else
+extern int alt_log_end_adrs;
+#define log_end (*(unsigned long*)alt_log_end_adrs)
+#endif

  /*
   *     Array of consoles built from command line options (console=)
@@ -117,8 +122,14 @@

  #ifdef CONFIG_PRINTK

+#ifndef CONFIG_LOG_BUF_ALTERNATE_ADRS
  static char __log_buf[__LOG_BUF_LEN];
  static char *log_buf = __log_buf;
+#else
+extern int alt_log_buf_adrs;
+#define __log_buf ((unsigned char*)alt_log_buf_adrs)
+#define log_buf ((unsigned char*)alt_log_buf_adrs)
+#endif
  static int log_buf_len = __LOG_BUF_LEN;
  static unsigned long logged_chars; /* Number of chars produced since 
last read+clear operation */

Re: early_printk accessing __log_buf

[Robin Getz]

On Wed 18 Jul 2007 20:26, Andrew Morton pondered:
> Robin Getz wrote:
> > [need to access _log_buf from external for early debugging code]
> > 
> > Something simple like - early_copy_log_buff(void *dest, size_t n) 
> > 
> > copies n bytes from log_buf to memory area dest. Returns number of
> > bytes that could not be copied. Can find out how many bytes are in
> > the log_buff by calling with zero size.
> 
> When I was at $EARLIER_EMPLOYER, we had code in there to copy the last
> kilobyte-odd of the log buffer into flash when the box oopsed.
> 

Hmm - I think that if you call with NULL dest, and have it advance the 
pointer, you could do the same thing with something like:

 /* see how many bytes are in the buff */
 length = early_copy_log_buff(NULL, NULL);
 /* advance the pointer, so we only copy the last 1k */
 if (length >= 1024 )
    left = early_copy_log_buff(NULL, length - 1024);
 /* copy to temp buffer, to save to flash */
 early_copy_log_buff(buff, 1024);
 save_buff_to_flash(buff);

That way - you can put this in the standard places for failure, and still have 
only one function polluting printk.c (Although if you want to use it for 
failure trapping - it's up for "normal" run time use, and doesn't go into 
__init. 

> Probably there are others, but they'll mainly be in the consumer/embedded
>  area, and those sorts of engineers don't read this mailing list much.

Adding a few more 'embedded' folks - who might have some thoughts/opinions.

-Robin

Re: early_printk accessing __log_buf

[Mike Frysinger]

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

On 7/18/07, Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> On Wed 18 Jul 2007 20:26, Andrew Morton pondered:
> > Robin Getz wrote:
> > > [need to access _log_buf from external for early debugging code]
> > >
> > > Something simple like - early_copy_log_buff(void *dest, size_t n)
> > >
> > > copies n bytes from log_buf to memory area dest. Returns number of
> > > bytes that could not be copied. Can find out how many bytes are in
> > > the log_buff by calling with zero size.
> >
> > When I was at $EARLIER_EMPLOYER, we had code in there to copy the last
> > kilobyte-odd of the log buffer into flash when the box oopsed.
> >
>
> Hmm - I think that if you call with NULL dest, and have it advance the
> pointer, you could do the same thing with something like:
>
>  /* see how many bytes are in the buff */
>  length = early_copy_log_buff(NULL, NULL);
>  /* advance the pointer, so we only copy the last 1k */
>  if (length >= 1024 )
>     left = early_copy_log_buff(NULL, length - 1024);
>  /* copy to temp buffer, to save to flash */
>  early_copy_log_buff(buff, 1024);
>  save_buff_to_flash(buff);
>
> That way - you can put this in the standard places for failure, and still have
> only one function polluting printk.c (Although if you want to use it for
> failure trapping - it's up for "normal" run time use, and doesn't go into
> __init.
>
> > Probably there are others, but they'll mainly be in the consumer/embedded
> >  area, and those sorts of engineers don't read this mailing list much.
>
> Adding a few more 'embedded' folks - who might have some thoughts/opinions.

i think the attached two functions account for what Robin and Andrew
were thinking ...
-mike

[-- Attachment #2: linux-log_buf_read.patch --]
[-- Type: application/octet-stream, Size: 2990 bytes --]

Add two new functions for reading the kernel log buffer.  Their intention
is to be used by recovery/dump/debug code so the kernel log can be easily
retrieved/parsed in a crash scenario, but they are generic enough for other
people to dream up other fun uses.

Signed-off-by: Mike Frysinger <vapier@gentoo.org>
---
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 4300bb4..3fcc09e 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -156,6 +156,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
+extern int log_buf_read(int len, char *buf, int grab_lock);
+extern int log_buf_read_byte(int idx, char *byte, int grab_lock);
 #else
 static inline int vprintk(const char *s, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
@@ -163,6 +165,8 @@ static inline int vprintk(const char *s, va_list args) { return 0; }
 static inline int printk(const char *s, ...)
 	__attribute__ ((format (printf, 1, 2)));
 static inline int __cold printk(const char *s, ...) { return 0; }
+static inline int log_buf_read(int len, char *buf, int grab_lock) { return 0; }
+static inline int log_buf_read_byte(int len, char *buf, int grab_lock) { return 0; }
 #endif
 
 unsigned long int_sqrt(unsigned long);
diff --git a/kernel/printk.c b/kernel/printk.c
index 051d27e..f08dbf5 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -163,6 +163,71 @@ out:
 __setup("log_buf_len=", log_buf_len_setup);
 
 /*
+ * Read the log buffer into the supplied buffer.  The len option
+ * tells whether to copy from the beginning (> 0), the end (< 0), or
+ * just query the number of existing chars.   The number of bytes
+ * actually copied is returned.
+ */
+int log_buf_read(int len, char *buf, int grab_lock)
+{
+	unsigned long start, end;
+	int num_to_copy;
+
+	if (len == 0)
+		return log_end - log_start;
+
+	if (grab_lock)
+		spin_lock_irq(&logbuf_lock);
+
+	num_to_copy = min(abs(len), abs(log_end - log_start));
+
+	if (len < 0) {
+		start = log_end - num_to_copy;
+		end = log_end;
+	} else {
+		start = log_start;
+		end = log_start + num_to_copy;
+	}
+
+	while (start != end)
+		*buf++ = LOG_BUF(start++);
+
+	if (grab_lock)
+		spin_unlock_irq(&logbuf_lock);
+
+	return num_to_copy;
+}
+
+/*
+ * Grab a single byte out of the log buffer.  The idx option
+ * tells whether to index from the beginning (>= 0) or the
+ * end (< 0) of the buffer.
+ */
+int log_buf_read_byte(int idx, char *byte, int grab_lock)
+{
+	int ret = 1;
+
+	if (grab_lock)
+		spin_lock_irq(&logbuf_lock);
+
+	if (abs(idx) >= log_buf_len || abs(idx) >= logged_chars) {
+		ret = -1;
+		goto done;
+	}
+
+	if (idx < 0)
+		*byte = LOG_BUF(log_end + idx);
+	else
+		*byte = LOG_BUF(log_start + idx);
+
+ done:
+	if (grab_lock)
+		spin_unlock_irq(&logbuf_lock);
+
+	return ret;
+}
+
+/*
  * Commands to do_syslog:
  *
  * 	0 -- Close the log.  Currently a NOP.

Re: early_printk accessing __log_buf

[Paul Mundt]

On Sun, Jul 22, 2007 at 07:50:47PM -0400, Mike Frysinger wrote:
> On 7/18/07, Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> >On Wed 18 Jul 2007 20:26, Andrew Morton pondered:
> >> Robin Getz wrote:
> >> > [need to access _log_buf from external for early debugging code]
> >> >
> >> > Something simple like - early_copy_log_buff(void *dest, size_t n)
> >> >
> >> > copies n bytes from log_buf to memory area dest. Returns number of
> >> > bytes that could not be copied. Can find out how many bytes are in
> >> > the log_buff by calling with zero size.
> >>
> >> When I was at $EARLIER_EMPLOYER, we had code in there to copy the last
> >> kilobyte-odd of the log buffer into flash when the box oopsed.
> >>
> >
> >Hmm - I think that if you call with NULL dest, and have it advance the
> >pointer, you could do the same thing with something like:
> >
> > /* see how many bytes are in the buff */
> > length = early_copy_log_buff(NULL, NULL);
> > /* advance the pointer, so we only copy the last 1k */
> > if (length >= 1024 )
> >    left = early_copy_log_buff(NULL, length - 1024);
> > /* copy to temp buffer, to save to flash */
> > early_copy_log_buff(buff, 1024);
> > save_buff_to_flash(buff);
> >
> >That way - you can put this in the standard places for failure, and still 
> >have
> >only one function polluting printk.c (Although if you want to use it for
> >failure trapping - it's up for "normal" run time use, and doesn't go into
> >__init.
> >
> >> Probably there are others, but they'll mainly be in the consumer/embedded
> >>  area, and those sorts of engineers don't read this mailing list much.
> >
> >Adding a few more 'embedded' folks - who might have some thoughts/opinions.
> 
> i think the attached two functions account for what Robin and Andrew
> were thinking ...

I don't have any strong opinions on this one way or the other. We've been
playing more with kexec for a recovery mode, that coupled with the crash
dumps gives us most of the state we need. We would probably make use of
this printk log access functionality if it were added, though, depending
on customer environments.

Re: early_printk accessing __log_buf

[Robin Getz]

On Sun 22 Jul 2007 19:50, Mike Frysinger pondered:
>
> i think the attached two functions account for what Robin and Andrew
> were thinking ...

A note about why/when grab_lock would be set to zero (pre-kernel init, or 
OOPs) might be nice. 

Or - remove it - and tell people they should be using do_syslog interface in 
a "normal" kernel environment (where log_end or log_start can be updated).

Either would be fine with me. Andrew?

-Robin

Re: early_printk accessing __log_buf

[Andrew Morton]

On Mon, 23 Jul 2007 14:19:12 -0400
Robin Getz <rgetz@blackfin.uclinux.org> wrote:

> On Sun 22 Jul 2007 19:50, Mike Frysinger pondered:
> >
> > i think the attached two functions account for what Robin and Andrew
> > were thinking ...
> 
> A note about why/when grab_lock would be set to zero (pre-kernel init, or 
> OOPs) might be nice. 

Definitely.

The pre-kernel init shouldn't be an issue: logbuf_lock is initialised at
compile time.

At oops time we could possibly use oops_in_progress to work out whether to
avoid taking the lock.  That's not terribly nice, but nor is it nice for
callers to know about printk internals.

> Or - remove it - and tell people they should be using do_syslog interface in 
> a "normal" kernel environment (where log_end or log_start can be updated).

You can't (or al least, shouldn't) use do_syslog() from within kernel code?

> Either would be fine with me. Andrew?

The interface is pretty bad, IMO:

 /*
+ * Read the log buffer into the supplied buffer.  The len option
+ * tells whether to copy from the beginning (> 0), the end (< 0), or
+ * just query the number of existing chars.   The number of bytes
+ * actually copied is returned.
+ */
+int log_buf_read(int len, char *buf, int grab_lock)

The magical interpretation of len isn't very nice.  This code would be
simpler if it did not attempt to read more than one char at a time.  It
will be plenty fast enough.

If the caller knows the length of the buffer, why is there any need for the
index-from-the-end function?

I think a sufficient implementation is

	int log_buf_len(void);

and

	int log_buf_read(int index);

which will return the character at `index', or -1 if `index' is out of
bounds.

Re: early_printk accessing __log_buf

[Mike Frysinger]

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

On 7/23/07, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Mon, 23 Jul 2007 14:19:12 -0400
> Robin Getz <rgetz@blackfin.uclinux.org> wrote:
>
> > On Sun 22 Jul 2007 19:50, Mike Frysinger pondered:
> > >
> > > i think the attached two functions account for what Robin and Andrew
> > > were thinking ...
> >
> > A note about why/when grab_lock would be set to zero (pre-kernel init, or
> > OOPs) might be nice.
>
> Definitely.
>
> The pre-kernel init shouldn't be an issue: logbuf_lock is initialised at
> compile time.
>
> At oops time we could possibly use oops_in_progress to work out whether to
> avoid taking the lock.  That's not terribly nice, but nor is it nice for
> callers to know about printk internals.

maybe, but for early debug users (the reason we wanted this
originally), it wouldnt be an oops in progress ... but i guess we can
just as easily set oops_in_progress to 1 in our code before calling
this function to keep from having to worry over locks from being
doubly grabbed.

> > Or - remove it - and tell people they should be using do_syslog interface in
> > a "normal" kernel environment (where log_end or log_start can be updated).
>
> You can't (or al least, shouldn't) use do_syslog() from within kernel code?
>
> > Either would be fine with me. Andrew?
>
> The interface is pretty bad, IMO:
>
>  /*
> + * Read the log buffer into the supplied buffer.  The len option
> + * tells whether to copy from the beginning (> 0), the end (< 0), or
> + * just query the number of existing chars.   The number of bytes
> + * actually copied is returned.
> + */
> +int log_buf_read(int len, char *buf, int grab_lock)
>
> The magical interpretation of len isn't very nice.  This code would be
> simpler if it did not attempt to read more than one char at a time.  It
> will be plenty fast enough.
>
> If the caller knows the length of the buffer, why is there any need for the
> index-from-the-end function?

fair enough ... my php side likes to overload the meaning of length :)

> I think a sufficient implementation is
>
>         int log_buf_len(void);
>
> and
>
>         int log_buf_read(int index);
>
> which will return the character at `index', or -1 if `index' is out of
> bounds.

the idea originally was to have a buffer based function and an index
based function due to the idea of copying chunks of the log at a time,
but i kind of forgot about that once was all said and done.  now that
i look at it, unless the buffer based function dives into the log
internals to figure out how to split the copy based on the log
wraparound, there's no need for it.

log_buf_len is already the variable used to track the size, so the
function is called 'log_buf_get_len()' ...
-mike

[-- Attachment #2: linux-log_buf_read.patch --]
[-- Type: application/octet-stream, Size: 1990 bytes --]

Add two new functions for reading the kernel log buffer.  Their intention
is to be used by recovery/dump/debug code so the kernel log can be easily
retrieved/parsed in a crash scenario, but they are generic enough for other
people to dream up other fun uses.

Signed-off-by: Mike Frysinger <vapier@gentoo.org>
---
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 4300bb4..baa661c 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -156,6 +156,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
+extern int log_buf_get_len(void);
+extern int log_buf_read(int idx);
 #else
 static inline int vprintk(const char *s, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
@@ -163,6 +165,8 @@ static inline int vprintk(const char *s, va_list args) { return 0; }
 static inline int printk(const char *s, ...)
 	__attribute__ ((format (printf, 1, 2)));
 static inline int __cold printk(const char *s, ...) { return 0; }
+static inline int log_buf_get_len(void) { return 0; }
+static inline int log_buf_read(int idx); { return 0; }
 #endif
 
 unsigned long int_sqrt(unsigned long);
diff --git a/kernel/printk.c b/kernel/printk.c
index 051d27e..fae4367 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -163,6 +163,35 @@ out:
 __setup("log_buf_len=", log_buf_len_setup);
 
 /*
+ * Return the number of unread characters in the log buffer.
+ */
+int log_buf_get_len(void)
+{
+	return log_end - log_start;
+}
+
+/*
+ * Extract a character from the log buffer.
+ */
+int log_buf_read(int idx)
+{
+	int ret;
+
+	if (!oops_in_progress)
+		spin_lock_irq(&logbuf_lock);
+
+	if (idx < 0 || idx >= log_buf_get_len())
+		ret = -1;
+	else
+		ret = LOG_BUF(idx);
+
+	if (!oops_in_progress)
+		spin_unlock_irq(&logbuf_lock);
+
+	return ret;
+}
+
+/*
  * Commands to do_syslog:
  *
  * 	0 -- Close the log.  Currently a NOP.

Re: early_printk accessing __log_buf

[Andrew Morton]

On Mon, 23 Jul 2007 16:54:36 -0400
"Mike Frysinger" <vapier.adi@gmail.com> wrote:

> On 7/23/07, Andrew Morton <akpm@linux-foundation.org> wrote:
> > On Mon, 23 Jul 2007 14:19:12 -0400
> > Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> >
> > > On Sun 22 Jul 2007 19:50, Mike Frysinger pondered:
> > > >
> > > > i think the attached two functions account for what Robin and Andrew
> > > > were thinking ...
> > >
> > > A note about why/when grab_lock would be set to zero (pre-kernel init, or
> > > OOPs) might be nice.
> >
> > Definitely.
> >
> > The pre-kernel init shouldn't be an issue: logbuf_lock is initialised at
> > compile time.
> >
> > At oops time we could possibly use oops_in_progress to work out whether to
> > avoid taking the lock.  That's not terribly nice, but nor is it nice for
> > callers to know about printk internals.
> 
> maybe, but for early debug users (the reason we wanted this
> originally), it wouldnt be an oops in progress ... but i guess we can
> just as easily set oops_in_progress to 1 in our code before calling
> this function to keep from having to worry over locks from being
> doubly grabbed.

I don't immediately see how logbuf_lock could be doubly grabbed.  Only if
you're calling this from hard irq context?

Re: early_printk accessing __log_buf

[Mike Frysinger]

On 7/23/07, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Mon, 23 Jul 2007 16:54:36 -0400
> "Mike Frysinger" <vapier.adi@gmail.com> wrote:
>
> > On 7/23/07, Andrew Morton <akpm@linux-foundation.org> wrote:
> > > On Mon, 23 Jul 2007 14:19:12 -0400
> > > Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> > >
> > > > On Sun 22 Jul 2007 19:50, Mike Frysinger pondered:
> > > > >
> > > > > i think the attached two functions account for what Robin and Andrew
> > > > > were thinking ...
> > > >
> > > > A note about why/when grab_lock would be set to zero (pre-kernel init, or
> > > > OOPs) might be nice.
> > >
> > > Definitely.
> > >
> > > The pre-kernel init shouldn't be an issue: logbuf_lock is initialised at
> > > compile time.
> > >
> > > At oops time we could possibly use oops_in_progress to work out whether to
> > > avoid taking the lock.  That's not terribly nice, but nor is it nice for
> > > callers to know about printk internals.
> >
> > maybe, but for early debug users (the reason we wanted this
> > originally), it wouldnt be an oops in progress ... but i guess we can
> > just as easily set oops_in_progress to 1 in our code before calling
> > this function to keep from having to worry over locks from being
> > doubly grabbed.
>
> I don't immediately see how logbuf_lock could be doubly grabbed.  Only if
> you're calling this from hard irq context?

i guess i'm just assuming the worse here and making sure that
something i couldnt conjure up doesnt have the opportunity to bite me
in the ass.  doubly grabbed, memory corruption, whatever ... i dont
really have a real scenario as i dont have a very active imagination
;)
-mike

Re: early_printk accessing __log_buf

[Robin Getz]

On Mon 23 Jul 2007 16:15, Andrew Morton pondered:
> This code would be
> simpler if it did not attempt to read more than one char at a time.  It
> will be plenty fast enough.

When systems have NMI kick off due to power failure, and you want to grab the 
log buffer to write it to flash before power really dies - every cycle 
counts.

A single function which does the copy as a loop (existing) is going to be much 
faster than the overhead of 1024 function calls to copy the last k.

> The magical interpretation of len isn't very nice. 

There are lots of places in the kernel which have magic in them :)

-Robin

Re: early_printk accessing __log_buf

[Andrew Morton]

On Mon, 23 Jul 2007 18:15:37 -0400
Robin Getz <rgetz@blackfin.uclinux.org> wrote:

> On Mon 23 Jul 2007 16:15, Andrew Morton pondered:
> > This code would be
> > simpler if it did not attempt to read more than one char at a time.  It
> > will be plenty fast enough.
> 
> When systems have NMI kick off due to power failure, and you want to grab the 
> log buffer to write it to flash before power really dies - every cycle 
> counts.
> 
> A single function which does the copy as a loop (existing) is going to be much 
> faster than the overhead of 1024 function calls to copy the last k.

I'd expect the overhead of the (fully-cached) instructions to be
insignificant compared to the time to write to flash?

> > The magical interpretation of len isn't very nice. 
> 
> There are lots of places in the kernel which have magic in them :)

Lots of the kernel is pretty crappy.  One of our main tools for fixing that is to
ensure that new stuff is non-crappy.

Re: early_printk accessing __log_buf

[Robin Getz]

On Mon 23 Jul 2007 18:34, Andrew Morton pondered:
> On Mon, 23 Jul 2007 18:15:37 -0400
> Robin Getz <rgetz@blackfin.uclinux.org> wrote:
> > 
> > A single function which does the copy as a loop (existing) is going to
> > be much faster than the overhead of 1024 function calls to copy the 
> > last k. 
> 
> I'd expect the overhead of the (fully-cached) instructions to be
> insignificant compared to the time to write to flash?

Maybe - the time to write a single page on NAND is pretty cheap.

SLC is 200us to program a page.
http://www.st.com/stonline/products/families/memories/fl_nand/nand_large.htm
http://www.st.com/stonline/products/families/memories/fl_nand/nand_small.htm

While you are correct - the majority of the time will be spent in the write to 
flash - the overhead of the loop 
 - call (3 cycles)
 - push a few registers on the stack (a cycle for each push),
 - pop same registers off the stack (a cycle for each pop).
 - return (5 cycles)

(Numbers go up and down depending on your arch - this was for 486)

If you assume three registers need to be pushed/popped - for a 1k buffer that 
is 14336 cycles of pure overhead - assuming 500MHz processor (and a perfect 
cache), that is 28us - about 14% of the time in overhead that doesn't need to 
be there.

Can someone increase the size of the capacitors in their power supply to make 
up for this - yes. But larger caps are more money.

> Lots of the kernel is pretty crappy.  One of our main tools for fixing
> that is to ensure that new stuff is non-crappy.

No problem - I wasn't advocating putting something that you thought was crappy 
into your tree (afterall that would be futile). Other than making the 
overhead high - is there a way to make it less crappy?

If the answer is no, and Mike's latest suggestion/patch is OK - that is what I 
will live with - and tell people to spend more on their power supply.

-robin

Re: early_printk accessing __log_buf

[Andrew Morton]

On Tue, 24 Jul 2007 13:50:44 -0400
Robin Getz <rgetz@blackfin.uclinux.org> wrote:

> > Lots of the kernel is pretty crappy.  One of our main tools for fixing
> > that is to ensure that new stuff is non-crappy.
> 
> No problem - I wasn't advocating putting something that you thought was crappy 
> into your tree (afterall that would be futile).

You wouldn't be the first ;)

> Other than making the 
> overhead high - is there a way to make it less crappy?
> 
> If the answer is no, and Mike's latest suggestion/patch is OK - that is what I 
> will live with - and tell people to spend more on their power supply.

Oh well, it sounds like we need the super-duper fast version.  Keep it as
simple as possible, please.

Re: early_printk accessing __log_buf

[Robin Getz]

On Tue 24 Jul 2007 14:12, Andrew Morton pondered:
> Oh well, it sounds like we need the super-duper fast version.  Keep it
> as simple as possible, please.

What about:

int log_buf_copy(void *dest, int idx, size_t n);

starting at index idx - copy n bytes to dest, return the number of bytes 
copied (in case there are not n bytes in the log_buf yet).

Re: early_printk accessing __log_buf

[Andrew Morton]

On Tue, 24 Jul 2007 16:12:56 -0400
Robin Getz <rgetz@blackfin.uclinux.org> wrote:

> On Tue 24 Jul 2007 14:12, Andrew Morton pondered:
> > Oh well, it sounds like we need the super-duper fast version.  Keep it
> > as simple as possible, please.
> 
> What about:
> 
> int log_buf_copy(void *dest, int idx, size_t n);
> 
> starting at index idx - copy n bytes to dest, return the number of bytes 
> copied (in case there are not n bytes in the log_buf yet).

Sounds sensible.  I'd make it return size_t and take a char* arg though.
Or just use `int' - size_t is a bit of a pain and this is all kernel-internal
anwyay.

Re: early_printk accessing __log_buf

[Mike Frysinger]

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

On 7/24/07, Andrew Morton <akpm@linux-foundation.org> wrote:
> On Tue, 24 Jul 2007 16:12:56 -0400 Robin Getz wrote:
> > On Tue 24 Jul 2007 14:12, Andrew Morton pondered:
> > > Oh well, it sounds like we need the super-duper fast version.  Keep it
> > > as simple as possible, please.
> >
> > What about:
> >
> > int log_buf_copy(void *dest, int idx, size_t n);
> >
> > starting at index idx - copy n bytes to dest, return the number of bytes
> > copied (in case there are not n bytes in the log_buf yet).
>
> Sounds sensible.  I'd make it return size_t and take a char* arg though.
> Or just use `int' - size_t is a bit of a pain and this is all kernel-internal
> anwyay.

attached
-mike

[-- Attachment #2: linux-log_buf_read.patch --]
[-- Type: application/octet-stream, Size: 2449 bytes --]

Add two new functions for reading the kernel log buffer.  Their intention
is to be used by recovery/dump/debug code so the kernel log can be easily
retrieved/parsed in a crash scenario, but they are generic enough for other
people to dream up other fun uses.

Signed-off-by: Mike Frysinger <vapier@gentoo.org>
---
diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 4300bb4..8d5b6c7 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -156,6 +156,9 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
 asmlinkage int printk(const char * fmt, ...)
 	__attribute__ ((format (printf, 1, 2))) __cold;
+extern int log_buf_get_len(void);
+extern int log_buf_read(int idx);
+extern int log_buf_copy(char *dest, int idx, int len);
 #else
 static inline int vprintk(const char *s, va_list args)
 	__attribute__ ((format (printf, 1, 0)));
@@ -163,6 +166,9 @@ static inline int vprintk(const char *s, va_list args) { return 0; }
 static inline int printk(const char *s, ...)
 	__attribute__ ((format (printf, 1, 2)));
 static inline int __cold printk(const char *s, ...) { return 0; }
+static inline int log_buf_get_len(void) { return 0; }
+static inline int log_buf_read(int idx); { return 0; }
+static inline int log_buf_copy(char *dest, int idx, int len) { return 0; }
 #endif
 
 unsigned long int_sqrt(unsigned long);
diff --git a/kernel/printk.c b/kernel/printk.c
index 051d27e..35b231a 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -163,6 +163,55 @@ out:
 __setup("log_buf_len=", log_buf_len_setup);
 
 /*
+ * Return the number of unread characters in the log buffer.
+ */
+int log_buf_get_len(void)
+{
+	return log_end - log_start;
+}
+
+/*
+ * Copy a range of characters from the log buffer.
+ */
+int log_buf_copy(char *dest, int idx, int len)
+{
+	int ret, max;
+
+	if (!oops_in_progress)
+		spin_lock_irq(&logbuf_lock);
+
+	max = log_buf_get_len();
+	if (idx < 0 || idx >= max)
+		ret = -1;
+	else {
+		if (len > max)
+			len = max;
+		ret = len;
+		while (len-- > 0) {
+			*dest = LOG_BUF(idx++);
+			++dest;
+		}
+	}
+
+	if (!oops_in_progress)
+		spin_unlock_irq(&logbuf_lock);
+
+	return ret;
+}
+
+/*
+ * Extract a single character from the log buffer.
+ */
+int log_buf_read(int idx)
+{
+	char ret;
+	if (log_buf_copy(&ret, idx, 1) == 1)
+		return ret;
+	else
+		return -1;
+}
+
+/*
  * Commands to do_syslog:
  *
  * 	0 -- Close the log.  Currently a NOP.

Re: early_printk accessing __log_buf

[Bryan Wu]

On Tue, 2007-07-31 at 03:47 -0400, Mike Frysinger wrote:
> On 7/24/07, Andrew Morton <akpm@linux-foundation.org> wrote:
> > On Tue, 24 Jul 2007 16:12:56 -0400 Robin Getz wrote:
> > > On Tue 24 Jul 2007 14:12, Andrew Morton pondered:
> > > > Oh well, it sounds like we need the super-duper fast version.  Keep it
> > > > as simple as possible, please.
> > >
> > > What about:
> > >
> > > int log_buf_copy(void *dest, int idx, size_t n);
> > >
> > > starting at index idx - copy n bytes to dest, return the number of bytes
> > > copied (in case there are not n bytes in the log_buf yet).
> >
> > Sounds sensible.  I'd make it return size_t and take a char* arg though.
> > Or just use `int' - size_t is a bit of a pain and this is all kernel-internal
> > anwyay.
> 
> attached
> -mike

why use attachment? You can just paste your patch in the email.

Thanks
- Bryan Wu

Re: early_printk accessing __log_buf

[Mike Frysinger]

On 7/31/07, Bryan Wu <bryan.wu@analog.com> wrote:
> why use attachment? You can just paste your patch in the email.

gmail eats inline text and my normal e-mail account is offline atm
-mike

Re: early_printk accessing __log_buf

[Andrew Morton]

On Tue, 31 Jul 2007 03:47:59 -0400
"Mike Frysinger" <vapier.adi@gmail.com> wrote:

> attached
> -mike
> 
> 
> [linux-log_buf_read.patch  application/octet-stream (2.4KB)]

Please sort out the email thing if you plan on sending more kernel patches?

Incremental:


From: Andrew Morton <akpm@linux-foundation.org>

- compile fix

- Race fix: oops_in_progress can change at any time

- coding-style fixlets.

Cc: Greg Ungerer <gerg@snapgear.com>
Cc: Mike Frysinger <vapier.adi@gmail.com>
Cc: Mike Frysinger <vapier@gentoo.org>
Cc: Paul Mundt <lethal@linux-sh.org>
Cc: Robin Getz <rgetz@blackfin.uclinux.org>
Cc: Russell King <rmk@arm.linux.org.uk>
Cc: Tim Bird <tim.bird@am.sony.com>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
---

 include/linux/kernel.h |    2 +-
 kernel/printk.c        |   12 ++++++++----
 2 files changed, 9 insertions(+), 5 deletions(-)

diff -puN include/linux/kernel.h~early_printk-accessing-__log_buf-fix include/linux/kernel.h
--- a/include/linux/kernel.h~early_printk-accessing-__log_buf-fix
+++ a/include/linux/kernel.h
@@ -168,7 +168,7 @@ static inline int printk(const char *s, 
 	__attribute__ ((format (printf, 1, 2)));
 static inline int __cold printk(const char *s, ...) { return 0; }
 static inline int log_buf_get_len(void) { return 0; }
-static inline int log_buf_read(int idx); { return 0; }
+static inline int log_buf_read(int idx) { return 0; }
 static inline int log_buf_copy(char *dest, int idx, int len) { return 0; }
 #endif
 
diff -puN kernel/printk.c~early_printk-accessing-__log_buf-fix kernel/printk.c
--- a/kernel/printk.c~early_printk-accessing-__log_buf-fix
+++ a/kernel/printk.c
@@ -233,14 +233,17 @@ int log_buf_get_len(void)
 int log_buf_copy(char *dest, int idx, int len)
 {
 	int ret, max;
+	bool took_lock = false;
 
-	if (!oops_in_progress)
+	if (!oops_in_progress) {
 		spin_lock_irq(&logbuf_lock);
+		took_lock = true;
+	}
 
 	max = log_buf_get_len();
-	if (idx < 0 || idx >= max)
+	if (idx < 0 || idx >= max) {
 		ret = -1;
-	else {
+	} else {
 		if (len > max)
 			len = max;
 		ret = len;
@@ -250,7 +253,7 @@ int log_buf_copy(char *dest, int idx, in
 		}
 	}
 
-	if (!oops_in_progress)
+	if (took_lock)
 		spin_unlock_irq(&logbuf_lock);
 
 	return ret;
@@ -262,6 +265,7 @@ int log_buf_copy(char *dest, int idx, in
 int log_buf_read(int idx)
 {
 	char ret;
+
 	if (log_buf_copy(&ret, idx, 1) == 1)
 		return ret;
 	else
_