Re: EXPLAIN BUFFERS and I/O timing accounting questions

On Thu, Oct 24, 2019 at 2:25 PM Andres Freund <andres(at)anarazel(dot)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?

> 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.