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

Recently I created a ruby logger library named ChronoLogger 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

  • Lock free when logging
  • Time based file rotation

Let’s see the details.

Lock free log writing

What is lock?

Why ChronoLogger could be lock free logger?

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

Break time

Time based file rotation

Logging to file having time based filename

# 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

  • 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. Thanks for reading.

Performance results

$ 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

Enjoy!

Originally published at coderwall.com.

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

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