5 ms·

Wait... It takes ~1ms to write a line to a log file?

by TheLoneWolfling 11y ago

anonyfox 11y ago
disk is slow, seems reasonable.
- TheLoneWolfling 11y ago
  Don't forget the Pi (generally) uses flash. So seek speeds are irrelevant. If you're writing the following in 1ms: Apr 4 22:50:59 heating kernel: [14572.940927] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x00008438 By my count that's ~1 kilobit. That means that you're writing to flash at ~1 Mb/s. (~125KB/s) That's slow, to put it mildly. (~5% of what it should be, according to http://ozzmaker.com/2012/12/27/how-to-test-the-sd-card-speed-on-your-raspberry-pi/ http://ozzmaker.com/2012/12/27/how-to-test-the-sd-card-speed... ) I could see that kind of speed if it was causing a disk seek every write (although if it was doing that you're probably using the wrong file system), but again, the Pi uses flash. So what gives? Is there braindead sync behavior that's causing it? Is it hitting a pathological case in the flash controller? Or what? (For that matter: is there a file system that is optimized for log files?)
  - tjoff 11y ago
    Just read the second comment on the link you provided and you have the answer.
    - TheLoneWolfling 11y ago
      > Nowaday’s fast Class 10 cards achieve their high read and write speeds only by buffering in advance, assuming that the subsequent blocks will be read or written next. That means they inevitably sacrifice random read and write speeds. This effect is in the order of several magnitudes. For instance, a card with sequential read and write speeds of 10 MB/s might collapse to just 0.01 MB/s for random access. Yow. Yet another example of over-optimization to benchmarks. ...Except that, even then, how exactly is appending to a log file repeatedly random access? Bad journaling?
      - trendandbeyond 11y ago
        Test
      - tjoff 11y ago
        This is much closer to random access than sequential access. Counter question: How is appending to a log file repeatedly sequential access? No meta data or other interaction required? Surely the sequential writes benefit from larger buffers? Not to mention that the flash block is way larger than the appended message. You would need TRIM to not make that an extremely wasteful operation, not sure if the typical Pi installations make use of it but a quick google seems to indicate that it at least has been a problem. So writing that 1 kbit now means reading a whole block, edit the content of it, and writing that whole block back - which is hardly sequential either. 1 Mbit/s is starting to seem pretty fast. The only pathological case here is the "not optimal sequential write case", which sure is enough to kill any random USB-thumbdrive or SD-card. Just copying two files two a thumdrive at once can kill performance by an order of magnitude compared to doing them one after another.
        TheLoneWolfling 11y ago
        This is where you benefit by having a file system (or disk controller) that isn't brain-dead. Unfortunately, it seems like both the controller and file system are brain-dead on the RPi. Namely, you have a cache that detects this sort of (relatively-common) append-only operation, and buffers it until it makes sense to actually write it (either because the disk is otherwise unoccupied or because you are close to the limits of your power buffer). Alternatively, you have a file system that actually knows the advantages and limitations of flash. You can do append-only files efficiently on flash (without doing all of the read + write dance). "All" you need to do is take advantage of a bit of scratch space and knowing how flash works. Namely that you don't necessarily need to flash a block to write to it, as long as you are only turning zeros to ones (or vice versa, depending on how physical bits are mapped to logical bits. Multilevel flash is a little more complex, but still doable). (For instance, instead of having one filestamp, you have space for 16 filestamps, with two bytes at the beginning, all initially set to all zeros. You check the last bit set and use that filestamp. Congratulations, you now can update the file 16 times before needing to reflash the block. If that's not enough, you can extend it arbitrarily (note that you can do this dynamically for files only when they are updated enough to warrant it!) And metadata/etc can be done in the same way. For something like a log file, you have, say, 16 slots for how much of the block is occupied, and a pointer to the next block (or null). You append the content of the new log line to the file and add the new content. One write, no blocks being flashed. (Two writes if/when you run out of space in the block.) See, for instance, https://github.com/bnahill/FLogFS/ https://github.com/bnahill/FLogFS/ or https://en.wikipedia.org/wiki/F2FS/ https://en.wikipedia.org/wiki/F2FS/
exDM69 11y ago
Since it's a debug log from the kernel, it makes sense to take the time to make sure it gets all the way to the disk. For many other purposes, it's fine to be quick and just do the best effort. But the kernel log is a vital resource for doing post mortem analysis if everything goes wrong and the kernel panics. It's better to be slow than unreliable in this case.
- TheLoneWolfling 11y ago
  Except that it's relatively simple to make an append-only file both quick to write and reliable on flash... It seems that both the file system and flash controller punt the relatively common (and relatively simple) case of a file being repeatedly appended to by small amounts.
a1k0n 11y ago
My theory is that it's also being written to the RPi's serial port console, which runs at 115200 baud by default, so 11520 characters/second or ~7ms to write 80 characters.
- TheLoneWolfling 11y ago
  Good theory. Alas, the author mentioned it took ~1ms, which would be ~11.5 characters, and those log messages are a lot longer than 11.5 characters.
  - tonyg 11y ago
    If I understood the article correctly, the ~1ms cost came from having rsyslog running, not from printk. Killing rsyslog led to a ~1ms speedup, but it was removing printk() that led to the rest. Printing to the console on the RPi could involve either or both of the serial port and the software-character-generator-based text-mode video output. Depending on screen resolution, the video output might be quite slow to print to, especially if it had to scroll a line, depending on exactly how it's implemented.
    - TheLoneWolfling 11y ago
      In which case, what on Earth is rsyslog doing that it takes 1ms to append a line of text to the log file? I could see it if it was outputting something to software-based video - except that in that case, why is it trying to output to software-based video?
      - JoachimSchipper 11y ago
        You need quite a few kernel<->userland switches in this case, maybe that's enough?
        TheLoneWolfling 11y ago
        Potentially, although in that case it's still dsyslog's fault.

Wait... It takes ~1ms to write a line to a log file?

anonyfox 11y ago

disk is slow, seems reasonable.

TheLoneWolfling 11y ago
Don't forget the Pi (generally) uses flash. So seek speeds are irrelevant. If you're writing the following in 1ms: Apr 4 22:50:59 heating kernel: [14572.940927] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x00008438 By my count that's ~1 kilobit. That means that you're writing to flash at ~1 Mb/s. (~125KB/s) That's slow, to put it mildly. (~5% of what it should be, according to http://ozzmaker.com/2012/12/27/how-to-test-the-sd-card-speed-on-your-raspberry-pi/ http://ozzmaker.com/2012/12/27/how-to-test-the-sd-card-speed... ) I could see that kind of speed if it was causing a disk seek every write (although if it was doing that you're probably using the wrong file system), but again, the Pi uses flash. So what gives? Is there braindead sync behavior that's causing it? Is it hitting a pathological case in the flash controller? Or what? (For that matter: is there a file system that is optimized for log files?)
- tjoff 11y ago
  Just read the second comment on the link you provided and you have the answer.
  - TheLoneWolfling 11y ago
    > Nowaday’s fast Class 10 cards achieve their high read and write speeds only by buffering in advance, assuming that the subsequent blocks will be read or written next. That means they inevitably sacrifice random read and write speeds. This effect is in the order of several magnitudes. For instance, a card with sequential read and write speeds of 10 MB/s might collapse to just 0.01 MB/s for random access. Yow. Yet another example of over-optimization to benchmarks. ...Except that, even then, how exactly is appending to a log file repeatedly random access? Bad journaling?
    - trendandbeyond 11y ago
      Test
    - tjoff 11y ago
      This is much closer to random access than sequential access. Counter question: How is appending to a log file repeatedly sequential access? No meta data or other interaction required? Surely the sequential writes benefit from larger buffers? Not to mention that the flash block is way larger than the appended message. You would need TRIM to not make that an extremely wasteful operation, not sure if the typical Pi installations make use of it but a quick google seems to indicate that it at least has been a problem. So writing that 1 kbit now means reading a whole block, edit the content of it, and writing that whole block back - which is hardly sequential either. 1 Mbit/s is starting to seem pretty fast. The only pathological case here is the "not optimal sequential write case", which sure is enough to kill any random USB-thumbdrive or SD-card. Just copying two files two a thumdrive at once can kill performance by an order of magnitude compared to doing them one after another.
      - TheLoneWolfling 11y ago
        This is where you benefit by having a file system (or disk controller) that isn't brain-dead. Unfortunately, it seems like both the controller and file system are brain-dead on the RPi. Namely, you have a cache that detects this sort of (relatively-common) append-only operation, and buffers it until it makes sense to actually write it (either because the disk is otherwise unoccupied or because you are close to the limits of your power buffer). Alternatively, you have a file system that actually knows the advantages and limitations of flash. You can do append-only files efficiently on flash (without doing all of the read + write dance). "All" you need to do is take advantage of a bit of scratch space and knowing how flash works. Namely that you don't necessarily need to flash a block to write to it, as long as you are only turning zeros to ones (or vice versa, depending on how physical bits are mapped to logical bits. Multilevel flash is a little more complex, but still doable). (For instance, instead of having one filestamp, you have space for 16 filestamps, with two bytes at the beginning, all initially set to all zeros. You check the last bit set and use that filestamp. Congratulations, you now can update the file 16 times before needing to reflash the block. If that's not enough, you can extend it arbitrarily (note that you can do this dynamically for files only when they are updated enough to warrant it!) And metadata/etc can be done in the same way. For something like a log file, you have, say, 16 slots for how much of the block is occupied, and a pointer to the next block (or null). You append the content of the new log line to the file and add the new content. One write, no blocks being flashed. (Two writes if/when you run out of space in the block.) See, for instance, https://github.com/bnahill/FLogFS/ https://github.com/bnahill/FLogFS/ or https://en.wikipedia.org/wiki/F2FS/ https://en.wikipedia.org/wiki/F2FS/

exDM69 11y ago

Since it's a debug log from the kernel, it makes sense to take the time to make sure it gets all the way to the disk. For many other purposes, it's fine to be quick and just do the best effort. But the kernel log is a vital resource for doing post mortem analysis if everything goes wrong and the kernel panics. It's better to be slow than unreliable in this case.

TheLoneWolfling 11y ago
Except that it's relatively simple to make an append-only file both quick to write and reliable on flash... It seems that both the file system and flash controller punt the relatively common (and relatively simple) case of a file being repeatedly appended to by small amounts.

a1k0n 11y ago

My theory is that it's also being written to the RPi's serial port console, which runs at 115200 baud by default, so 11520 characters/second or ~7ms to write 80 characters.

TheLoneWolfling 11y ago
Good theory. Alas, the author mentioned it took ~1ms, which would be ~11.5 characters, and those log messages are a lot longer than 11.5 characters.
- tonyg 11y ago
  If I understood the article correctly, the ~1ms cost came from having rsyslog running, not from printk. Killing rsyslog led to a ~1ms speedup, but it was removing printk() that led to the rest. Printing to the console on the RPi could involve either or both of the serial port and the software-character-generator-based text-mode video output. Depending on screen resolution, the video output might be quite slow to print to, especially if it had to scroll a line, depending on exactly how it's implemented.
  - TheLoneWolfling 11y ago
    In which case, what on Earth is rsyslog doing that it takes 1ms to append a line of text to the log file? I could see it if it was outputting something to software-based video - except that in that case, why is it trying to output to software-based video?
    - JoachimSchipper 11y ago
      You need quite a few kernel<->userland switches in this case, maybe that's enough?
      - TheLoneWolfling 11y ago
        Potentially, although in that case it's still dsyslog's fault.