Re: EXPLAIN BUFFERS and I/O timing accounting questions

Hi,

On 2019-10-24 16:31:39 -0700, Maciek Sakrejda wrote:
> On Thu, Oct 24, 2019 at 2:25 PM Andres Freund <andres@anarazel.de> wrote:
> > Note that the buffer access stats do *not* count the number of distinct
> > buffers accessed, but that they purely the number of buffer
> > accesses.
> 
> You mean, even within a single node? That is, if a node hits a block ten
> times, that counts as ten blocks hit? And if it reads a block and then
> needs it three more times, that's one read plus three hit?

Correct. It's basically the number of lookups in the buffer
pool. There's some nodes that will kind repeatedly use the same buffer,
without increasing the count. E.g. a seqscan will keep the current page
pinned until all the tuples on the page have been returned.

Consider e.g. an nested loop indexscan - how would we determine whether
we've previously looked at a buffer within the indexscan, without
drastically increasing the resources?


> > Do you have an example?
> 
> Sure, here's the "abridged" plan:
> 
> [{ "Plan": {
>   "Node Type": "Aggregate",
>   "Plan Rows": 1,
>   "Plan Width": 8,
>   "Total Cost": 26761745.14,
>   "Actual Rows": 1,
>   "I/O Read Time": 234129.299,
>   "I/O Write Time": 0,
>   "Local Hit Blocks": 0,
>   "Local Read Blocks": 0,
>   "Local Dirtied Blocks": 0,
>   "Local Written Blocks": 0,
>   "Shared Hit Blocks": 4847762,
>   "Shared Read Blocks": 1626312,
>   "Shared Dirtied Blocks": 541014,
>   "Shared Written Blocks": 0,
>   "Temp Read Blocks": 0,
>   "Temp Written Blocks": 4786,
>   "Plans": [
>     {
>       "Node Type": "ModifyTable",
>       "Operation": "Delete",
>       "Parent Relationship": "InitPlan",
>       "Plan Rows": 13943446,
>       "Plan Width": 6,
>       "Total Cost": 25774594.63,
>       "Actual Rows": 2178416,
>       "I/O Read Time": 234129.299,
>       "I/O Write Time": 0,
>       "Local Hit Blocks": 0,
>       "Local Read Blocks": 0,
>       "Local Dirtied Blocks": 0,
>       "Local Written Blocks": 0,
>       "Shared Hit Blocks": 4847762,
>       "Shared Read Blocks": 1626312,
>       "Shared Dirtied Blocks": 541014,
>       "Shared Written Blocks": 0,
>       "Temp Read Blocks": 0,
>       "Temp Written Blocks": 0,
>       "Plans": "<elided>"
>     },
...

I think this may be partially confusing due to the way the json output
looks. Which is so bad that it's imo fair to call it a bug.  Here's text
output to a similar-ish query:


Aggregate  (cost=112.50..112.51 rows=1 width=8) (actual time=35.893..35.894 rows=1 loops=1)
  Output: count(*)
  Buffers: shared hit=6015 dirtied=15
  CTE foo
    ->  Delete on public.p  (cost=0.00..45.00 rows=3000 width=6) (actual time=0.235..28.239 rows=3000 loops=1)
          Output: p.data
          Delete on public.p
          Delete on public.c1
          Delete on public.c2
          Buffers: shared hit=6015 dirtied=15
          ->  Seq Scan on public.p  (cost=0.00..15.00 rows=1000 width=6) (actual time=0.161..1.375 rows=1000 loops=1)
                Output: p.ctid
                Buffers: shared hit=5 dirtied=5
          ->  Seq Scan on public.c1  (cost=0.00..15.00 rows=1000 width=6) (actual time=0.147..1.314 rows=1000 loops=1)
                Output: c1.ctid
                Buffers: shared hit=5 dirtied=5
          ->  Seq Scan on public.c2  (cost=0.00..15.00 rows=1000 width=6) (actual time=0.145..1.170 rows=1000 loops=1)
                Output: c2.ctid
                Buffers: shared hit=5 dirtied=5
  ->  CTE Scan on foo  (cost=0.00..60.00 rows=3000 width=0) (actual time=0.243..34.083 rows=3000 loops=1)
        Output: foo.data
        Buffers: shared hit=6015 dirtied=15
Planning Time: 0.508 ms
Execution Time: 36.512 ms

Note that the node below the Aggregate is actually the CTE, and that
that the DELETEs are below that. But the json, slightly abbreviated,
looks like:

[
  {
    "Plan": {
      "Node Type": "Aggregate",
      "Strategy": "Plain",
      "Shared Hit Blocks": 6015,
      "Shared Read Blocks": 0,
      "Shared Dirtied Blocks": 15,
      "Shared Written Blocks": 0,
      "Plans": [
        {
          "Node Type": "ModifyTable",
          "Operation": "Delete",
          "Parent Relationship": "InitPlan",
          "Subplan Name": "CTE foo",
          "Output": ["p.data"],
          "Target Tables": [
            {
              "Relation Name": "p",
              "Schema": "public",
              "Alias": "p"
            },
            {
              "Relation Name": "c1",
              "Schema": "public",
              "Alias": "c1"
            },
            {
              "Relation Name": "c2",
              "Schema": "public",
              "Alias": "c2"
            }
          ],
          "Shared Hit Blocks": 6015,
          "Shared Read Blocks": 0,
          "Shared Dirtied Blocks": 15,
          "Shared Written Blocks": 0,
          "Plans": [
            {
              "Node Type": "Seq Scan",
              "Parent Relationship": "Member",
              "Output": ["p.ctid"],
              "Shared Hit Blocks": 5,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 5,
            },
            {
              "Node Type": "Seq Scan",
              "Parent Relationship": "Member",
              "Parallel Aware": false,
              "Relation Name": "c1",
              "Schema": "public",
              "Shared Hit Blocks": 5,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 5,
              "Shared Written Blocks": 0,
              "Local Hit Blocks": 0,
            },
            {
              "Node Type": "Seq Scan",
              "Parent Relationship": "Member",
              "Shared Hit Blocks": 5,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 5,
              "Shared Written Blocks": 0,
            }
          ]
        },
        {
          "Node Type": "CTE Scan",
          "Parent Relationship": "Outer",
          "Parallel Aware": false,
          "CTE Name": "foo",
          "Alias": "foo",
          "Startup Cost": 0.00,
          "Total Cost": 60.00,
          "Plan Rows": 3000,
          "Plan Width": 0,
          "Actual Startup Time": 0.258,
          "Actual Total Time": 12.737,
          "Actual Rows": 3000,
          "Actual Loops": 1,
          "Output": ["foo.data"],
          "Shared Hit Blocks": 6015,
          "Shared Read Blocks": 0,
          "Shared Dirtied Blocks": 15,
          "Shared Written Blocks": 0,
        }
      ]

But I still don't quite get how the IO adds up in your case.

Perhaps you could send me the full plan and query privately? And, if you
have access to that, the plain text explain?

Greetings,

Andres Freund