Search this site


Metadata

Articles

Projects

Presentations

Ruby's DateTime::strptime vs libc strptime

A project I'm working on has some odd slowness about it. Using ruby-prof, I found that String#scan was consuming most of the time, but ruby-prof didn't tell me where it was coming from. A quick hack that replaced String#scan with my own method showed who was calling it, DateTime.strptime -
class String
  def scan(*args)
    raise
  end
end
I tried using the ruby debugger to break on String#scan, but it didn't seem to work. PEBCAK, probably, which is why I used the solution above to just toss an exception when that function was called.

Back at the point, DateTime.strptime is slow. Looking at the underlying code shows you why: date/format.rb - the _strptime_i method.

Lots of string shuffling, regular expressions to match field specifiers (%d, etc), string modification with more regexps, etc. The code is pretty easy to read, but it's still doing a lot of work it doesn't need to be doing. Luckily, libc comes with a method for parsing times in the same way: strptime.

So, I started working on an extension to the Time class that invokes libc's strptime and returns a Time instance: ruby-ctime. The usage is simple once you have the module:

require "CTime"

puts Time.strptime("%Y", "2009")
# outputs 'Wed Jan 00 00:00:00 +0000 2009'
The one major holdback from strptime is that there's no wide support for timezones. Format strings like %Z and %z work with strftime, but generally are unsupported by strptime; exceptions that do support %z are glibc, and freebsd appears to support both %Z and %z. Nothing reliably cross-platform. This is a historical problem due to the fact that the 'struct tm' structure has no timezone field (glibc and the bsds add 'long tm_gmtoff' to support timezones).

This means we'll have to correct for this by extending strptime to support it, but I'm not there yet.

Anyway, short benchmarking for features supported by both libc strptime and DateTime strptime shows libc a massive winner:

snack(~/projects/ruby-ctime) % ruby test.rb
Iterations: 10000
datetime: 7.680928 (1301.92601727291/sec)
my_strptime: 0.126583 (78999.5497025667/sec)
A 60x speedup using the new C code vs DateTime.strptime. This is a great start, but we still need timezone support. I need to hack timezone support into this, which probably means I'll start with glibc's strptime implementation.

Grok speed improvements

The benchmark for testing speed improvements was to process 3000 lines for '%SYSLOGBASE .*? %IPORHOST%'. Profiler was Devel::Profile.

Before:

time running program:  11.9738  (85.07%)
number of calls:       409362

%Time    Sec.     #calls   sec/call  F  name
64.52    7.6336     2870   0.002660     main::meta2string
10.00    1.1838     5740   0.000206     main::filter
 8.88    1.0507     3000   0.000350     main::handle
 3.14    0.3710    54828   0.000007     main::handle_capture
 0.77    0.0908     2870   0.000032     main::react
After
time running program:  2.5216  (82.73%)
number of calls:       105152

%Time    Sec.     #calls   sec/call  F  name
40.56    1.0228     3000   0.000341     main::handle
15.22    0.3838    54828   0.000007     main::handle_capture
 4.47    0.1128     2870   0.000039     main::meta2string
 3.31    0.0834     2870   0.000029     main::react
 2.61    0.0658    14747   0.000004     main::debug
 1.81    0.0456      237   0.000192     main::readlog
Primary changes were mostly to pregenerate a few regular expressions. Previously, I was generating the same regex every time filter() or meta2string() was being called. These small changes gave grok a serious boost in speed: what was taking 12 seconds now takes 2.5 seconds.

One example of a simple optimization is this:

before: my $re = join("|", map { qr/(?:$_)/ } keys(%$filters));
after:  our $re ||= join("|", map { qr/(?:$_)/ } keys(%$filters));
This may decrease readability, but it only sets $re once no matter how many times that line of code is executed. This line of code change was in the filter() function. Just doing this one simple change reduced the runtime of each filter() call by 97%; which reduces its runtime to something trivially small by comparison.

At this point, this is where I was very happy to have written tests for grok. To verify that grok still behaved properly after making these speed improvements, I just ran the tests suite. It passed, giving me some confidence in the stability of the changes.