Folks,
We are trying to apply journald as default (and only) logging system
for our ARM-based handhelds. There is one major problem, though -
performance.
We have found that journald can consume considerable amount of CPU
time under moderate load (10-20% of CPU per, for say 100-300msg/s).
We have profiled journald and there are few places that could benefit
from _some_ optimizations but I have come to conclusion it isn't
journald code that is real bottleneck - it's, or seems to be,
synchronous nature of send()/recv(). In default configuration each
send() can cause context-switch which is especially costly on ARM.
This is why I decided to try to make logging completely async and see
if/what changes.
Following patchset (based on top of f20c84c15f3) implements pickup
logic in journald [patch 1] and uncoditionally enables it in client
api [patch 2].
In short - instead of sending DGRAMs I do drop files to /dev/shm
which are then picked up by journald at specified intervals.
(Precisely, I have (ab)used mechanism used to pass fd via DGRAM
when message is too big.)
Patch 3 contains standalone test program, which floods journald with
specified number of messages per second.
On my development (x86) machine I made following test with good old
time(1):
# send 2000 messages (each of size 100 bytes) to journal per second
# for ~5mins
./journal-feeder 2000 100 & sleep $((60*5 - 10)) && kill $!
Unpatched systemd:
==================
/usr/bin/time --verbose ./systemd-journald & sleep $((60*5)) && kill $(pidof
systemd-journald)
User time (seconds): 16.87
System time (seconds): 39.38
Percent of CPU this job got: 18%
Elapsed (wall clock) time (h:mm:ss or m:ss): 5:00.06
Major (requiring I/O) page faults: 30
Minor (reclaiming a frame) page faults: 1061740
Voluntary context switches: 496757
Involuntary context switches: 497
File system inputs: 0
File system outputs: 50592
Deferred pickup every 5 secs (logs passed via /dev/shm/FILE rather than DGRAMs):
================================================================================
/usr/bin/time --verbose ./systemd-journald & sleep $((60*5)) && kill $(pidof
systemd-journald)
User time (seconds): 8.27
System time (seconds): 8.40
Percent of CPU this job got: 5%
Elapsed (wall clock) time (h:mm:ss or m:ss): 5:00.36
Major (requiring I/O) page faults: 180
Minor (reclaiming a frame) page faults: 38976
Voluntary context switches: 157
Involuntary context switches: 1933
File system inputs: 8
File system outputs: 307312
Deferred pickup every 1 sec (logs passed via /dev/shm/FILE rather than DGRAMs):
===============================================================================
/usr/bin/time --verbose ./systemd-journald & sleep $((60*5)) && kill $(pidof
systemd-journald)
User time (seconds): 9.54
System time (seconds): 9.56
Percent of CPU this job got: 6%
Elapsed (wall clock) time (h:mm:ss or m:ss): 5:00.15
Major (requiring I/O) page faults: 180
Minor (reclaiming a frame) page faults: 39034
Voluntary context switches: 382
Involuntary context switches: 2359
File system inputs: 0
File system outputs: 307768
This is quite naive test as a far more changes when we pass fd instead
of DGRAM (ucred is NULL, which means we won't gather information from
proc at all). However, we verified that cost of this is rather minor
and not that important in this test.
Of course, I'm not proposing to include it as is (uncoditionally
enable it for all messages) but I would just like to hear your opinion
about this idea.
If I read these numbers correctly there seems to be considerable
benefit in terms of CPU time. Something like that wouldn't be useful
for all messages, but I think that gazzilions of debug messages that
our apps produce could be send in non-synchronous and low-overhead
manner.
RFC.
Thanks in advance!
Karol Lewandowski (3):
journald: Add deferred log processing logic
journal: Try to pass log via /dev/shm to avoid waking up journal
journal-feeder: trivial test program to flood journald
journal-feeder.c | 64 +++++++++++++++++++++++
src/journal/journal-send.c | 39 ++++++++++++++
src/journal/journald-gperf.gperf | 2 +
src/journal/journald-server.c | 107 +++++++++++++++++++++++++++++++++++++++
src/journal/journald-server.h | 5 ++
src/journal/journald.conf | 2 +
6 files changed, 219 insertions(+)
create mode 100644 journal-feeder.c
--
1.8.4.rc3
_______________________________________________
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/systemd-devel
