Last Updated: February 25, 2016

ChronoLogger logging is 1.5x faster than ruby's stdlib Logger

Recently I created a ruby logger library named ChronoLogger (gem name is chrono_logger) that has lock free writing and time based file rotation.
This post introduces ChronoLogger features and what I learned throughout created it.

Let's just start with, see the following result comparing logging speed by ChronoLogger from ruby's stdlib Logger (hereinafter: ::Logger).
The condition is 100,000 writings by 2 threads at the same time.
ChronoLogger's logging speed is 1.5x faster, more than ::Logger.

                 user     system      total        real
std_logger: 20.220000  14.530000  34.750000 ( 24.209075)
chrono_logger: 11.950000   8.650000  20.600000 ( 13.843873)

The code is here to profiling it.

require 'benchmark'
require 'parallel'

std_logger = ::Logger.new('_std_logger')
chrono_logger = ChronoLogger.new('_chrono_logger.%Y%m%d')

COUNT = 100_000
Benchmark.bm(10) do |bm|
  bm.report('std_logger:') do
    Parallel.map(['1 logged', '2 logged'], in_threads: 2) do |letter|
      COUNT.times { std_logger.info letter }
    end
  end
  bm.report('chrono_logger:') do
    Parallel.map(['1 logged', '2 logged'], in_threads: 2) do |letter|
      COUNT.times { chrono_logger.info letter }
    end
  end
end

Why fast? There is secret that ChronoLogger has the advantage in the above case. I'm writing details about it by introducing features.

ChronoLogger's features

ChronoLogger has 2 features comparing with ::Logger.

Lock free when logging
Time based file rotation

Let's see the details.

Lock free log writing

What is lock?

What is the lock in this article?
It's a ::Logger's mutex for writing atomicity when multi-threading.
Specifically, mutex block in ::Logger::LogDevice class's write method.

Why ChronoLogger could be lock free logger?

::Logger locked for atomicity, why it can be removed?
In fact, log writing is atomicly by OS in some specific environments.
See the linux documentation, write(2) provides atomic writing when data size is under PIPEBUF, but does not say atomic when data size more than PIPEBUF.
However some file system takes lock when writing any size of data, so writing is atomic in these environments.
Therefore ChronoLogger removed lock when writing and reduce it's cost.

Please note it's not always true about lock, for this reason it's safe to check multi process behaviour in your environment.
In real, logs aren't mixed in my CentOS envirionments that has ext4 file system.
On the other hand logs are mixed when writing to pipe when data size more than PIPE_BUF.

Lock free world

Limiting environment leads lock free logger.
ChronoLogger's 1.5x faster writing is removing mutex when multi threading on top of the article.
That solves ChronoLogger's advantage in multi threading. I also tried checking performance in multi processing its results only small percent faster.

Break time :coffee:

The idea about lock free is originally from MonoLogger project.
My colleague @yteraoka told me MonoLogger a year or so ago.
MonoLogger has no file rotation function so we could not use it in production.
Anyway, it's benefit existing expert colleague, I'm thankful to my environments. :)

Time based file rotation

Logging to file having time based filename

You would notice ::Logger already has daily file rotation.
That's right, but there is a difference the way to rotate file.
Actually, ::Logger rotates file when first writing to log file in the next day.
Specifically, there is not rotated file existed when first writing in the next day.

# 2015/02/01
logger = Logger.new('stdlib.log', 'daily')
# => stdlib.log generated
logger.info 'today'

# 2015/02/02
logger.info 'next day'
# => stdlib.log.20150201 generated

This makes a tiny problem. For instance, you would compress the log file when starting the next day. You cannot compress rotated file if first writing is not started.
ChronoLogger solves this problem the way to writing a file that has time based filename. This way is same as cronolog.
The result is the following when using ChronoLogger.

# 2015/02/01
logger = ChronoLogger.new('chrono.log.%Y%m%d')
# => chrono.log.20150201 generated
logger.info 'today'

# 2015/02/02
logger.info 'next day'
# => chrono.log.20150202 generated

ChronoLogger ensure existing rotated log file when starting the next day. Except there is no writing during a day...
This is fitted about the last use case to compressing a log file.
Additionally, this way only writes to file that has a new name so it's simple, this simplicity leads also simple code.

Wrap up

ChronoLogger's pros comparing with ::Logger's are

Logging faster when multi threading by lock free
Ensure rotated file existence when starting the next day by time based file rotation

ChronoLogger's cons is a risk that logs are mixed depending on environment.
I'm beginning to use ChronoLogger and currently there is no problem in my Rails project.
I'm looking forward to receive your feedback.
HackerNews post is here.
Thanks for reading.

If you like ChronoLogger, checkout the github repository.

Performance results

I confirmed whether we can use ChronoLogger from the standpoint of performance.
Measuring code is here, but it's rough code.
Measuring environment: CentOS 6.3, file system is ext4, disk is HDD, 1G memory and 2 CPU cores with 2.4 GHz.
I confirmed we can use ChronoLogger. Anyway, MonoLogger is fastest on my selected logger. :)

$ bundle exec ruby test/benchmark.rb 
# single process
                 user     system      total        real
std_logger:  3.350000   1.070000   4.420000 (  4.420561)
with_cronolog:  3.630000   1.560000   5.190000 (  5.187311)
mono_logger:  2.860000   1.010000   3.870000 (  3.881853)
mono_with_cronolog:  2.990000   1.390000   4.380000 (  4.372675)
chrono_logger:  3.010000   1.010000   4.020000 (  4.023661)

# 2 processes
                 user     system      total        real
std_logger:  0.000000   0.010000   9.370000 (  4.701836)
with_cronolog:  0.000000   0.000000  11.090000 (  6.949749)
mono_logger:  0.000000   0.000000   8.390000 (  4.339267)
mono_with_cronolog:  0.000000   0.000000  10.640000 (  6.734415)
chrono_logger:  0.010000   0.000000   8.820000 (  4.542710)

# 2 threads
                 user     system      total        real
std_logger: 20.220000  14.530000  34.750000 ( 24.209075)
with_cronolog: 17.780000  11.210000  28.990000 ( 23.061586)
mono_logger: 13.110000   9.720000  22.830000 ( 14.918505)
mono_with_cronolog:  9.460000   5.300000  14.760000 ( 12.584132)
chrono_logger: 11.950000   8.650000  20.600000 ( 13.843873)