PostgreSQL 9.5 query performance depends on JOINed column in SELECT clause

Question

Data:

Over the following two tables:

                                      Table "public.response_logs"
  Column  |           Type           | Collation | Nullable |                  Default
----------+--------------------------+-----------+----------+-------------------------------------------
 id       | integer                  |           | not null | nextval('response_logs_id_seq'::regclass)
 status   | bigint                   |           |          |
 uuid     | text                     |           |          |
 payload  | text                     |           |          |
 accessed | timestamp with time zone |           | not null | now()
Indexes:
    "response_logs_pkey" PRIMARY KEY, btree (id)
    "response_logs_uuid_idx" UNIQUE, btree (uuid)
Foreign-key constraints:
    "response_logs_uuid_fkey" FOREIGN KEY (uuid) REFERENCES request_logs(uuid)

And:

                                        Table "public.request_logs"
    Column     |           Type           | Collation | Nullable |                 Default
---------------+--------------------------+-----------+----------+-----------------------------------------
 id            | integer                  |           | not null | nextval('access_logs_id_seq'::regclass)
 accountid     | bigint                   |           |          |
 userid        | bigint                   |           |          |
 applicationid | bigint                   |           |          |
 requesturi    | text                     |           |          |
 method        | text                     |           |          |
 accessed      | timestamp with time zone |           | not null | now()
 uuid          | text                     |           | not null |
 payload       | text                     |           | not null | ''::text
 apikeyid      | bigint                   |           |          |
 header        | jsonb                    |           | not null | '[]'::jsonb
Indexes:
    "request_logs_pkey" PRIMARY KEY, btree (uuid)
    "request_logs_application_idx" btree (applicationid)
Referenced by:
    TABLE "response_logs" CONSTRAINT "response_logs_uuid_fkey" FOREIGN KEY (uuid) REFERENCES request_logs(uuid)

I'm performing the following query:

SELECT
  req.uuid,
  res.status,
  req.method,
  req.requesturi,
  req.accessed,
  req.payload reqpayload,
  res.payload respayload,         /* #1 - response payload */
  COUNT(*) OVER() AS total_rows   /* #2 - total count of response on each row in response */
FROM
  request_logs req
  INNER JOIN response_logs res ON req.uuid = res.uuid AND res.status IS NOT NULL
WHERE
   req.applicationid = 1 AND
   req.accessed BETWEEN '2018-01-01 15:04:05 +0000' AND '2019-01-02 15:04:05+0000' AND
   req.requesturi NOT ILIKE '/v1/sessions%'
ORDER BY
   accessed DESC LIMIT 1000;

Which takes 270 ms on average.

---

The issue:

I can make the query much faster by omitting #2 (COUNT(*) OVER() AS total_rows) for rather obvious reasons. It would go to about 40 ms.

However, and this I find very confusing, the query goes to about 34 ms if I omit respayload from the response.

---

Questions!

1. Shouldn't the bottle neck in any way be COUNT(*) OVER() AS total_rows? How can the query go to 40 ms with this still being calculated?

2. Why does omitting the respayload give such an improvement? Removing reqpayload doesn't have a similar effect and it's even if we don't add respayload, we still need to grab the response_log with corresponding UUID to copy the status into the response.

3. Considering that the only changing query values are the applicationid and the date we compared accessed with, which further improvements including indexing can be done to help performance?

---

Further data!

Here is explain analyse for the different query configurations:

With respayload and COUNT(*) OVER() AS total_rows:

Limit  (cost=2826.59..2829.09 rows=1000 width=823) (actual time=408.535..419.136 rows=1000 loops=1)
      ->  Sort  (cost=2826.59..2829.79 rows=1281 width=823) (actual time=408.524..412.154 rows=1000 loops=1)
            Sort Key: req.accessed DESC
            Sort Method: top-N heapsort  Memory: 2064kB
            ->  WindowAgg  (cost=1090.16..2760.47 rows=1281 width=823) (actual time=368.207..390.866 rows=3951 loops=1)
                  ->  Hash Join  (cost=1090.16..2744.46 rows=1281 width=823) (actual time=50.244..127.325 rows=3951 loops=1)
                        Hash Cond: (res.uuid = req.uuid)
                        ->  Seq Scan on response_logs res  (cost=0.00..1607.26 rows=9126 width=758) (actual time=0.008..36.196 rows=9129 loops=1)
                              Filter: (status IS NOT NULL)
                        ->  Hash  (cost=1044.85..1044.85 rows=3625 width=102) (actual time=38.739..38.739 rows=4046 loops=1)
                              Buckets: 4096  Batches: 1  Memory Usage: 1122kB
                              ->  Index Scan using request_logs_application_idx on request_logs req  (cost=0.29..1044.85 rows=3625 width=102) (actual time=0.035..22.009 rows=4046 loops=1)
                                    Index Cond: (applicationid = 1)
                                    Filter: ((accessed >= '2018-01-01 15:04:05+00'::timestamp with time zone) AND (accessed <= '2019-01-02 15:04:05+00'::timestamp with time zone) AND (requesturi !~~* '/v1/sessions%'::text))
    Planning time: 2.699 ms
    Execution time: 423.068 ms

With respayload and without COUNT(*) OVER() AS total_rows:

Limit  (cost=2810.58..2813.08 rows=1000 width=823) (actual time=136.977..146.820 rows=1000 loops=1)
  ->  Sort  (cost=2810.58..2813.78 rows=1281 width=823) (actual time=136.967..140.334 rows=1000 loops=1)
        Sort Key: req.accessed DESC
        Sort Method: top-N heapsort  Memory: 2064kB
        ->  Hash Join  (cost=1090.16..2744.46 rows=1281 width=823) (actual time=47.127..119.808 rows=3951 loops=1)
              Hash Cond: (res.uuid = req.uuid)
              ->  Seq Scan on response_logs res  (cost=0.00..1607.26 rows=9126 width=758) (actual time=0.015..33.307 rows=9129 loops=1)
                    Filter: (status IS NOT NULL)
              ->  Hash  (cost=1044.85..1044.85 rows=3625 width=102) (actual time=38.328..38.328 rows=4046 loops=1)
                    Buckets: 4096  Batches: 1  Memory Usage: 1122kB
                    ->  Index Scan using request_logs_application_idx on request_logs req  (cost=0.29..1044.85 rows=3625 width=102) (actual time=0.047..21.813 rows=4046 loops=1)
                          Index Cond: (applicationid = 1)
                          Filter: ((accessed >= '2018-01-01 15:04:05+00'::timestamp with time zone) AND (accessed <= '2019-01-02 15:04:05+00'::timestamp with time zone) AND (requesturi !~~* '/v1/sessions%'::text))
Planning time: 3.882 ms
Execution time: 150.465 ms

Without respayload and with COUNT(*) OVER() AS total_rows:

Limit  (cost=2826.59..2829.09 rows=1000 width=110) (actual time=164.428..174.760 rows=1000 loops=1)
  ->  Sort  (cost=2826.59..2829.79 rows=1281 width=110) (actual time=164.418..167.956 rows=1000 loops=1)
        Sort Key: req.accessed DESC
        Sort Method: top-N heapsort  Memory: 564kB
        ->  WindowAgg  (cost=1090.16..2760.47 rows=1281 width=110) (actual time=133.997..148.382 rows=3951 loops=1)
              ->  Hash Join  (cost=1090.16..2744.46 rows=1281 width=110) (actual time=46.282..119.070 rows=3951 loops=1)
                    Hash Cond: (res.uuid = req.uuid)
                    ->  Seq Scan on response_logs res  (cost=0.00..1607.26 rows=9126 width=45) (actual time=0.009..33.656 rows=9129 loops=1)
                          Filter: (status IS NOT NULL)
                    ->  Hash  (cost=1044.85..1044.85 rows=3625 width=102) (actual time=37.844..37.844 rows=4046 loops=1)
                          Buckets: 4096  Batches: 1  Memory Usage: 1122kB
                          ->  Index Scan using request_logs_application_idx on request_logs req  (cost=0.29..1044.85 rows=3625 width=102) (actual time=0.029..21.602 rows=4046 loops=1)
                                Index Cond: (applicationid = 1)
                                Filter: ((accessed >= '2018-01-01 15:04:05+00'::timestamp with time zone) AND (accessed <= '2019-01-02 15:04:05+00'::timestamp with time zone) AND (requesturi !~~* '/v1/sessions%'::text))
Planning time: 3.758 ms
Execution time: 178.675 ms

Answer 1

After trying various configuration, I think I found the answer to my own question. It's not 100% proven but it makes sense.

The COUNT(*) OVER() as total_rows command executes the entire query, including the WHERE clause AND the SELECT fields. So when the result set is very big, much larger than the LIMIT 1000, we would still be copying all the matching records according to the columns indicated in SELECT, including the respayload.

Since respayload can be fairly big, when the unlimited response count is high, let's say 10K, then 10K respayloads are copied, only to later be discarded, as the copy of the selected columns happens again for only the first 1000 (because of limit) records.

That's why omitting respayload from the statement improved performance so drastically.

I will be careful in the future where I use COUNT(*) OVER() as this seems to be seriously affected by the selected columns.