Statistics from SQLite Object Cache

The SQLite Object Cache plugin measures how long its operations take. It gathers those measurements, and you can see a statistical summary report of them on the plugin’s Statistics tab. Statistics-gathering records the individual elapsed times for various operations. Then, the report presents so-called descriptive statistics of the time taken by each operation. When considering, for example, how long wp_cache_get() operations take, it is helpful to know the average time. And it’s helpful to know more, so the report shows the median time taken, the 95th and 99th percentile, and several other measures.

Careful measuring of the performance of basic services is fundamental to improving performance. Plain old averages, if that’s all you have, conceal both problems and solutions. As you may guess, the author’s a bit of a zealot about this. Many basic data services have really nice average performance and a few outrageously long outlier operations. Making the system perform better for its users usually depends on dealing with the outliers.

So, this plugin gathers a lot of samples of the times taken on individual operations. It then shows a descriptive statistical display of the samples. So, we can see the longest operations compared to the median operation. Is it an egregious outlier? It is good to know that. So we present, among other numbers, the median, maximum, 95th percentile, and 99th percentile values from the samples for each operation.

Here’s a sample report.

  n [min p1 p5 median mean p95 p99 max] range mad stdev
RAM hit ratio 336 0.93 0.98 0.99 1 1 1 1 1 0.07 0 0.01
SQLite hit ratio 336 0.08 0.18 0.32 0.79 0.72 0.96 0.98 1 0.92 0.16 0.2
SQLite lookups/request 336 1 5 7 15 68 199 330 1238 1237 69.6 99.67
SQLite saves/request 336 0 0 0 4 8.71 29 64 439 439 8.78 27.63
MySQL queries/request 336 0 0 0 5 7.85 22 60 236 236 6.51 16.18
Initialization times 336 0 3406.11 3624.94 5957.65 6474.49 11084.86 25014.63 84127.94 84127.94 1848.33 5331.26
Lookup times 20715 4.13 5.1 11.06 26.25 214.62 562.18 5630.86 84203.82 84199.69 340.54 1312.8
Save times 2926 10.07 11.23 14.06 145.48 16910.7 105345.88 245090.02 476674.86 476664.79 25488.93 46735.79
Delete times 242 34.67 39.18 48.52 87.61 149.32 233.16 328.67 8373.83 8339.16 99.5 537.39
  n [min p1 p5 median mean p95 p99 max] range mad stdev

The columns of the report

Let’s look at the last row of data to explain the report’s columns.

Delete Times means the row contains a summary of how long it took to delete an entry from the cache. Deleting a transient, for example, causes the plugin to delete its entry.

n 242 means we measured 242 different Delete operations.

min 34.67 means the fastest deletion (the minimum time) took 34.67 microseconds.

p1 39.18 means 1% of the delete operations happened in 39.18 or less microseconds. For p1 read “first percentile.”

p5 48.52 means 5% (the fifth percentile) took this long or less.

median 87.61 means half the operations (median or 50th percentile) took this long or less.

mean 149.32 means the average operation took this long.

p95 233.16 means 95% (the 95th percentile) took this long or less. Only 5% were slower than this.

p99 328.67 means 99% (the 99th percentile) took this long or less. Only 1% were slower than this.

max 8373.83 means the slowest delete operation took a whopping 8.37 milliseconds, roughly two hundred times slower than the fastest delete operation.

range 8839.16 is the max time less the min time.

mad 99.5 is the mean absolute deviation of all the times. It is a measure of the variability of the times.

stdev 537.39 is the standard deviation of all the times. It too is a measure of the variability of the times, but it tends to exaggerate the importance of outlying values. (Standard deviation is most useful for data sets that follow the well-known normal or bell-curve distribution. But the times taken by computing operations often don’t.) From max 8373.83 we know we have one or a very few outlying values.

What do we make of this row of data?

Deleting cache values is usually quite fast. 99% of the operations took less than a third of a millisecond (333 microseconds).

One or a tiny handful of operations are far slower than that. (As of early February 2023, the author doesn’t understand exactly why.)

The rows of the report

Each row of the report shows a different way of measuring the cache.

RAM Hit Ratio and SQLite Hit Ratio measure how often WordPress found an item in the cache. A hit ratio of 0.75, for example, means WordPress found cached items 75% of the time. The other 25% were cache misses, and WordPress had to look those items up in the MySQL or MariaDB database, or recompute them. Keep in mind that WordPress’s cache is a so-called memoization cache: it keeps temporary copies of the results of lookups or computations, to save the cost of regenerating those results.

SQLite Lookups / Request summarizes the number of times WordPress retrieved a cached value from SQLite as it processed each request. WordPress handles some requests while needing only a few cached values. Other requests (typically lists of posts, products, or users) need many cached values.

SQLite Saves / Request summarizes the number of times WordPress put a value into the cache as it processed each request.

MySQL Queries / Request summarizes the number of MySQL or MariaDB database queries WordPress used as it processed each request.

Initialization Times summarizes how long the SQLite Object Cache took (in microseconds) to start up, access the SQLite database, and load a few commonly-used cache entries into RAM at the beginning of WordPress’s handling of each request.

Lookup Times summarizes how long it took to look up cached items in the SQLite database. The sample report summarizes the time taken to look up 20,715 cached items. Notice that each separate WordPress request (page view, AJAX request, or REST request) must look up the cached items it needs, so the number of looked-up items is large.

Save Times summarizes how long it took to save newly cached items into the SQLite database.

Delete Times summarizes, as described earlier in this post, how long it took to delete items from the SQLite cache.