vsg
commented
8 years ago 
Closed vsg closed 8 years ago
vsg
commented
8 years ago
AlexTatiyants
commented
8 years ago can you please submit the plan which caused this bug? thanks
vsg
commented
8 years ago Can't do that, sorry.
felixbuenemann
commented
8 years ago I have the same problem, in the following example the sort node at the very top shows up as taking -86% time:
Execution Plan:
[
{
"Plan": {
"Node Type": "Sort",
"Startup Cost": 1460.74,
"Total Cost": 1470.87,
"Plan Rows": 4050,
"Plan Width": 183,
"Actual Startup Time": 13.766,
"Actual Total Time": 13.793,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv.variant_id", "sv.sku", "sp.slug", "sp.name", "vc.color", "pr.min_price", "pcc.available_colors", "sv.product_id"],
"Sort Key": ["sv.product_id"],
"Sort Method": "quicksort",
"Sort Space Used": 101,
"Sort Space Type": "Memory",
"Shared Hit Blocks": 2695,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "InitPlan",
"Subplan Name": "CTE catalog_variants",
"Relation Name": "spree_variants",
"Schema": "public",
"Alias": "spree_variants",
"Startup Cost": 0.00,
"Total Cost": 80.47,
"Plan Rows": 352,
"Plan Width": 19,
"Actual Startup Time": 0.022,
"Actual Total Time": 0.740,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["spree_variants.id", "spree_variants.product_id", "spree_variants.sku"],
"Filter": "((spree_variants.deleted_at IS NULL) AND spree_variants.show_in_catalog)",
"Rows Removed by Filter": 3595,
"Shared Hit Blocks": 41,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Aggregate",
"Strategy": "Sorted",
"Parent Relationship": "InitPlan",
"Subplan Name": "CTE product_color_classifications",
"Startup Cost": 288.86,
"Total Cost": 292.38,
"Plan Rows": 176,
"Plan Width": 12,
"Actual Startup Time": 2.799,
"Actual Total Time": 3.980,
"Actual Rows": 311,
"Actual Loops": 1,
"Output": ["sv_1.product_id", "array_agg(DISTINCT sov.presentation)"],
"Group Key": ["sv_1.product_id"],
"Shared Hit Blocks": 1295,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Sort",
"Parent Relationship": "Outer",
"Startup Cost": 288.86,
"Total Cost": 289.30,
"Plan Rows": 176,
"Plan Width": 12,
"Actual Startup Time": 2.676,
"Actual Total Time": 2.705,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv_1.product_id", "sov.presentation"],
"Sort Key": ["sv_1.product_id"],
"Sort Method": "quicksort",
"Sort Space Used": 41,
"Sort Space Type": "Memory",
"Shared Hit Blocks": 1287,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 20.28,
"Total Cost": 282.30,
"Plan Rows": 176,
"Plan Width": 12,
"Actual Startup Time": 0.312,
"Actual Total Time": 2.450,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv_1.product_id", "sov.presentation"],
"Hash Cond": "(sov_sv.option_value_id = sov.id)",
"Shared Hit Blocks": 1287,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Nested Loop",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 12.71,
"Total Cost": 270.98,
"Plan Rows": 528,
"Plan Width": 8,
"Actual Startup Time": 0.229,
"Actual Total Time": 2.086,
"Actual Rows": 1056,
"Actual Loops": 1,
"Output": ["sv_1.product_id", "sov_sv.option_value_id"],
"Shared Hit Blocks": 1284,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 12.42,
"Total Cost": 24.30,
"Plan Rows": 176,
"Plan Width": 12,
"Actual Startup Time": 0.221,
"Actual Total Time": 0.468,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv_1.product_id", "sv_1.variant_id", "catalog_variants.variant_id"],
"Hash Cond": "(sv_1.variant_id = catalog_variants.variant_id)",
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "catalog_variants",
"Alias": "sv_1",
"Startup Cost": 0.00,
"Total Cost": 7.04,
"Plan Rows": 352,
"Plan Width": 8,
"Actual Startup Time": 0.000,
"Actual Total Time": 0.086,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv_1.variant_id", "sv_1.product_id", "sv_1.sku"],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 9.92,
"Total Cost": 9.92,
"Plan Rows": 200,
"Plan Width": 4,
"Actual Startup Time": 0.212,
"Actual Total Time": 0.212,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants.variant_id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 21,
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Aggregate",
"Strategy": "Hashed",
"Parent Relationship": "Outer",
"Startup Cost": 7.92,
"Total Cost": 9.92,
"Plan Rows": 200,
"Plan Width": 4,
"Actual Startup Time": 0.112,
"Actual Total Time": 0.158,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants.variant_id"],
"Group Key": ["catalog_variants.variant_id"],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "catalog_variants",
"Alias": "catalog_variants",
"Startup Cost": 0.00,
"Total Cost": 7.04,
"Plan Rows": 352,
"Plan Width": 4,
"Actual Startup Time": 0.001,
"Actual Total Time": 0.029,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants.variant_id", "catalog_variants.product_id", "catalog_variants.sku"],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
}
]
}
]
},
{
"Node Type": "Index Scan",
"Parent Relationship": "Inner",
"Scan Direction": "Forward",
"Index Name": "index_spree_option_values_variants_on_variant_id",
"Relation Name": "spree_option_values_variants",
"Schema": "public",
"Alias": "sov_sv",
"Startup Cost": 0.29,
"Total Cost": 1.37,
"Plan Rows": 3,
"Plan Width": 8,
"Actual Startup Time": 0.002,
"Actual Total Time": 0.003,
"Actual Rows": 3,
"Actual Loops": 352,
"Output": ["sov_sv.variant_id", "sov_sv.option_value_id", "sov_sv.id"],
"Index Cond": "(sov_sv.variant_id = sv_1.variant_id)",
"Rows Removed by Index Recheck": 0,
"Shared Hit Blocks": 1284,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 6.69,
"Total Cost": 6.69,
"Plan Rows": 71,
"Plan Width": 12,
"Actual Startup Time": 0.064,
"Actual Total Time": 0.064,
"Actual Rows": 11,
"Actual Loops": 1,
"Output": ["sov.presentation", "sov.id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 9,
"Shared Hit Blocks": 3,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 1.05,
"Total Cost": 6.69,
"Plan Rows": 71,
"Plan Width": 12,
"Actual Startup Time": 0.020,
"Actual Total Time": 0.062,
"Actual Rows": 11,
"Actual Loops": 1,
"Output": ["sov.presentation", "sov.id"],
"Hash Cond": "(sov.option_type_id = sot.id)",
"Shared Hit Blocks": 3,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Relation Name": "spree_option_values",
"Schema": "public",
"Alias": "sov",
"Startup Cost": 0.00,
"Total Cost": 4.13,
"Plan Rows": 213,
"Plan Width": 16,
"Actual Startup Time": 0.003,
"Actual Total Time": 0.017,
"Actual Rows": 213,
"Actual Loops": 1,
"Output": ["sov.id", "sov.\"position\"", "sov.name", "sov.presentation", "sov.option_type_id", "sov.created_at", "sov.updated_at"],
"Shared Hit Blocks": 2,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 1.04,
"Total Cost": 1.04,
"Plan Rows": 1,
"Plan Width": 4,
"Actual Startup Time": 0.007,
"Actual Total Time": 0.007,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": ["sot.id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 9,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Relation Name": "spree_option_types",
"Schema": "public",
"Alias": "sot",
"Startup Cost": 0.00,
"Total Cost": 1.04,
"Plan Rows": 1,
"Plan Width": 4,
"Actual Startup Time": 0.003,
"Actual Total Time": 0.003,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": ["sot.id"],
"Filter": "((sot.name)::text = 'color_classification'::text)",
"Rows Removed by Filter": 2,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
}
]
}
]
}
]
}
]
}
]
},
{
"Node Type": "Hash Join",
"Parent Relationship": "InitPlan",
"Subplan Name": "CTE variant_colors",
"Join Type": "Inner",
"Startup Cost": 20.28,
"Total Cost": 282.30,
"Plan Rows": 176,
"Plan Width": 12,
"Actual Startup Time": 0.357,
"Actual Total Time": 1.844,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv_2.variant_id", "sov_1.presentation"],
"Hash Cond": "(sov_sv_1.option_value_id = sov_1.id)",
"Shared Hit Blocks": 1287,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Nested Loop",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 12.71,
"Total Cost": 270.98,
"Plan Rows": 528,
"Plan Width": 8,
"Actual Startup Time": 0.233,
"Actual Total Time": 1.555,
"Actual Rows": 1056,
"Actual Loops": 1,
"Output": ["sv_2.variant_id", "sov_sv_1.option_value_id"],
"Shared Hit Blocks": 1284,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 12.42,
"Total Cost": 24.30,
"Plan Rows": 176,
"Plan Width": 8,
"Actual Startup Time": 0.214,
"Actual Total Time": 0.350,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv_2.variant_id", "catalog_variants_1.variant_id"],
"Hash Cond": "(sv_2.variant_id = catalog_variants_1.variant_id)",
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "catalog_variants",
"Alias": "sv_2",
"Startup Cost": 0.00,
"Total Cost": 7.04,
"Plan Rows": 352,
"Plan Width": 4,
"Actual Startup Time": 0.000,
"Actual Total Time": 0.046,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv_2.variant_id", "sv_2.product_id", "sv_2.sku"],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 9.92,
"Total Cost": 9.92,
"Plan Rows": 200,
"Plan Width": 4,
"Actual Startup Time": 0.204,
"Actual Total Time": 0.204,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants_1.variant_id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 21,
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Aggregate",
"Strategy": "Hashed",
"Parent Relationship": "Outer",
"Startup Cost": 7.92,
"Total Cost": 9.92,
"Plan Rows": 200,
"Plan Width": 4,
"Actual Startup Time": 0.115,
"Actual Total Time": 0.150,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants_1.variant_id"],
"Group Key": ["catalog_variants_1.variant_id"],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "catalog_variants",
"Alias": "catalog_variants_1",
"Startup Cost": 0.00,
"Total Cost": 7.04,
"Plan Rows": 352,
"Plan Width": 4,
"Actual Startup Time": 0.001,
"Actual Total Time": 0.027,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants_1.variant_id", "catalog_variants_1.product_id", "catalog_variants_1.sku"],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
}
]
}
]
},
{
"Node Type": "Index Scan",
"Parent Relationship": "Inner",
"Scan Direction": "Forward",
"Index Name": "index_spree_option_values_variants_on_variant_id",
"Relation Name": "spree_option_values_variants",
"Schema": "public",
"Alias": "sov_sv_1",
"Startup Cost": 0.29,
"Total Cost": 1.37,
"Plan Rows": 3,
"Plan Width": 8,
"Actual Startup Time": 0.002,
"Actual Total Time": 0.003,
"Actual Rows": 3,
"Actual Loops": 352,
"Output": ["sov_sv_1.variant_id", "sov_sv_1.option_value_id", "sov_sv_1.id"],
"Index Cond": "(sov_sv_1.variant_id = sv_2.variant_id)",
"Rows Removed by Index Recheck": 0,
"Shared Hit Blocks": 1284,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 6.69,
"Total Cost": 6.69,
"Plan Rows": 71,
"Plan Width": 12,
"Actual Startup Time": 0.109,
"Actual Total Time": 0.109,
"Actual Rows": 88,
"Actual Loops": 1,
"Output": ["sov_1.presentation", "sov_1.id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 13,
"Shared Hit Blocks": 3,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 1.05,
"Total Cost": 6.69,
"Plan Rows": 71,
"Plan Width": 12,
"Actual Startup Time": 0.034,
"Actual Total Time": 0.090,
"Actual Rows": 88,
"Actual Loops": 1,
"Output": ["sov_1.presentation", "sov_1.id"],
"Hash Cond": "(sov_1.option_type_id = sot_1.id)",
"Shared Hit Blocks": 3,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Relation Name": "spree_option_values",
"Schema": "public",
"Alias": "sov_1",
"Startup Cost": 0.00,
"Total Cost": 4.13,
"Plan Rows": 213,
"Plan Width": 16,
"Actual Startup Time": 0.007,
"Actual Total Time": 0.028,
"Actual Rows": 213,
"Actual Loops": 1,
"Output": ["sov_1.id", "sov_1.\"position\"", "sov_1.name", "sov_1.presentation", "sov_1.option_type_id", "sov_1.created_at", "sov_1.updated_at"],
"Shared Hit Blocks": 2,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 1.04,
"Total Cost": 1.04,
"Plan Rows": 1,
"Plan Width": 4,
"Actual Startup Time": 0.018,
"Actual Total Time": 0.018,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": ["sot_1.id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 9,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Relation Name": "spree_option_types",
"Schema": "public",
"Alias": "sot_1",
"Startup Cost": 0.00,
"Total Cost": 1.04,
"Plan Rows": 1,
"Plan Width": 4,
"Actual Startup Time": 0.014,
"Actual Total Time": 0.015,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": ["sot_1.id"],
"Filter": "((sot_1.name)::text = 'color'::text)",
"Rows Removed by Filter": 2,
"Shared Hit Blocks": 1,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
}
]
}
]
}
]
},
{
"Node Type": "Aggregate",
"Strategy": "Hashed",
"Parent Relationship": "InitPlan",
"Subplan Name": "CTE variants_min_prices",
"Startup Cost": 225.63,
"Total Cost": 271.84,
"Plan Rows": 4621,
"Plan Width": 7,
"Actual Startup Time": 5.936,
"Actual Total Time": 6.037,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["spree_prices.variant_id", "COALESCE(min(spree_prices.amount), '0'::numeric)"],
"Group Key": ["spree_prices.variant_id"],
"Shared Hit Blocks": 102,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 12.42,
"Total Cost": 202.53,
"Plan Rows": 4621,
"Plan Width": 7,
"Actual Startup Time": 2.415,
"Actual Total Time": 5.785,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["spree_prices.variant_id", "spree_prices.amount"],
"Hash Cond": "(spree_prices.variant_id = catalog_variants_2.variant_id)",
"Shared Hit Blocks": 102,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Relation Name": "spree_prices",
"Schema": "public",
"Alias": "spree_prices",
"Startup Cost": 0.00,
"Total Cost": 153.42,
"Plan Rows": 9242,
"Plan Width": 7,
"Actual Startup Time": 0.023,
"Actual Total Time": 2.548,
"Actual Rows": 9242,
"Actual Loops": 1,
"Output": ["spree_prices.id", "spree_prices.variant_id", "spree_prices.amount", "spree_prices.currency", "spree_prices.deleted_at", "spree_prices.is_default"],
"Shared Hit Blocks": 61,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 9.92,
"Total Cost": 9.92,
"Plan Rows": 200,
"Plan Width": 4,
"Actual Startup Time": 1.229,
"Actual Total Time": 1.229,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants_2.variant_id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 21,
"Shared Hit Blocks": 41,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Aggregate",
"Strategy": "Hashed",
"Parent Relationship": "Outer",
"Startup Cost": 7.92,
"Total Cost": 9.92,
"Plan Rows": 200,
"Plan Width": 4,
"Actual Startup Time": 1.075,
"Actual Total Time": 1.140,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants_2.variant_id"],
"Group Key": ["catalog_variants_2.variant_id"],
"Shared Hit Blocks": 41,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "catalog_variants",
"Alias": "catalog_variants_2",
"Startup Cost": 0.00,
"Total Cost": 7.04,
"Plan Rows": 352,
"Plan Width": 4,
"Actual Startup Time": 0.024,
"Actual Total Time": 0.915,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["catalog_variants_2.variant_id", "catalog_variants_2.product_id", "catalog_variants_2.sku"],
"Shared Hit Blocks": 41,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
}
]
}
]
}
]
},
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 42.71,
"Total Cost": 291.08,
"Plan Rows": 4050,
"Plan Width": 183,
"Actual Startup Time": 13.149,
"Actual Total Time": 13.526,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv.variant_id", "sv.sku", "sp.slug", "sp.name", "vc.color", "pr.min_price", "pcc.available_colors", "sv.product_id"],
"Hash Cond": "(pr.variant_id = sv.variant_id)",
"Shared Hit Blocks": 2692,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "variants_min_prices",
"Alias": "pr",
"Startup Cost": 0.00,
"Total Cost": 92.42,
"Plan Rows": 4621,
"Plan Width": 36,
"Actual Startup Time": 5.939,
"Actual Total Time": 6.157,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["pr.variant_id", "pr.min_price"],
"Shared Hit Blocks": 102,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 40.52,
"Total Cost": 40.52,
"Plan Rows": 175,
"Plan Width": 155,
"Actual Startup Time": 7.189,
"Actual Total Time": 7.189,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv.variant_id", "sv.sku", "sv.product_id", "sp.slug", "sp.name", "vc.color", "vc.variant_id", "pcc.available_colors"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 63,
"Shared Hit Blocks": 2590,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 27.68,
"Total Cost": 40.52,
"Plan Rows": 175,
"Plan Width": 155,
"Actual Startup Time": 6.664,
"Actual Total Time": 7.024,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv.variant_id", "sv.sku", "sv.product_id", "sp.slug", "sp.name", "vc.color", "vc.variant_id", "pcc.available_colors"],
"Hash Cond": "(sv.variant_id = vc.variant_id)",
"Shared Hit Blocks": 2590,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 21.96,
"Total Cost": 32.31,
"Plan Rows": 199,
"Plan Width": 119,
"Actual Startup Time": 4.636,
"Actual Total Time": 4.846,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv.variant_id", "sv.sku", "sv.product_id", "sp.slug", "sp.name", "pcc.available_colors"],
"Hash Cond": "(sv.product_id = sp.id)",
"Shared Hit Blocks": 1303,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "catalog_variants",
"Alias": "sv",
"Startup Cost": 0.00,
"Total Cost": 7.04,
"Plan Rows": 352,
"Plan Width": 40,
"Actual Startup Time": 0.001,
"Actual Total Time": 0.059,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["sv.variant_id", "sv.product_id", "sv.sku"],
"Shared Hit Blocks": 0,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 19.76,
"Total Cost": 19.76,
"Plan Rows": 176,
"Plan Width": 87,
"Actual Startup Time": 4.622,
"Actual Total Time": 4.622,
"Actual Rows": 311,
"Actual Loops": 1,
"Output": ["sp.slug", "sp.name", "sp.id", "pcc.available_colors", "pcc.product_id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 47,
"Shared Hit Blocks": 1303,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Hash Join",
"Parent Relationship": "Outer",
"Join Type": "Inner",
"Startup Cost": 5.72,
"Total Cost": 19.76,
"Plan Rows": 176,
"Plan Width": 87,
"Actual Startup Time": 4.258,
"Actual Total Time": 4.510,
"Actual Rows": 311,
"Actual Loops": 1,
"Output": ["sp.slug", "sp.name", "sp.id", "pcc.available_colors", "pcc.product_id"],
"Hash Cond": "(sp.id = pcc.product_id)",
"Shared Hit Blocks": 1303,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Relation Name": "spree_products",
"Schema": "public",
"Alias": "sp",
"Startup Cost": 0.00,
"Total Cost": 11.11,
"Plan Rows": 311,
"Plan Width": 51,
"Actual Startup Time": 0.016,
"Actual Total Time": 0.115,
"Actual Rows": 311,
"Actual Loops": 1,
"Output": ["sp.id", "sp.name", "sp.description", "sp.available_on", "sp.deleted_at", "sp.slug", "sp.meta_description", "sp.meta_keywords", "sp.tax_category_id", "sp.shipping_category_id", "sp.created_at", "sp.updated_at", "sp.promotionable", "sp.meta_title", "sp.fashion_xl_id"],
"Filter": "(sp.deleted_at IS NULL)",
"Rows Removed by Filter": 0,
"Shared Hit Blocks": 8,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 3.52,
"Total Cost": 3.52,
"Plan Rows": 176,
"Plan Width": 36,
"Actual Startup Time": 4.228,
"Actual Total Time": 4.228,
"Actual Rows": 311,
"Actual Loops": 1,
"Output": ["pcc.available_colors", "pcc.product_id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 31,
"Shared Hit Blocks": 1295,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "product_color_classifications",
"Alias": "pcc",
"Startup Cost": 0.00,
"Total Cost": 3.52,
"Plan Rows": 176,
"Plan Width": 36,
"Actual Startup Time": 2.801,
"Actual Total Time": 4.136,
"Actual Rows": 311,
"Actual Loops": 1,
"Output": ["pcc.available_colors", "pcc.product_id"],
"Shared Hit Blocks": 1295,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
}
]
}
]
}
]
},
{
"Node Type": "Hash",
"Parent Relationship": "Inner",
"Startup Cost": 3.52,
"Total Cost": 3.52,
"Plan Rows": 176,
"Plan Width": 36,
"Actual Startup Time": 2.018,
"Actual Total Time": 2.018,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["vc.color", "vc.variant_id"],
"Hash Buckets": 1024,
"Original Hash Buckets": 1024,
"Hash Batches": 1,
"Original Hash Batches": 1,
"Peak Memory Usage": 26,
"Shared Hit Blocks": 1287,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "variant_colors",
"Alias": "vc",
"Startup Cost": 0.00,
"Total Cost": 3.52,
"Plan Rows": 176,
"Plan Width": 36,
"Actual Startup Time": 0.358,
"Actual Total Time": 1.945,
"Actual Rows": 352,
"Actual Loops": 1,
"Output": ["vc.color", "vc.variant_id"],
"Shared Hit Blocks": 1287,
"Shared Read Blocks": 0,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
}
]
}
]
}
]
}
]
},
"Planning Time": 4.462,
"Triggers": [
],
"Execution Time": 14.391
}
]Query:
WITH catalog_variants AS (
SELECT id variant_id, product_id, sku FROM spree_variants WHERE deleted_at IS NULL AND show_in_catalog
),
product_color_classifications AS (
SELECT sv.product_id, array_agg(DISTINCT sov.presentation) available_colors
FROM catalog_variants sv
JOIN spree_option_values_variants sov_sv USING(variant_id)
JOIN spree_option_values sov ON sov_sv.option_value_id = sov.id
JOIN spree_option_types sot ON sov.option_type_id = sot.id
WHERE sot.name = 'color_classification'
AND sov_sv.variant_id IN (SELECT variant_id FROM catalog_variants)
GROUP BY sv.product_id
),
variant_colors AS (
SELECT sv.variant_id, sov.presentation color
FROM catalog_variants sv
JOIN spree_option_values_variants sov_sv USING(variant_id)
JOIN spree_option_values sov ON sov_sv.option_value_id = sov.id
JOIN spree_option_types sot ON sov.option_type_id = sot.id
WHERE sot.name = 'color'
AND sov_sv.variant_id IN (SELECT variant_id FROM catalog_variants)
),
variants_min_prices AS (
SELECT variant_id, COALESCE(min(amount), 0) min_price
FROM spree_prices
WHERE variant_id IN (SELECT variant_id FROM catalog_variants)
GROUP BY variant_id
)
SELECT sv.variant_id id, sv.sku, sp.slug, sp.name, vc.color, pr.min_price, pcc.available_colors
FROM catalog_variants sv
JOIN spree_products sp ON sp.id = sv.product_id
JOIN variants_min_prices pr USING(variant_id)
JOIN variant_colors vc USING(variant_id)
JOIN product_color_classifications pcc USING(product_id)
WHERE sp.deleted_at IS NULL
ORDER BY sv.product_id;Btw. here's the same query (but different run) on explain.depesz.com: http://explain.depesz.com/s/JcoC
I really don't get how that tool calculates the exclusive time, because 11.843 ms - 11.819 ms should be 0.024 ms but exclusive time is shown as 0.441 ms.
felixbuenemann
commented
8 years ago Ah, I get it, the explain.depesz.com exclusive time is not the difference of the actual start and end time, but the difference between the inclusive time of this node minus the inclusive time of the subnodes.
felixbuenemann
commented
8 years ago I think what happens is that pev subtracts the execution time for the CTEs from the execution time of the sort, but instead these should be ignored, because they are already included in the total times of the subnodes referencing the CTEs. explain.depesz.com seems to calculate this correctly, the times for the CTEs are part of the final hash join node, that shows up with 11.4 ms on despesz.
felixbuenemann
commented
8 years ago Here is a much shorter example that shows the problem (the query doesn't make any sense, it's just for illustration), PEV shows -87% in the final aggregate node:
[
{
"Plan": {
"Node Type": "Aggregate",
"Strategy": "Plain",
"Startup Cost": 407544.79,
"Total Cost": 407544.80,
"Plan Rows": 1,
"Plan Width": 0,
"Actual Startup Time": 7232.094,
"Actual Total Time": 7232.094,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": ["count(*)"],
"Shared Hit Blocks": 323,
"Shared Read Blocks": 29748,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 45795,
"Temp Written Blocks": 71001,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Sort",
"Parent Relationship": "InitPlan",
"Subplan Name": "CTE extras_cte",
"Startup Cost": 373884.66,
"Total Cost": 377250.68,
"Plan Rows": 1346405,
"Plan Width": 139,
"Actual Startup Time": 5643.506,
"Actual Total Time": 6631.646,
"Actual Rows": 1346394,
"Actual Loops": 1,
"Output": ["extras.id", "extras.engine_id", "extras.category_name", "extras.option_id", "extras.option_code", "extras.option_type", "extras.label", "extras.price_net", "extras.price_gross", "extras.dbnames"],
"Sort Key": ["extras.category_name"],
"Sort Method": "external merge",
"Sort Space Used": 201848,
"Sort Space Type": "Disk",
"Shared Hit Blocks": 323,
"Shared Read Blocks": 29748,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 45795,
"Temp Written Blocks": 45795,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Seq Scan",
"Parent Relationship": "Outer",
"Relation Name": "extras",
"Schema": "public",
"Alias": "extras",
"Startup Cost": 0.00,
"Total Cost": 43532.05,
"Plan Rows": 1346405,
"Plan Width": 139,
"Actual Startup Time": 0.059,
"Actual Total Time": 392.022,
"Actual Rows": 1346394,
"Actual Loops": 1,
"Output": ["extras.id", "extras.engine_id", "extras.category_name", "extras.option_id", "extras.option_code", "extras.option_type", "extras.label", "extras.price_net", "extras.price_gross", "extras.dbnames"],
"Shared Hit Blocks": 320,
"Shared Read Blocks": 29748,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
},
{
"Node Type": "CTE Scan",
"Parent Relationship": "Outer",
"CTE Name": "extras_cte",
"Alias": "extras_cte",
"Startup Cost": 0.00,
"Total Cost": 26928.10,
"Plan Rows": 1346405,
"Plan Width": 0,
"Actual Startup Time": 5643.509,
"Actual Total Time": 7126.421,
"Actual Rows": 1346394,
"Actual Loops": 1,
"Output": ["extras_cte.id", "extras_cte.engine_id", "extras_cte.category_name", "extras_cte.option_id", "extras_cte.option_code", "extras_cte.option_type", "extras_cte.label", "extras_cte.price_net", "extras_cte.price_gross", "extras_cte.dbnames"],
"Shared Hit Blocks": 323,
"Shared Read Blocks": 29748,
"Shared Dirtied Blocks": 0,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 45795,
"Temp Written Blocks": 71001,
"I/O Read Time": 0.000,
"I/O Write Time": 0.000
}
]
},
"Planning Time": 0.715,
"Triggers": [
],
"Execution Time": 7512.649
}
]WITH extras_cte AS (SELECT * FROM extras ORDER BY category_name) SELECT COUNT(*) FROM extras_cte;Explain on explain.depesz.com: http://explain.depesz.com/s/1BbAf
If one looks at the start times, it is evident that the sort gets triggered as part of the cte scan, so it is included in the execution time of the cte scan, but pve counts it separately, which leads to 7232.094 ms (aggregate) - 7126.421 ms (cte scan) - 6631.646 ms (sort) = -6525.973 ms (wrong actual duration of aggregate).
AlexTatiyants
commented
8 years ago @felixbuenemann thank you so much for all this information, it was very helpful. I'm working on a fix, should be pushed up shortly.
felixbuenemann
commented
8 years ago Great, btw I noticed the CTE nodes are marked as "Parent Relationship": "InitPlan" while the other plans are marked as "Parent Relationship": "Outer". Maybe that is a more general approach, then checking for CTEs.
AlexTatiyants
commented
8 years ago yeah, that’s an interesting observation.
On March 5, 2016 at 12:04:05 PM, Felix Bünemann (notifications@github.com) wrote:
Great, btw I noticed the CTE nodes are marked as "Parent Relationship": "InitPlan" while the other plans are marked as "Parent Relationship": "Outer".
— Reply to this email directly or view it on GitHub.
felixbuenemann
commented
8 years ago I just tried on master and the calculations still seem to be wrong.
explain.depesz.com lists the exclusive time at 114ms, which is the difference between the inclusive time of the cte scan node and the inclusive time of the aggregate node, but leaves a gap of 343 ms to the total execution time of the query of 7700 ms.
In PEV it now calculates the actual duration of the aggregate node as 600 ms, which when added to the 7.13 s of the cte scan node sums up to 7.73s, but the total execution time is only 7.51s and the difference between the total times of the cte scan node and the aggregate node is only 105ms.
AlexTatiyants
commented
8 years ago Hmm, so it’s not as simple as just excluding CTE time from the parent. i’ll need to think about it some more,
On March 5, 2016 at 12:25:55 PM, Felix Bünemann (notifications@github.com) wrote:
I just tried on master and the calculations still seem to be wrong.
explain.depesz.com lists the exclusive time at 114ms, which is the difference between the inclusive time of the cte scan node and the inclusive time of the aggregate node, but leaves a gap of 343 ms to the total execution time of the query of 7700 ms.
In PEV it now calculates the actual duration of the aggregate node as 600 ms, which when added to the 7.13 s of the cte scan node sums up to 7.73s, but the total execution time is only 7.51s and the difference between the total times of the cte scan node and the aggregate node is only 105ms.
— Reply to this email directly or view it on GitHub.
felixfbecker
commented
4 years ago I have the same problem
Could this issue be reopened?
felixfbecker
commented
4 years ago Since I read CTEs mentioned above, I rewrote the query to not use any CTEs (instead subqueries), but it's still happening :/
pgiraud
commented
4 years ago @felixfbecker Have you heard about https://github.com/dalibo/pev2 ? I'd be interested to know if you get negative durations on this new tool as well. If so, please share your plan.
felixfbecker
commented
4 years ago Nope, it works there! I had not heard of it, it looks awesome!