Getting the Timing Right - Sun, 26 Jul 2015

One of my concerns about switching from in-memory data structures to an on-disk database has been with regards to speed. Memory is faster than disk. Writing to disk will slow things down.

But it better not slow things down too much. For normal-sized genealogy files (say up to 10,000 people), everything should be fast and smooth. Larger files of 100,000 or more people should degrade gracefully. But they should not take forever.

As I have learned through my implementation of Behold’s database during the past few weeks, writing databases to disk one record at a time is sloooooow.

In the past to get timings, I used to use AQtime, a third-party profiler that would count and time each line of your executable without adding much overhead at all. It worked like magic to me. But moving to Delphi XE8, I would need to upgrade to their new version. The cost plus a horrendous interface with the Delphi development environment just wasn’t worth it to me.

Instead I found a wonderful simple new function in Delphi called StopWatch that gives accurate timings. You can create as many as you want and you just add them around your code, e.g.:

Stopwatch1.Start;
Stopwatch2.Start;
code
Stopwatch2.Stop;
more code
Stopwatch2.Start;
even more code
Stopwatch2.Stop;
and more code
Stopwatch1.Stop;

Testing inside a routine that is called 10,000 times, I get a timing of 229 milliseconds (ms), and rerunning the routine doesn’t vary from that by more than about 5 ms, so it is very accurate and more than accurate enough to compare the speed of different implementations for optimization purposes.

So I used Stopwatches to see how quick I could get SQLite to be and determine how to best implement it. I used two files. In the first, I loaded 33,790 INDI (people) records from a GEDCOM file. In the second I loaded 198,522 INDI records.

What I was comparing to I knew was an unattainable goal. It was the B* tree I created and super-optimized to index and store the INDI records in memory in Behold. A B* tree is a balanced version of a B-tree (which is really a generalized binary tree but with n-nodes rather than just 2). For the two files, my B* tree took 53 ms and 459 ms.

Next I did a straight insert of the same information to a disk-based SQLite database. It took 1530 ms and 10985 ms. Well that’s quite a bit longer, and 10 seconds is a bit too long for someone to wait when it only took a half a second before.

The default way a database writes information is one record at a time. What was needed was to batch the transactions using a technique called Array DML. Once I did that, I was able to get times down to 176 ms and 1012 ms.

That was better, still not as good as my beautiful b*-tree, but acceptable when disk writes are involved.

Still something bothered me. The amount of time needed to load the DML array was half of the total time. This was a simple assignment of all the data, one by one, into the array. There was no database work going on. In the two tests, it was loading a 20 MB array and a 100 MB array and it was all in memory. That should be much faster than it is, and shouldn’t take as long as writing the data to disk.

I wasn’t sure what was going on. It was using a Delphi object known as a TCollection. Technically it was a collection of a collection of variants. So it was two dimensional, one for each INDI and one for the 16 fields for each INDI.

I played around a bit but was not able to find a way to load that TCollection any faster. I even posted a question on StackOverflow (check it out if you want to get into some technical details with more timings).

By the way. All the above timings were compiled to 64-bit. Remember when I blogged a few days ago that 64-bit was slower than 32-bit? Well that’s not true for the database.  My B* tree is 25% slower in 64-bit, but the database writes are 15% faster despite using 35% more memory.

I’m going to do a bit more research into this, but I’m not going to let it side-track me. Tomorrow I’ll start the work to get Behold writing to and using the database.