[Toybox] [PATCH] fix dmesg default size/level filtering/performance

[enh]

On Mon, Nov 24, 2014 at 7:10 PM, Isaac Dunham <ibid.ag at gmail.com> wrote:
> On Mon, Nov 24, 2014 at 05:26:06PM -0800, enh wrote:
>> * the kernel buffer hasn't defaulted to 16KiB for a very long time.
>> i'm not sure why the original code said < 2 rather than <= 0 (or 1KiB,
>> say), but i've left that as it was.
>>
>> * there's also a bug with the filtering out of level markers; they can
>> be more than one digit. (this is true of all kernels, not just Android
>> ones.)
>>
>> * finally, the use of xputc for every character makes the toybox dmesg
>> human-noticeably slow. writing line at a time is orders of magnitude
>> faster/fewer syscalls.
>>
>> here's the patch, which attempts to imitate your style:
>> diff --git a/toys/lsb/dmesg.c b/toys/lsb/dmesg.c
>> index 1003256..d4a2b66 100644
>> --- a/toys/lsb/dmesg.c
>> +++ b/toys/lsb/dmesg.c
>> @@ -15,7 +15,7 @@ config DMESG
>>      Print or control the kernel ring buffer.
>>
>>      -n Set kernel logging level (1-9).
>> -    -s Size of buffer to read (in bytes), default 16384.
>> +    -s Size of buffer to read (in bytes), default kernel buffer size.
>>      -c Clear the ring buffer after printing.
>>  */
>>
>> @@ -34,22 +34,34 @@ void dmesg_main(void)
>>    if (toys.optflags & 2) {
>>      if (klogctl(8, NULL, TT.level)) error_exit("klogctl");
>>    } else {
>> -    int size, i, last = '\n';
>> -    char *data;
>> +    int size, i;
>> +    char *data, *end;
>>
>>      // Figure out how much data we need, and fetch it.
>>      size = TT.size;
>> -    if (size<2) size = 16384;
>> +    if (size < 2) size = klogctl(10, 0, 0); // SYSLOG_ACTION_SIZE_BUFFER.
>> +    if (size < 0) size = 16384;
>>      data = xmalloc(size);
>>      size = klogctl(3 + (toys.optflags&1), data, size);
>>      if (size < 0) error_exit("klogctl");
>>
>> -    // Display data, filtering out level markers.
>> +    // Display data, filtering out level markers (<\d+>).
>>      for (i=0; i<size; ) {
>> -      if (last=='\n' && data[i]=='<') i += 3;
>> -      else xputc(last = data[i++]);
>> +      if (data[i]=='<') {
>> +        end = strchr(data+i, '>');
>> +        if (end) i = end-data+1;
> I presume the theory here is that log levels might eventually end up going
> above 8, despite the documentation implying otherwise?

never trust the documentation :-) --- as i said in my commentary, this
is the case right now, and not just on Android kernels. example from
my Ubuntu desktop:

~$ dmesg -r | egrep '<[0-9][0-9]>'
<12>[230625.033238] init: anacron main process (848) killed by TERM signal
<12>[230626.308516] init: anacron main process (1996) killed by TERM signal
<12>[230631.510410] init: anacron main process (2439) killed by TERM signal
<12>[231591.145838] init: anacron main process (3557) killed by TERM signal
~$

> And of course everything assumes that < and > are off-limits for the contents.

no, there's a loop invariant that you're always at the start of the
line. strchr stops at the first match. so the assumption is that a
level doesn't contain '>', which is a pretty safe assumption given
that that's the character used to mark the end.

strictly there's another assumption: that the buffer the kernel
returns starts at the beginning of a line. but the old code had that
assumption too, and i've not seen that assumption violated in practice
(despite playing around with small buffer sizes trying to provoke it).

>> +      } else {
>> +        end = strchr(data+i, '\n');
>> +        if (end) {
>> +          xwrite(1, data+i, end-(data+i)+1);
>> +          i += end - (data+i) + 1;
>
> Somehow this whole bit reminds me of something I wrote not long ago,
> where I took care of unwanted strings by moving the memory contents
> towards the start.
> Applied here, it might look like this:
>
> void memback(long delbytes, char *string)
> {
>   // could be adjusted to not need strlen() in our case...
>   memmove(string, string + delbytes, strlen(string) + delbytes);
> }
>
> ...
>   while ((cur = strchr(cur, '<') != 0) {
>     memback(3, cur);
>   }
>
>
> This will call memmove() a lot; on the other hand, it can call write once.

yeah, the toolbox dmesg (which is "dmesg -r") only needs to do one big
write, but for default current kernel buffers (128KiB) the difference
between that and one syscall per line is not human-noticeable. judging
by "strace -c dmesg" on the desktop, the competition doesn't bother
either.

>> +        } else {
>> +          xwrite(1, data+i, size-i);
>> +          xputc('\n');
>> +          i = size;
>
> I'm guessing you want "xwriteall()" instead of "xwrite()";
> xwriteall retries until everything has been written.

there's no xwriteall function. see the documentation for xwrite.

>> +        }
>> +      }
>>      }
>> -    if (last!='\n') xputc('\n');
>>      if (CFG_TOYBOX_FREE) free(data);
>>    }
>>  }
>>
>> i'm assuming no one actually cares about the old Android "implicit -r"
>> behavior. if i get a complaint, adding -r is trivial. (once i learn
>> how to add an option at all :-) )
>
> Adding an option is simple:
>
> -USE_DMESG(NEWTOY(dmesg, "s#n#c", TOYFLAG_BIN)
> +USE_DMESG(NEWTOY(dmesg, "s#n#cr", TOYFLAG_BIN)
> ...
>      -n  Set kernel logging level (1-9).
> +    -r  Print the raw message buffer.
>      -s  Size of buffer to read (in bytes), default 16384.
> ...
> +  if (toys.optflags&FLAG_r) {
> +    //write the buffer in its entirety
> +  }
>
> (I suppose that this could be done with a single call to xwriteall)
> www/code.html has more on how to write things for toybox.
>
>
> And I notice now that dmesg doesn't use the FLAG_* macros, but
> instead hardcodes options by their offset in the optsring.
> It was last touched about 2 years ago just after the FLAG_* macros,
> so that isn't surprising.

cool. i'm assuming given how size-conscious you seem to be that i
shouldn't add -r until someone actually asks for it though?

 1416887441.0