Performance: g2log vs Google's glog

Home      KjellKod Code Page   g2log part 1

[Part 2] Performance: g2log vs. Google's glog 

In this page, g2log Part 2, I will show how a very effective, [#pseudo asynchronous], but still synchronous logging utility (
Google's glog version 0.3.1), compares to an asynchronous logger (g2log). The performance section shows that the asynchronousg2log is much more efficient, especially in a worst case scenario. This section can be read standalone for anyone who is interested in g2log's performance.
 
  1. 1 Introduction: Performance comparison
  2.  1.1 The actual LOG call
  3. 2 Rationale for the comparison
  4. 3 Facts and numbers
  5. 4 Simplified description of Pseudo Asynchronous
  6. 5 Performance comparison
  7.  5.1 Average LOG call times
  8.  5.2 Average LOG call times with congestion
  9.  5.3 Maximum LOG call times
  10.  5.4 The complete picture
  11. 6 Background thread: Total times - improvement

  12. 7 Performance conclusion


Introduction: Performance comparison

glog is a good candidate for comparison since it is very fast on the average, maybe even the fastest synchronous logger due to its pseudo asynchronous behavior. Even though glog is very effective, it is outperformed by g2log both for the average case and for the worst case scenario.

The purpose of this performance comparison is in no way meant to discredit Google's glog. Quite the contrary. I believe that Google's glog is an amazing piece of software and it provides a lot more functionality than g2log probably ever will. The purpose of this performance comparison is instead to test g2log against a very good synchronous logger. Through this comparison, I hope that the performance differences and why they differ will be obvious. I hope also that it will be clear when an asynchronous logger truly is preferable.

The actual LOG call

Since g2log uses both printf and stream-like APIs but their performances are similar, I show only tests using exactly the same streaming LOG call for g2log as for glog.

LOG(INFO) << title << " iteration #" << count << " " 
  << charptrmsg << strmsg << " and a float: " << std::setprecision(6) << pi_f;

 

Rationale for the comparison

On Google glog's forum, I noticed that requests for an asynchronous glog was met with silence. It was partly because of this I decided to make g2log.

Much later, I got contacted by a software engineer who had noticed my asynchronous feature request on the forum. He was also frustrated with glog's (quote) "poor performance" and naturally interested in the asynchronous g2log. I do not know if he is using g2log today or not, but thanks to his expressed need for improved performance, I decided to include this performance comparison.

 

Facts and numbers

All the data used here can be viewed in an online spreadsheet. The performance tests are easily reproducible since they come with the g2log code. I have also attached a copy of the performance measurements logs in case someone would like to have access to it.

The tests were made on a Dell Latitude E6500 laptop, Intel Core2 Duo CPU P8600 2.40GHz x2, with a solid state drive. On another system using a standard harddrive, the difference between synchronous (glog) and asynchronous (g2log) would be larger.

 

Simplified description of pseudo asynchronous

The key to the pseudo asynchronous performance is that glog buffers log entries. Every buffered LOG call is very fast since slow disk access is avoided. At certain triggers, or when the buffer is full, a flush-to-disk operation is performed. This results in that the latest log entry is penalized by the disk I/O access time for many previous entries.

The buffer-then-flush method gives a better average performance than a truly synchronous logger. However, every now and then, performance will be hit as all of the log entries are written to file at once.

 

Performance comparison

As previously stated, g2log manages disk access I/O in the background. This means that the call to make a log entry will result in a string that is asynchronously forwarded to a background worker. The worker is in due time saving the text to file.

Apart from that g2log is asynchronous, no real optimization has been made. This can be shown below where the average times sometimes do not differ too much between the two logger utilities. In the worst case scenario, when I/O wait times peak, that's when glog suffers and g2log shines.

Average LOG call times

For the average case, it is not always a big difference between the two. The pseudo asynchronous behavior gives glog good results for a test run of 1 thread creating 1 million log entries. The numbers used below can be viewed at the online performance chart tab "Tab for 1 million entries".

Average Application time per call [us]: 1 thread creates 1 million log entries
g2log glog g2log % better than glog
9.56 11.113 13.97%

1 thread writing 1 million log entries


Average LOG call times with congestion

It is apparent that the total time (ref: the online spreadsheet) is more than the time spent for glog. The total time is the time from when the LOG calls started to when all the LOG calls are on file.

This is as it should be: g2log does not buffer log entries, not even if writing several log entries at once, instead the background thread writes them to file as soon as a log entry is available. This is an area where the background thread on g2log is not optimized. However, it is also of less importance - the important time to keep low is the application time. It is the application wait time for a LOG call to be finished that will slow down the LOG caller.

When adding contention, the average times for Google's glog worsens. Every now and then, the threads will have to wait a long time when the thread-safe buffer is emptied and written down to file.

Average application time per call, in microseconds [us], 4 threads, each creating 1 million log entries
g2log [us], glog [us], g2log % better than glog
6.52 12.45 47.63%
4 threads, each writing 1 million log entries


Clearly, g2log outperforms even a pseudo asynchronous logger on the average as soon as there is congestion. The slow I/O is definitely penalizing the software if not done in the background.

Maximum LOG call times

With thread switching, mutex overhead, etc., there will of course be some peak wait times for g2log. Using a test setup with different number of threads, it is clear how these peak times increase with the data load. Compared to glog, the peak times for g2log pales in comparison. g2log's peak times are in the range of 10 - 35 times less than glog's peak times [online spreadsheet tab: maximum times].

How maximum and peak times, in milliseconds [ms], increase with the number of threads. Each thread is writing 1 million log entries.
threads g2log [ms], glog [ms], g2log factor better than glog
1 13 459 35.31
2 28 920 32.86
4 42 925 22.02
8 66 914 13.85
16 113 1065 9.42

1 to 16 threads, each writing 1 million log entries


The complete picture

To really show how the peak times can hit performance, a scatter chart is used below. Maybe this graph is a good wake-up call for synchronous log users? [Online spreadsheet tab: complete picture comparison]

Below is the same data shown but in an area chart. The red noise in the end are the peak times. Although it might look insignificant, they represent a significant part of the total time consumption.


Background thread: total times - improvement

What is not shown here, but available in the online spreadsheet, are the total times for the background logger. With the current implementation, the g2log background thread writes log entries to disk as soon as one is available. This is of course not efficient, since every new disk access operation is slow.

This can be optimized if, for some reason, the total disk I/O time must be decreased for the background thread. An easy optimization would be to use the glog's scheme, but on the background thread's side. By buffering log entries in the background, and flushing it on triggers (time, or buffer full), the total disk I/O time would be significantly decreased.

 

Conclusions

Performance conclusion

It is obvious that KjellKod's g2log is faster than Google's glog, both when measuring the average times and when measuring the worst cases. This has more to do with the fact that glog is (partly) synchronous in nature while g2log is asynchronous. In the average case, Kjellkod's g2log is 10-48% faster than Google's glog. In the worst case scenarios, g2log is a factor 10-35 times faster than glog.

The pseudo asynchronous glog is much more efficient than a traditional synchronous logger. However, the peak times are alarming and discouraging.

The tests were made on a laptop with a solid state drive. On another system using a standard hard drive, with even slower disk access, the difference between synchronous (glog) and asynchronous (g2log) would be considerable.

The implication of using a synchronous logger is that sometimes the I/O wait times will be long. Using a synchronous logger can halt the log calling thread for a very long time. This is usually not desired since being responsive is a normal software design goal.

G2log's average time is less than glog's average time. In the worst case scenario, the asynchronous g2log has a tremendous advantage over the synchronous glog.

 

ċ
2011-11-14-peformance-measurements-raw-files.zip
(20k)
Kjell Hedström,
Nov 15, 2011, 1:54 PM
Comments