The story of an SQL investigation.

Last December, I received an interesting bug report from the VWO support team. The loading time for one of the analytical reports for a major corporate client seemed excessively long. Since this is in my area of responsibility, I immediately focused on solving the problem.

Background

To provide some context, let me briefly explain what VWO is. It is a platform that allows you to run various targeted campaigns on your websites: conduct A/B experiments, track visitors and conversions, analyze sales funnels, display heatmaps, and replay visit recordings.

But the most important feature of the platform is reporting. All the aforementioned functions are interconnected. For corporate clients, a vast array of information would be utterly useless without a powerful platform to represent it in an analytical format.

Using the platform, you can make arbitrary queries on a large dataset. Here’s a simple example:

Show all clicks on the page "abc.com"
FROM  TO 
for people who
used Chrome OR
(were in Europe AND used iPhone)

Notice the boolean operators. They are available for clients in the query interface to create arbitrarily complex queries for obtaining datasets.

Slow query

The client in question was trying to do something that intuitively should work quickly:

Show all session recordings
for users who visited any page
with a URL containing "/jobs"

This site had an enormous amount of traffic, and we stored over a million unique URLs just for it. They wanted to find a fairly simple URL pattern related to their business model.

Preliminary Inquiry

Let's take a look at what is happening in the database. Below is the original slow SQL query:

SELECT 
    count(*) 
FROM 
    acc_{account_id}.urls as recordings_urls, 
    acc_{account_id}.recording_data as recording_data, 
    acc_{account_id}.sessions as sessions 
WHERE 
    recording_data.usp_id = sessions.usp_id 
    AND sessions.referrer_id = recordings_urls.id 
    AND  (  urls &&  array(select id from acc_{account_id}.urls where url  ILIKE  '%enterprise_customer.com/jobs%')::text[]   ) 
    AND r_time > to_timestamp(1542585600) 
    AND r_time = 5 
    AND recording_data.num_of_pages > 0 ;

Here are the timings:

Planned time: 1.480 ms
Execution time: 1431924.650 ms

The query scanned 150 thousand rows. The query planner revealed a few interesting details but no obvious bottlenecks.

Let's study the query further. As you can see, it makes JOIN three tables:

1. sessions: to display session information: browser, user agent, country, and so on.
2. recording_data: recorded URLs, pages, duration of visits
3. urls: to avoid duplication of extremely large URLs, we store them in a separate table.

Also, note that all our tables are already partitioned by account_id. Thus, the situation where one particularly large account causes issues for others is excluded.

In search of clues

Upon closer inspection, we see that something is wrong with this specific query. We should pay attention to this line:

urls && array(
	select id from acc_{account_id}.urls 
	where url ILIKE '%enterprise_customer.com/jobs%'
)::text[]

The first thought was that perhaps, due to ILIKE on all these long URLs (we have more than 1.4 million unique URLs collected for this account) the performance might suffer.

But no — that's not the issue!

SELECT id FROM urls WHERE url ILIKE '%enterprise_customer.com/jobs%';
  id
--------
 ...
(198661 rows)

Time: 5231.765 ms

The search query by pattern only takes 5 seconds. Searching by pattern across a million unique URLs is clearly not the problem.

The next suspect on the list — several JOIN. Perhaps their excessive use led to the slowdown? Typically JOIN‘s are the most obvious candidates for performance issues, but I didn't believe our case was typical.

analytics_db=# SELECT
    count(*)
FROM
    acc_{account_id}.urls as recordings_urls,
    acc_{account_id}.recording_data_0 as recording_data,
    acc_{account_id}.sessions_0 as sessions
WHERE
    recording_data.usp_id = sessions.usp_id
    AND sessions.referrer_id = recordings_urls.id
    AND r_time > to_timestamp(1542585600)
    AND r_time = 5
    AND recording_data.num_of_pages > 0 ;
 count
-------
  8086
(1 row)

Time: 147.851 ms

And this was not our case either. JOIN‘s turned out to be quite fast.

Narrowing down the suspects

I was ready to start modifying the query in search of any possible performance improvements. My team and I developed two main ideas:

• Use EXISTS for the URL subquery: We wanted to double-check if there were issues with the URL subquery. One way to achieve this is simply to use EXISTS. EXISTS take the parameter significantly improve performance as it ends immediately upon finding a single row that meets the condition.

SELECT
	count(*) 
FROM 
    acc_{account_id}.urls as recordings_urls,
    acc_{account_id}.recording_data as recording_data,
    acc_{account_id}.sessions as sessions
WHERE
    recording_data.usp_id = sessions.usp_id
    AND  (  1 = 1  )
    AND sessions.referrer_id = recordings_urls.id
    AND  (exists(select id from acc_{account_id}.urls where url  ILIKE '%enterprise_customer.com/jobs%'))
    AND r_time > to_timestamp(1547585600)
    AND r_time =5
    AND recording_data.num_of_pages > 0 ;
 count
 32519
(1 row)
Time: 1636.637 ms

Well, yes. A subquery, when wrapped in EXISTS, makes everything super fast. The next logical question is why the query with JOIN-es and the subquery are fast individually but slow together?

• We move the subquery into a CTE : if the query is fast on its own, we can simply first calculate the quick result and then provide it to the main query.

WITH matching_urls AS (
    select id::text from acc_{account_id}.urls where url  ILIKE  '%enterprise_customer.com/jobs%'
)

SELECT 
    count(*) FROM acc_{account_id}.urls as recordings_urls, 
    acc_{account_id}.recording_data as recording_data, 
    acc_{account_id}.sessions as sessions,
    matching_urls
WHERE 
    recording_data.usp_id = sessions.usp_id 
    AND  (  1 = 1  )  
    AND sessions.referrer_id = recordings_urls.id
    AND (urls && array(SELECT id from matching_urls)::text[])
    AND r_time > to_timestamp(1542585600) 
    AND r_time =5 
    AND recording_data.num_of_pages > 0;

But even this was still very slow.

Identifying the culprit

All this time, one small detail kept flashing before my eyes, which I constantly dismissed. But since nothing else was left, I decided to take a look at it as well. I'm talking about && the operator. While EXISTS just improved performance, && was the only remaining common factor in all versions of the slow query.

Looking at documentation, we see that && is used when it is necessary to find common elements between two arrays.

In the original query, this is:

AND  (  urls &&  array(select id from acc_{account_id}.urls where url  ILIKE  '%enterprise_customer.com/jobs%')::text[]   )

Which means we are performing a pattern search on our URLs, then finding the intersection with all URLs with common records. This is a bit confusing because 'urls' here does not refer to a table containing all the URLs, but to the 'urls' column in the table recording_data.

As my suspicions regarding &&grew, I tried to find confirmation for them in the generated query plan. EXPLAIN ANALYZE (I already had a saved plan, but I usually find it easier to experiment in SQL than to understand the opaqueness of query planners).

Filter: ((urls &&& ($0)::text[]) AND (r_time > '2018-12-17 12:17:23+00'::timestamp with time zone) AND (r_time = '5'::double precision) AND (num_of_pages > 0))
                           Rows Removed by Filter: 52710

There were several filter rows just from &&. Which meant that this operation was not only costly but also executed multiple times.

I checked this by isolating the condition

SELECT 1
FROM 
    acc_{account_id}.urls as recordings_urls, 
    acc_{account_id}.recording_data_30 as recording_data_30, 
    acc_{account_id}.sessions_30 as sessions_30 
WHERE 
	urls && array(select id from acc_{account_id}.urls where url ILIKE '%enterprise_customer.com/jobs%')::text[]

This query was slow. Since JOIN-s are fast and subqueries are fast, only the && operator remained.

But this is the key operation. We always need to search across the main URL table to look up by pattern, and we always need to find intersections. We can't search the URL records directly because they are simply IDs referring to urls.

On the way to the solution

&& is slow because both sets are huge. The operation will be relatively fast if I replace urls to { "http://google.com/", "http://wingify.com/" }.

I started looking for a way to do set intersection in Postgres without using &&, but without much success.

Ultimately, we decided to just solve the problem in isolation: give me all urls the rows for which the URL matches the pattern. Without additional conditions it will be — 

SELECT urls.url
FROM 
	acc_{account_id}.urls as urls,
	(SELECT unnest(recording_data.urls) AS id) AS unrolled_urls
WHERE
	urls.id = unrolled_urls.id AND
	urls.url ILIKE '%jobs%'

Instead of JOIN syntax I simply used a subquery and expanded recording_data.urls the array to directly apply the condition in WHERE.

The important thing here is that && is used to check if the given record contains the corresponding URL. Squinting a bit, you can see in this operation the traversal of array elements (or table rows) and stopping upon meeting the condition (match). Does that ring a bell? Aha, EXISTS.

Since at recording_data.urls can be referenced from outside the subquery context when that happens, we can go back to our old friend EXISTS and wrap it with a subquery.

Putting everything together, we get the final optimized query:

SELECT 
    count(*) 
FROM 
    acc_{account_id}.urls as recordings_urls, 
    acc_{account_id}.recording_data as recording_data, 
    acc_{account_id}.sessions as sessions 
WHERE 
    recording_data.usp_id = sessions.usp_id 
    AND  (  1 = 1  )  
    AND sessions.referrer_id = recordings_urls.id 
    AND r_time > to_timestamp(1542585600) 
    AND r_time = 5 
    AND recording_data.num_of_pages > 0
    AND EXISTS(
        SELECT urls.url
        FROM 
            acc_{account_id}.urls as urls,
            (SELECT unnest(urls) AS rec_url_id FROM acc_{account_id}.recording_data) 
            AS unrolled_urls
        WHERE
            urls.id = unrolled_urls.rec_url_id AND
            urls.url  ILIKE  '%enterprise_customer.com/jobs%'
    );

And the final execution time Time: 1898.717 ms Time to celebrate?!?

Not so fast! First, we need to check the correctness. I was quite suspicious about EXISTS the optimization, as it alters the logic for an earlier completion. We must ensure that we haven't introduced an obscure error into the query.

A simple check involved performing count(*) both on slow and fast queries for a large variety of datasets. Then, for a small subset of data, I manually checked the accuracy of all results.

All checks yielded consistently positive results. We fixed everything!

Lessons Learned

Several lessons can be drawn from this story:

1. Query plans do not tell the whole story, but they can offer hints
2. Main suspects are not always the actual culprits
3. Slow queries can be broken down to isolate bottlenecks
4. Not all optimizations are inherently reductive
5. Using EXIST, where applicable, can lead to a significant performance boost

Output

We went from a query time of ~24 minutes down to 2 seconds — quite a substantial performance increase! Although this article turned out lengthy, all the experiments we conducted took place in one day and approximately took 1.5 to 2 hours for optimization and testing.

SQL is a wonderful language if you don't fear it, but rather try to understand and use it. With a solid grasp of how SQL queries are executed, how the database generates query plans, how indexes work, and simply the size of the data you're dealing with, you can excel at query optimization. Equally important, however, is to continue testing various approaches and gradually break down the problem to find the bottlenecks.

The best part of achieving such results is the noticeable visible improvement in performance — when a report that previously wouldn’t even load now loads almost instantly.

Special thanks to my colleagues in the team Aditya Mishra, Aditya Gaur and Varun Malhotra for the brainstorming and Dinkar Pandir for identifying a critical error in our final request before we finally parted ways with it!

Source: habr.com