News from std.log

[Jose Armando Garcia]

Now that std.log is nearly complete on the set of features for it
first release. I thought I compare it against glog. The synthetic load
generator for glog is written in C++ and compiled without any flag.
The synthetic load generator for std.log is written in D and compiled
without any flag. The test does the following:

1) Reads std/traits.d into memory and each line is stored in an
"array". In C++ I use std::vector<std::string>; in D I use string[].
2) Iterate through the "array" 1000 times and log each line at INFO
level. Note: no conditional logging e.g. when() in std.log.

Here are some result of executing /usr/bin/time ...:
glog:
45.03user 14.28system 1:01.82elapsed 95%CPU (0avgtext+0avgdata 5856maxresident)k
0inputs+523512outputs (0major+406minor)pagefaults 0swaps

std.log:
72.76user 12.61system 1:29.95elapsed 94%CPU (0avgtext+0avgdata 8608maxresident)k
0inputs+439168outputs (0major+594minor)pagefaults 0swaps

Now for the interesting part; here are the result if I disable info
logging at runtime. Note: This not compile time disabling.

glog:
36.44user 7.95system 0:44.47elapsed 99%CPU (0avgtext+0avgdata 5504maxresident)k
0inputs+0outputs (0major+384minor)pagefaults 0swaps

std.log:
2.50user 0.01system 0:02.53elapsed 99%CPU (0avgtext+0avgdata 5280maxresident)k
0inputs+0outputs (0major+374minor)pagefaults 0swaps

Take homes. Need to improve std.log performance. It is much slower
than glog. There is probably some unnecessary copy going on. There is
probably a bug in glog since the elapsed time when disabling logging
is almost the same as that when it is enabled (you know disable is
working and not doing IO because the CPU time is 99%). In the future I
need to do a more realistic concurrent test.

-Jose