ChronoLogger logging is 1.5x faster than ruby’s stdlib 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)
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

ChronoLogger’s features

ChronoLogger has 2 features comparing with ::Logger.

  • Lock free when logging
  • Time based file rotation

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 PIPE_BUF, but does not say atomic when data size more than PIPE_BUF. 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.

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

The idea about lock free is not my idea, I copied the idea from MonoLogger project. My colleague @yteraoka tells 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
# 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

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

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)

references

ChronoLogger

about the lock

others

--

--

A Rubyist and family man. Ruby / Elixir / JavaScript / Java / GUNDAM http://git.io/ma2ge http://about.me/ma2ge

Love podcasts or audiobooks? Learn on the go with our new app.

Get the Medium app

A button that says 'Download on the App Store', and if clicked it will lead you to the iOS App store
A button that says 'Get it on, Google Play', and if clicked it will lead you to the Google Play store
taka

taka

A Rubyist and family man. Ruby / Elixir / JavaScript / Java / GUNDAM http://git.io/ma2ge http://about.me/ma2ge