After the October speed-up, I looked at what the production database was still spending its time on. The top two statements had nothing to do with the bots. They were the ordinary work of showing a port page, and of working out what any other URL refers to. Both are now cheaper. This post says what changed, and what it saved.
As a website/database evolves, new items are added and sometimes existing ways of doing the same thing are ignored, or in my case completely over looked.
How I measure database time
Production runs the pg_stat_statements extension. For each distinct query, it keeps the number of calls, and a running total of the time spent executing it, in total_exec_time. I give database time in seconds per hour (s/hour): total_exec_time divided by the hours since pg_stat_statements_reset() was last run.
- It is query execution time only. Planning time is not counted, because pg_stat_statements.track_planning is off. Neither is time spent in PHP, nginx, or on the network.
- It is summed across all connections. Ten queries running for one second at the same time count as ten seconds.
- pg_stat_statements only keeps so many distinct queries. When it fills up, it evicts the least-used, and their time goes with them. pg_stat_statements_info.dealloc says how often that has happened.
Every figure for a single statement below comes from this query, run at the end of each window:
SELECT calls,
round(mean_exec_time::numeric, 2) AS mean_ms,
round((total_exec_time / 1000 / extract(epoch FROM now() - i.stats_reset) * 3600)::numeric, 2) AS s_per_h,
left(regexp_replace(query, '\s+', ' ', 'g'), 110) AS query
FROM pg_stat_statements, pg_stat_statements_info i
ORDER BY total_exec_time DESC
LIMIT 15;
The before window ran from the reset at 19:09 UTC on 20 October to 28 October, 7 days and 17 hours (185 hours). The after window started with a reset at 23:06 UTC on 29 October, once both changes were on production, and ran for 21.5 hours. Calls per hour are the calls divided by the hours in the window.
Port pages
A port page, such as /www/nginx/, is built in parts, and each part is cached. Before showing the page, url-parser.php needs to know whether the port exists on the branch asked for. It found out by calling Port::FetchByCategoryPortBranch(), which fetches everything about the port. That query also calls pkg_plist(), PortVersionOnQuarterlyBranch(), and element_pathname() twice. Their results are only used to build the cached parts. When every part came from the cache, all of that work was thrown away.
It was the most expensive statement on production: 1,264,264 calls at 3.75 ms, 25.5 s/hour.
Now url-parser.php calls a new Port::ExistsOnBranch(). It uses the same joins, so it finds the same ports, but returns only the port's id:
SELECT ports.id
FROM ports
JOIN element ON element.id = ports.element_id
AND element.name = $1
JOIN categories ON categories.id = ports.category_id
AND categories.name = $2
JOIN element_pathname ON element_pathname.element_id = ports.element_id
AND element_pathname.pathname = $3
The full fetch moved to _GetThatPort() in rewrite/missing-port.php, which runs when a part is not in the cache. It runs at most once per page, however many parts are missing. A page built from the cache now never runs it.
Other URLs
A URL that is not a category or a port, such as /ports/head/www/nginx/Makefile, is looked up with the database function elementGet(). It called Pathname_ID() three times: once to find the element, once for IsCategory(), and once for IsPort(). Pathname_ID() walks the path one directory at a time, in PL/pgSQL. Then element_pathname() built the pathname again, the same way.
It was the second most expensive statement: 347,674 calls at 10.73 ms, 20.1 s/hour.
The element_pathname table already holds the pathname of every element, kept current by triggers on element, with a unique index on pathname. elementGet() now does one lookup there:
CREATE OR REPLACE FUNCTION elementGet (text) RETURNS SETOF element_type AS $$
SELECT E.id,
E.name::text,
E.directory_file_flag::text,
E.status::text,
IsCategory(E.id) IS NOT NULL,
IsPort( E.id) IS NOT NULL,
EP.pathname
FROM element_pathname EP
JOIN element E ON E.id = EP.element_id
WHERE EP.pathname = regexp_replace(CASE WHEN left($1, 1) = '/' THEN $1 ELSE '/' || $1 END, '(.)/$', '\1');
$$ LANGUAGE SQL STABLE;
Like Pathname_ID(), it accepts a path without the leading slash, or with one trailing slash. Before the change went anywhere, I ran the old and new versions side by side on my development database, over 4,916 paths: a sample of real pathnames, variations of them with and without slashes, in upper case, and paths that don't exist. They returned the same rows. On that database, /ports/head/www/nginx/Makefile went from 18.6 ms to 0.5 ms.
Results
| Statement | Calls an hour, before | Mean, before | s/hour, before | Calls an hour, after | Mean, after | s/hour, after |
|---|---|---|---|---|---|---|
| elementGet() | 1,879 | 10.73 ms | 20.1 | 1,012 | 0.28 ms | 0.28 |
| Full port fetch | 6,834 | 3.75 ms | 25.5 | 3,866 | 3.75 ms | 14.49 |
| Port exists check (new) | 8,103 | 0.10 ms | 0.82 |
elementGet() is 38 times faster. It was also called less often in the after window, so the fairest comparison uses the same number of calls. At 1,012 calls an hour, the old function would have cost 10.9 s/hour (1,012 × 10.73 ms). The new one costs 0.28.
The port pages saved less than I expected. I expected the full fetch to run only now and then, when the cache had nothing. In fact, it ran 83,239 times in the window, against 174,456 existence checks. The existence check runs once per port page, or twice if the port is not on the branch asked for and it tries head instead. So the full fetch still runs for about half of all port pages, or more. I haven't looked into why the cache misses that often.
Still, it is a saving. At today's traffic, running the full fetch for every port page would cost 30.4 s/hour (8,103 × 3.75 ms). Instead, the existence checks and the fetches cost 15.3 s/hour together (0.82 + 14.49).
Together, the two changes save about 26 s/hour at today's traffic: 15 from the port pages, and 10.6 from elementGet().
The total
The total for the after window comes from this query:
SELECT round((sum(total_exec_time) / 1000 / extract(epoch FROM now() - max(i.stats_reset)) * 3600)::numeric, 1) AS s_per_h FROM pg_stat_statements, pg_stat_statements_info i;
It came to 86.1 s/hour. In the October speed-up post, the figure after the release was 188 s/hour, of which the nightly pg_dump took 53.
Those two can't be compared directly. dealloc was 14 at the end of this window, so statements had been evicted. The dump copies each table with its own COPY statement, run once a night, and those are the first to go. This shows what was left of them:
SELECT count(*), round(sum(total_exec_time)::numeric / 1000) AS seconds FROM pg_stat_statements WHERE query LIKE 'COPY%';
13 COPY statements remained, with 15 seconds between them. In the October window, the dump took 893 seconds. So the dump ran in this window, but nearly all of its time was evicted, and 86.1 s/hour is effectively the figure without it.
The comparable earlier figure is about 134 s/hour without the dump. That is a drop of about 48 s/hour. The two changes in this post account for about 26 of it. Some of the rest is the Commits::FetchLimit() fix for branch pages, which went to production on 22 October, after that window, and cost 13 to 17 s/hour before it. The remainder is traffic, which varies from day to day.
The full port fetch is still the most expensive statement on production. That is where I am stopping, for now.
