BalaBit Blog

In syslog-ng Store Box we wanted to provide a simple, but yet fast log viewing and searching interface, like the popular php-syslog-ng. However the performance of SQL databases when handling and indexing of high volume log messages is poor and does not really scale. SQL databases does not really handle couple of 1,000 messages per second traffic without really large hw configuration, which is usually not available for a log collection project. Therefore we created our own log indexing daemon that tokenizes messages and creates small compressed index files that could be used latter to search the messages in a free-text like manner.

The design goal was to create the indexer so it can do the indexing online as log messages received. Messages are received by syslog-ng and stored in syslog-ng’s logstore format while messages are also sent to the indexer over a unix-domain socket. There is a receiving thread that reads messages from syslog-ng and queues them for the tokenizer thread. (Hmm, I think I should write and other post on the indexer details next time, but for now back to my experiment.)

The receiving thread reads data in an infinite-loop into a 1MB buffer and parses messages from the buffer before queuing the deserialized messages for the tokenizer. As normally messages are 300-400 bytes long with a single read() we can read up to a few thousands messages in each loop. However after doing some debugging it turned out that the indexer was reading only one message in a read(). It is not really optimal as doing lot of read() syscalls involves much more overhead (context switches, cache becoming cold etc.). Why is it happing?

The other side (syslog-ng) feeds the socket, but as our receiving thread has almost nothing to do, it processes messages faster than syslog-ng could feed it, so for each read() there is normally only one message data in the socket buffer which is returned without waiting for more data to arrive. (Even the socket is in blocking mode, it return immediately as at least one byte is availble. Syslog-ng on the other end of the socket writes a message in one writev() so read() side reads that message when available.)

So, if I could just slow down my receiving thread to read() more data in one loop would help my performance. My simple solution was to add a very short sleep() before the read() so there is time to accumulate more data in the socket buffer and therefore more messages would be read(). Also more data requires more time to deserialize and to queue to the tokenizer. The data flow to the tokenizer is no problem as there is a queue in use which can buffer messages when the tokenizer can not handle the load. Of course the size of the queue should be limited. Previously the queue between the receiver and the tokenizer thread was nearly empty, now it holds between 1,000 and 20,000 messages which causes some latency of 1-2 seconds, but that is OK in our case. After some testing a 5millisec duration looked optimal for the task.

My benchmark showed roughly 25% speedup which is pretty good from a single sleep() call.

In the benchmark I was sending messages to syslog-ng that stored the messages and also forwarded them to the indexer which processed them. On my laptop (2.4GHz Core2Duo 4GB RAM x86_64) I was able to index around 20,000 messages/sec, now I can do over 25,000 messages/sec.

At the end of the day it turned out that sometime it is not that bad to sleep() in the code. (syslog-ng has a similar “time_sleep” configuration option that could be used to slow down main loop, so that sources/destinations are not checked so often and also some expensive poll() cycle could be also spared.) It is getting late, so now, it is time to sleep…

Be Sociable, Share!

•