The logger meets linux-kernel

Posted Jan 5, 2012 0:16 UTC (Thu) by dlang (guest, #313)
In reply to: The logger meets linux-kernel by neilbrown
Parent article: The logger meets linux-kernel

how fast do you need to be? rsyslog has been measured at 1M logs/sec for fairly trivial situations (which this would probably be).

however, I'll bet that you are really talking about much lower data rates, I'd be surprised if you needed much over 100 logs/sec and amazed if you need over 1000 logs/sec (remember, we're not talking about logs from the kernel here, we're talking about logs from userspace, the type of thing that is sent to syslog on a traditional linux distro, or is written to a app-specific log file)

the fact that the kernel is involved at all is simply a desire from the android developers to avoid having a userspace daemon.

for the trivial capabilities that the logger currently has (listen to a filesystem name, accept anything written to it into a circular buffer, and regurgitate the buffer if requested), it seems to me that a pretty trivial userspace daemon should be able to do this. I still haven't seen any explanation (other than the "we didn't want another daemon running" one) for why the kernel should be involved at all.

The logger meets linux-kernel

Posted Jan 5, 2012 0:52 UTC (Thu) by neilbrown (subscriber, #359) [Link] (1 responses)

By "fast" I didn't mean raw bytes-per-second speed but rather how much it slows down the rest of the system. Android needs to run on slow phones as well a quad-core monsters and we don't want to waste cycles on logs that probably aren't going to be read.

I don't think we are just talking about the stuff that a normal distro sends to syslog. Brian observed that app developers complain that other apps send too many message to the log so "their" much more important messages fall off the end of the log. This suggests a high rate of log-spam.

The kernel is *always* involved. Even if you use shared memory, who do you think it is that maps the memory into each process on the relevant page faults?

Yes: by pre-faulting large shared memory images and using futexs you could interleave logs from multiple processes with little interaction with the kernel (if each process ran on its own processor) but that doesn't fit the android security model. Each process has it's own uid and doesn't trust other processes (or at least the log system doesn't trust any of it's clients beyond the fixed API). So shared-memory logging doesn't really meet the need.

The logger meets linux-kernel

Posted Jan 5, 2012 1:26 UTC (Thu) by dlang (guest, #313) [Link]

if you want to define it, you can define any inter-process communication to involve the kernel, but most people would not talk the kernel to provide standard syslog /dev/log functionality, even though the kernel is involved.

given that they have a rather tiny fixed-size buffer (256K was mentioned), having enough logs generated to fall off the end does not really equate to that large a data rate.

But even if high performance is needed (and note that I am still not agreeing that it is), that doesn't, by itself, justify implementing something in the kernel. That's why we no longer have the tux webserver in the kernel, and there have been many other things proposed that "required" kernel level implementations for performance reasons, that ended up not going in to the kernel.

the fact that we haven't been able to get anyone to talk about data rates other than the very generic "overrunning a 256K buffer in seconds" doesn't do much to justify this going into the kernel.

I'll bet just about any linux system generates > 256k of syslog messages in 'seconds' as it boots up.

In fact, I have a server that I just rebooted, in it's first second, syslog shows >100K of message data in syslog (and this is a pretty stripped down kernel and boot, I'll bet standard distro kernels end up logging quite a bit more)

The logger meets linux-kernel

Posted Jan 5, 2012 16:41 UTC (Thu) by PaulMcKenney (✭ supporter ✭, #9624) [Link] (12 responses)

Battery lifetime is critically important to the Android folks. This is related to the raw performance metrics you are thinking in terms of, but not exactly the same. And the differences are part of the reason that they don't want to have another user-space daemon running.

The logger meets linux-kernel

Posted Jan 5, 2012 17:39 UTC (Thu) by dlang (guest, #313) [Link] (11 responses)

remember that the userspace daemon can be suspended along with the rest of userspace, so it's not keeping the system alive if nothing else is.

and in any case, where are the numbers?

how much traffic are we actually talking about here, what how much processor does it take to do this in kernel space, how much more in userspace (and even if it's 100x more, is it enough to actually matter?)

What matters

Posted Jan 5, 2012 18:03 UTC (Thu) by PaulMcKenney (✭ supporter ✭, #9624) [Link] (10 responses)

Heh! Over the past couple of years, I have been repeatedly taken to task for RCU's being insufficiently aggressive about allowing the scheduler-clock tick being disabled. As in a handful of ticks at the beginning of an idle period.

So the sensitivity to CPU consumption is way higher than I would have guessed a couple of years ago. In addition, there are other well-known issues that arise when relying on a separate daemon in addition to efficiency. I have run into them many times over the years (make that decades), and I would guess that you have as well.

It is instructive to turn the question around. First, start with the assumption that the Android guys actually are competent in their area of expertise. Then ask yourself why a userspace daemon might be problematic for them.

What matters

Posted Jan 5, 2012 18:58 UTC (Thu) by dlang (guest, #313) [Link] (9 responses)

the problem is that by that logic, just about everything should be in the kernel.

I really believe that this is premature optimization and micro-benchmark optimization.

to restate an example I've posted before, several years ago at $work, the engineers ran a benchmark that showed a 60x performance improvement (from 30 seconds to .5 seconds) for a read_config() function by creating a shared memory segment and populating that rather than reading from disk.

the problem is that this benchmark was for 100,000 reads of the config file, and the real-world usage showed that this function was executed 50,000 times in an hour across >50 machines. This 6-month engineering project saved a total of 15 cpu seconds in a peak hour across 200 cores.

sometimes "it's faster", even for high multipliers of how much faster just don't matter because the function just isn't called frequently enough.

I have some firewalls that run 'inefficient' fork-for-every-connection proxies (horribly inefficient, right), but on a peak day these systems (on low-end hardware) still don't hit a loadaverage of 0.2, so the inefficiency really doesn't matter.

application logging just isn't that heavy, even on a 'slow' cell phone processor.

What matters

Posted Jan 5, 2012 20:48 UTC (Thu) by PaulMcKenney (✭ supporter ✭, #9624) [Link] (7 responses)

OK, so the short version of this story is that you are not willing to assume that the Android guys are competent within their area of expertise.

Fair enough.

Just don't be surprised when others return the favor by being unwilling to assume that you are competent within your area of expertise.

What matters

Posted Jan 5, 2012 21:26 UTC (Thu) by dlang (guest, #313) [Link] (6 responses)

when it comes to performance claims, nobody's claims of need, without the backing of numbers should be believed.

In general, this is exactly how it works in kernel development.

What matters

Posted Jan 5, 2012 22:10 UTC (Thu) by PaulMcKenney (✭ supporter ✭, #9624) [Link] (5 responses)

Interesting.

How did you determine that the Android guys' avoidance of user-mode daemons was strictly due to performance issues?

What matters

Posted Jan 5, 2012 22:51 UTC (Thu) by dlang (guest, #313) [Link] (4 responses)

I'm basing this on their statements on l-k in the logger thread. It's always possible that I'm misunderstanding what they are meaning or missed something

What matters

Posted Jan 5, 2012 23:13 UTC (Thu) by dlang (guest, #313) [Link] (3 responses)

unfortunately with my schedule for the last month and the next few weeks, I have no time to try this, but I don't think that it would be very hard to hack together a user-space replacement for the journal that listened on a few unix sockets, stored the results in a circular buffer, and provide a control socket for requesting the data get dumped out

What matters

Posted Jan 6, 2012 16:35 UTC (Fri) by PaulMcKenney (✭ supporter ✭, #9624) [Link] (2 responses)

It would be really cool if you did get a chance to try this out!

One caution: It is difficult to get requirements from the Android guys. Not because they are uncooperative, but because they are only conscious of some of the requirements. The rest are so second-nature to them that they don't think of them. This means that working on a suitable replacement is an iterative process, where you learn the requirements by repeatedly implementing your best guess at each point in time.

John Stultz has gone through much of this process with his alarm-timers work, and he does appear to be getting close to a solution that is useful to both the Android guys and to non-smartphone software.

I have been on both sides of this. Back in the 1990s, those of us at Sequent habitually wrote parallel programs, but could not describe how to do it to others. We did try, but the results were not so good. Instead, we used apprenticeship-style training: We put the new guy in a cube surrounded by people who knew parallel programming, and after a few months, the new guy would have no problem writing competent parallel code.

I was on the other side while gathering wakelock requirements in 2010 and 2011. The “Avoid Thundering Herds of Timers” requirement is an example of an important requirement that was not at all obvious to me, but so obvious to the Android guys that they didn't think to state it.

Sort of like you would probably not see the need to put “the acceleration of gravity at the site is 9.8 meters per second squared” when creating specs for a builder. ;–)

What matters

Posted Jan 12, 2012 23:20 UTC (Thu) by Kluge (subscriber, #2881) [Link] (1 responses)

"Sort of like you would probably not see the need to put “the acceleration of gravity at the site is 9.8 meters per second squared” when creating specs for a builder. ;–)"

Does this mean that Android developers are from Mars, kernel hackers from Venus? ;-)

Mars and Venus

Posted Jan 13, 2012 0:54 UTC (Fri) by PaulMcKenney (✭ supporter ✭, #9624) [Link]

;-) ;-) ;-)

What matters

Posted Jan 18, 2012 6:02 UTC (Wed) by kevinm (guest, #69913) [Link]

It's not the time taken by the extra cycles that matters - of course a user space daemon could keep up with the rate of message, even on a slow processor.

Rather, it's the fact that every extra cycle wasted is an extra cycle that the CPU must remain in a higher power state, and thus represents an incremental hit to the battery life. Recall in particular that context-switching from one userspace process to another requires a cache-flush on older ARM processors.