syslog-ng fun with performance

I like christmas for a number of reasons: in addition to the traditional "meet and have fun with your family", eat lots of delicious food and so on, I like it because this is the season of the year when I have some time to do whatever I feel like.

This year I felt like doing some syslog-ng performance analysis. After reading Ulrich Deppert's series about stuff "What every programmer should know about memory" on LWN, I thought I'm more than prepared to improve syslog-ng performance. Before going any further, I'd recommend this reading to any programmer, it's a bit long but every second reading it is worth it.

As you need to measure performance in order to improve it, I wrote a tool called "loggen". This program generates messages messages at a user-specifyable rate. Apart from the git repository you can get this tool from the latest syslog-ng snapshots.

Loggen supports TCP, UDP and UNIX domain sockets, so really almost everything can be measured.

Then I've put together a test environment, which consisted of a 4-way Opteron box as a server (two dual-core CPUs at 2.6GHz and 1MB of cache), where the syslog-ng center ran in 64 bit mode, and a venerable P4 Xeon 2.4GHz as client. I verified that the client was more than capable of saturating a 100MBit link that was used to connect the two boxes. Then I've installed syslog-ng on the server, using the simplest configuration possible: fetching messages from the TCP/UDP socket and writing everything to disk into a plain, text file without macros in the filename.

Syslog-ng 2.o OSE performed somewhat better than I had anticipated. When using TCP it could successfully process messages at about 44000 messages/sec without losing a single message. Each message was 150 byte long (I've started with 200, but the 100MBit link proved to be the bottleneck) Some funny findings:

• Enabling flow-control did not really make the results worse.
• Increasing log-fetch-limit to a large number (10000) made the results worse.
• Using the Glib GSlice allocator instead of malloc/free didn't improve the numbers.

Of course once you have a baseline, there are a lot of possibilities to try how that given change affects performance, but I only had a day :)

I've found some things that improved performance even further, the most important bottleneck was the time related functions in libc (localtime, mktime, strftime, etc.) For some reason they reread /etc/localtime upon every invocation. I'm going to file a ticket in their bugzilla as it's completely unnecessary to do that, especially if the value of the TZ environment variable does not change.

At the end of the day I finished with syslog-ng chewing messages at around 68500 messages/sec which is a 55.9% improvement. I can see some further possibilities, but I doubt I could increase performance over 75000 msg/sec. This means that syslog-ng can process messages at about wirespeed of a 100MBit/sec ethernet link. (68500*150 = 10275000 bytes/sec)

I was very satisfied at this point, even explained my findings to my wife and my elder brother :)

This of course does not apply to legacy UDP based syslog traffic directly, unless a really large socket buffer is set for syslog-ng. I'd say that you need 3-5 seconds worth of receive buffer in order to avoid losing messages, which with the above rate would be about 30MB-50MB of non-swappable kernel memory.

These changes were committed to the Premium Edition of syslog-ng, although the loggen program is GPLed, so anyone can do performance testing their own setup/configuration.

syslog-ng stuff and christmas

We've been busy recently on the syslog-ng front. A new release came out from both the Open Source and Premium Editions, covering various bugfixes, the most important being a fix for an easy denial of service. Please upgrade to at least OSE 2.0.6 and PE 2.1.8, my bugtraq posting has more details.

A new release from the syslog-ng documentation was also published, it contains a new chapter on losing messages and another one which explains the "Log statistics" message generated by syslog-ng.

And since, I'm writing this entry I wanted to say "Merry Christmas" to all the readers of this blog:
Marry Christmas and a Happy New Year.

I'm spending the winter holiday with my wife and I'm going to travel a lot around the country to visit relatives. So I'm not sure I can be very productive in the coming days.

syslog-ng disk based buffering

I've just seen a post on the loganalysis mailing list how easy it is to implement disk-based buffering with perl and a few hours time. The implementation would be as simple as sending the messages to a file and using a script like "tail -f" to follow the file and send messages to the desired log collectors.

Although the scheme that was described would work, I see three important problems:

• latency: because the solution would work by polling the log file, the latency is severely increased, when you have thousands of log entries per second, a second is a long time. And you don't want to poll more often than every second.
• disk usage: relaying the data would store everything on the local disk, no upper bound on disk usage, if the disk is full, data is lost
• load: using an interpreted language and the requirement to store all data on disk puts an enormous load on the system that might be spent better elsewhere.
  

Syslog-ng on the other hand uses a spool file, but this file is only written when the memory based buffer becomes full. For the generic case all messages come and go, without touching the disk at all or having to poll the disk for changes. The disk space requirements are bounded. Disk buffering with the combination of flow-control and disk buffers you can avoid message loss.

And what's more, the disk spooling in syslog-ng is an independent feature for all flow-controllable destinations: tcp(), unix-stream(), pipe(), program() and also sql().

Adding a disk buffer to a destination is as simple as specifying the buffer size in bytes:

destination d_tcp { tcp("logserver" log_disk_fifo_size(100000000)); };

This means that a 100MB of space is allocated for disk-based spooling to store messages whenever "logserver" is not fast enough or is unavailable.

For more information read the syslog-ng documentation about the way this feature works.

IBM System i

I was learning computer programming while at secondary school, at as a school assignment we had to create an accounting system on a venerable IBM 360. We had 386dx computers back then with 2MB RAM, the first Linux encounter at this time required me and my friend to put all of our RAM modules to a single computer to get 4 megs and make it suitable for Linux.

This 360 machine had two CPUs, each the size of a large office desk, speed comparable to an 386, had 8MB of RAM. After getting used to the speed it provided (had 8 terminals on a 2400 baud modem) it was fun, completely different to the PCs we've had, but still, interesting.

Some of this memories were brought back by our partnership with Patownsend & Associates, a US based company to deliver System i (formerly AS400) and System z (the mainframe) software. Our partnership focuses on the development of a Syslog agent for System i, this way we could extend our syslog-ng Premium Edition offering with support for IBM midrange servers.

AS/400 (or System i), is a very interesting platform, somewhat reminding me to the IBM mainframe at secondary school. Text display on tn3270 terminals, all commands always starting with the letter 'Q', filenames condensed to a point where it is difficult to understand their meaning (QAUDJRN anyone? :) ), but at the same time a very consistent and very use-case oriented interface. The system is very complete, while a UNIX contains the stream-of-bytes file concept, OS/400 supports many different file types, for instance there's a file type of SQL tables, a complete DB2 is integrated into the OS itself.

It was a great experience to work with the Patownsend guys, knowledgeable people, who know what they are doing. I'm looking forward to our cooperation.