Re: EXPLAIN BUFFERS and I/O timing accounting questions

[Maciek Sakrejda <m.sakrejda@xxxxxxxxx>]

On Thu, Oct 24, 2019 at 2:25 PM Andres Freund <andres@xxxxxxxxxxx> 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?

> 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>"
    },
    {
      "Node Type": "ModifyTable",
      "Operation": "Delete",
      "Parent Relationship": "InitPlan",
      "Plan Rows": 63897788,
      "Plan Width": 38,
      "Total Cost": 315448.53,
      "Actual Rows": 0,
      "I/O Read Time": 30529.231,
      "I/O Write Time": 0,
      "Local Hit Blocks": 0,
      "Local Read Blocks": 0,
      "Local Dirtied Blocks": 0,
      "Local Written Blocks": 0,
      "Shared Hit Blocks": 12964205,
      "Shared Read Blocks": 83260,
      "Shared Dirtied Blocks": 48256,
      "Shared Written Blocks": 0,
      "Temp Read Blocks": 4788,
      "Temp Written Blocks": 0,
      "Plans": "<elided>"
    },
    {
      "Node Type": "ModifyTable",
      "Operation": "Delete",
      "Parent Relationship": "InitPlan",
      "Plan Rows": 45657680,
      "Plan Width": 38,
      "Total Cost": 357974.43,
      "Actual Rows": 0,
      "I/O Read Time": 24260.512,
      "I/O Write Time": 0,
      "Local Hit Blocks": 0,
      "Local Read Blocks": 0,
      "Local Dirtied Blocks": 0,
      "Local Written Blocks": 0,
      "Shared Hit Blocks": 10521264,
      "Shared Read Blocks": 64450,
      "Shared Dirtied Blocks": 36822,
      "Shared Written Blocks": 0,
      "Temp Read Blocks": 4788,
      "Temp Written Blocks": 1,
      "Plans": "<elided>"
    },
    {
      "Node Type": "CTE Scan",
      "Parent Relationship": "Outer",
      "Plan Rows": 13943446,
      "Plan Width": 8,
      "Total Cost": 278868.92,
      "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": 4786
    }
  ]
}}]

Let me know if I removed anything I shouldn't have and I can follow up with extra info.

>  I assume what's going on is that the cost of
> the CTE is actually attributed (in equal parts or something like that)
> to all places using the CTE. Do the numbers add up if you just exclude
> the CTE?

Not really--it looks like the full Shared Blocks Hit cost in the root is the same as the CTE by itself. This is playing around with the plan in a node console:

> p[0].Plan['Shared Hit Blocks']
4847762
> p[0].Plan.Plans.map(p => p['Node Type'])
[ 'ModifyTable', 'ModifyTable', 'ModifyTable', 'CTE Scan' ]
> p[0].Plan.Plans.map(p => p['Shared Hit Blocks'])
[ 4847762, 12964205, 10521264, 4847762 ]

> IIRC one can get multiple plans when there's a DO ALSO rule. There might
> be other ways to get there too.

Thanks, good to know.