(Some lessons in) optimizing Org::Parser

Here's what I have been using in my ~/.bashrc for the past few months:


echo "UPCOMING TODOS:"
list-org-todos --due-in 7 --group-by-tags ~/o/todo.org
echo "UPCOMING ANNIVERSARIES:"
list-org-anniversaries --has-tags '[remind_anniv]' --due-in 14 --max-overdue 7 ~/o/addressbook.org

list-org-todos and list-org-anniversaries come with App-OrgUtils, which in turn uses Org::Parser.

todo.org contains all my todo items for most projects (a few projects are large enough to warrant their own todo files). addressbook.org contains all my contacts and important addresses/numbers (some older contacts are still in .vcf files produced by kaddressbook). These two files have been steadily growing, but they are not large by any standard. In April, they weigh in at about 50K each. However, my slow Atom Eee laptop at home required around 10s to execute each command, for a total of 20s. This started to annoy me, even after I set so that both commands are only run once a day.

%+ is slow! So I profiled the scripts. Turned out, one line $log->tracef("...%s...", \%+) was so heavy, the script spent almost half of its time on this line! The line was executed thousands of times, true, but I had assumed it would not take too big a hit since log level is normally not at TRACE. %+ is a tied hash, handled by Tie::Hash::NamedCapture, so accessing it is slower than accessing a regular hash. Org::Parser was using %+ *a lot* that the speed difference became significant. So I wrapped that logging line with if ($log->is_trace) { ... }, and I managed to cut script execution time by half. But, a total of 10s is still too much. After I knew that %+ is slow (each $+{foo} access requires 8 microns on my laptop, compared to submicron time needed to access a normal hash pair value), I replaced a bunch of conditional against various $+{key} with copying %+ to some hash first %m, then using the %m in the conditionals. This cut down script execution time again around 20%.

Don't do unnecessary stuffs. The next day, I realized that I had been doing unnecessary work in pass 1. Org::Parser parses Org documents in two passes, the first pass is for collecting settings like custom todo keywords (#+TODO) and for scanning the radio targets. The second pass is for actually building the element tree. Turned out since the two passes share the same code, I also built the element tree in pass 1, only to destroy the elements and build the tree again in pass 2. So after eliminating that unnecessary work, I managed to cut down again the execution time. My laptop now "only" spent 6-7s to execute both commands.

Cache. That was in April. In July, my todo.org and addressbook.org have grown to 90k and 80k, respectively and again my home laptop suffers. This time, I thought I'll just cache the parse result to file using Storable. This is a bit tricky at first since the Timestamp element object can have the date recurrence object, which contains coderefs. The workaround is to remove the parse result before serializing, and automatically parse again whenever an attribute is accessed (easily done using Moo/Moose's before method modifier). A 90k Org file translates to about 500k of Storable file, but the latter loads in just a fraction of a second.

Reduce startup time. The last optimization done for now is reducing the startup time. list-org-todos and list-org-anniversaries each requires around 1-2s just to start on the laptop, due to almost 100k of lines of code needs to be parsed (some heavy modules are involved: Log::Log4perl, DateTime, Date::Manip). The scripts basically just call the corresponding Perl functions list_org_todos() and list_org_anniversaries(). Startup overhead can be cut to half by just using one script instead of two. So the bash commands are converted to:


perl -E'
  use App::ListOrgTodos qw(list_org_todos);
  use App::ListOrgAnniversaries qw(list_org_anniversaries);
  use Data::Format::Pretty::Console qw(format_pretty);
  my $res;

say "UPCOMING TODOS:";
$res = list_org_todos(due_in=>7, group_by_tags=>1, cache_dir=>"$ENV{HOME}/tmp", files=>["$ENV{HOME}/o/todo.org"]);
print format_pretty($res->[2]);
say "UPCOMING ANNIVERSARIES:";
$res = list_org_anniversaries(has_tags=>["remind_anniv"], due_in=>14, max_overdue=>7, cache_dir=>"$ENV{HOME}/tmp", files=>["$ENV{HOME}/o/addressbook.org"]);
print format_pretty($res->[2]);'

Now with a cache hit on both Org files, my laptop only about 2s to display my upcoming todos and anniversaries.

Org::Parser is still far from fast. Future ideas for optimization include delaying parsing the elements until attributes are accessed (just like in the timestamp element) and using a real parser generator. But that would probably not save me as much execution time. So enough for now.

2 Comments

Have you considered switching from DateTime to DateTime::Tiny? DateTime::Tiny doesn't have all the features of DateTime, but it does have a roughly compatible interface, and seems to load significantly faster.

use Benchmark;
timethese(20, {
	'DateTime'       => sub { qx(perl -MDateTime -e1) },
	'DateTime::Tiny' => sub { qx(perl -MDateTime::Tiny -e1) },
});
__END__
Benchmark: timing 20 iterations of DateTime, DateTime::Tiny...
DateTime: 14 wallclock secs ( 0.00 usr  0.00 sys + 13.18 cusr  0.42 csys = 13.60 CPU) @  1.47/s (n=20)
DateTime::Tiny:  0 wallclock secs ( 0.00 usr  0.00 sys +  0.58 cusr  0.09 csys =  0.67 CPU) @ 29.85/s (n=20)
            (warning: too few iterations for a reliable count)

Leave a comment

About Steven Haryanto

user-pic A programmer (mostly Perl 5 nowadays). My CPAN ID: SHARYANTO. I'm sedusedan on perlmonks. My twitter is stevenharyanto (but I don't tweet much). Follow me on github: sharyanto.