What's actually happening in the “Result” node and “Append” in a Postgres plan?

Question

I have a table (postgres 9.6) which is partitioned by date into about 70 child tables.

The EXPLAIN output below is truncated as most of it is identical bitmap index/heap scans of each of the child tables (full, verbose output here). The parts I'm interested in are the Append and Result nodes near the top of the tree.

1. From what I've been able to glean (e.g. here and elsewhere), Append is simply the sum of all the subqueries. In fact it takes about 3.5s longer than this. Where's the extra coming from?
2. I can only find the one reference to Result which states This operation is used when your query selects some constant value. This node is taking about 7 seconds yet the query selects no constant values.

I would love to save these 10 seconds if possible, but I don't actually know what these nodes are doing, so I don't know what to try.

EXPLAIN ANALYZE output:

  ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
  │                                                                                      QUERY PLAN                                                                                       │
  ├───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
  │ HashAggregate  (cost=4459946.40..4473566.96 rows=1089645 width=64) (actual time=26289.308..26419.989 rows=190112 loops=1)                                                             │
  │   Group Key: frontend_prescription.processing_date, frontend_prescription.pct_id, substr((frontend_prescription.presentation_code)::text, 1, 9)                                       │
  │   Buffers: shared hit=172527                                                                                                                                                          │
  │   ->  Result  (cost=0.00..4296499.68 rows=10896448 width=60) (actual time=29.021..18762.432 rows=10769038 loops=1)                                                                    │
  │         Buffers: shared hit=172527                                                                                                                                                    │
  │         ->  Append  (cost=0.00..4160294.08 rows=10896448 width=44) (actual time=29.011..11454.952 rows=10769038 loops=1)                                                              │
  │               Buffers: shared hit=172527                                                                                                                                              │
  │               ->  Seq Scan on frontend_prescription  (cost=0.00..0.00 rows=1 width=88) (actual time=0.010..0.010 rows=0 loops=1)                                                      │
  │                     Filter: ((presentation_code)::text ~~ '0212%'::text)                                                                                                              │
  │               ->  Bitmap Heap Scan on frontend_prescription_201110  (cost=607.38..39094.77 rows=127148 width=44) (actual time=28.998..126.694 rows=183185 loops=1)                    │
  │                     Filter: ((presentation_code)::text ~~ '0212%'::text)                                                                                                              │
  │                     Heap Blocks: exact=2083                                                                                                                                           │
  │                     Buffers: shared hit=2788                                                                                                                                          │
  │                     ->  Bitmap Index Scan on idx_frontend_prescription_201110_presentation  (cost=0.00..575.59 rows=37356 width=0) (actual time=28.576..28.576 rows=183185 loops=1)   │
  │                           Index Cond: (((presentation_code)::text ~>=~ '0212'::text) AND ((presentation_code)::text ~<~ '0213'::text))                                                │
  │                           Buffers: shared hit=705
  <snip>    

The query:

EXPLAIN (ANALYZE,BUFFERS) SELECT
  processing_date,
  pct_id,
  SUBSTR(presentation_code, 1, 9) AS chemical_id,
  SUM(total_items) AS items,
  SUM(actual_cost) AS cost,
  SUM(quantity) AS quantity
FROM
  frontend_prescription
WHERE presentation_code LIKE '0212%'
GROUP BY
  processing_date,
  pct_id,
  chemical_id

Answer 1

The Append has to do some buffer management. It also makes a lot of calls to some clock function (gettimeofday, for example), to satisfy the timing component of EXPLAIN ANALYZE. That overhead might be the dominant time sink.

In your case, the Result node is computing the result of the SUBSTR function. You can see this is in the Output field of the verbose plan. It is also making a lot of calls to some clock function.

If you run explain (analyze, timing off), the execution time of that should tell you how much of the time in your EXPLAIN ANALYZE is going just towards instrumentation overhead.