0

I'm trying to optimize some queries in MariaDB, and I've found the ANALYZE FORMAT=JSON functionality to be extremely useful. However, in the case of some complex joins, I'm running into some examples where the time doesn't add up, or come close to it.

A when-it-works example, in the case of one query, the query_block r_total_time_ms was about 239ms; the query itself involved 11 tables, and one of those 11 was taking up nearly 227ms, accounting for the large majority of the time spent in the query. There was an obvious index change to make, and making it took that element down to less than 1 ms, and total query time to just over 1 ms.

But in another case, the query_block r_total_time_ms is a little over 163ms; the query involves 9 tables and/or subqueries, and the highest r_total_time_ms for any of the components is just over 15 ms. The total of all those components adds up to about 25 ms. So where is the rest of the time being spent? What's it doing for the other 140-ish ms? If there's a way to tell, I don't know what it is.

Here's the ANALYZE output that I'm struggling with:

ANALYZE
{
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 163.18,
    "filesort": {
      "sort_key": "tcontent.lastUpdate",
      "r_loops": 1,
      "r_total_time_ms": 0.0147,
      "r_limit": 20,
      "r_used_priority_queue": false,
      "r_output_rows": 2,
      "r_buffer_size": "252",
      "temporary_table": {
        "table": {
          "table_name": "tcontent",
          "access_type": "index_merge",
          "possible_keys": [
            "IX_TContent",
            "IX_TContent_1",
            "IX_TContent_2",
            "IX_TContent_5",
            "IX_tcontent_mobileExclude",
            "IX_tcontent_displaystart",
            "IX_tcontent_displaystop",
            "IX_tcontent_approved",
            "IX_tcontent_active",
            "IX_tcontent_display",
            "IX_tcontent_type",
            "ntID_Type_subType_Display_DisplayStart_DisplayStop_mobileExclude",
            "ix_tcontent_SiteID_Active_Filename_Type"
          ],
          "key_length": "2,2,2,2,2,78,106",
          "index_merge": {
            "union": {

              "range": {
                "key": "IX_tcontent_display",
                "used_key_parts": ["Display"]
              },
              "range": {
                "key": "IX_tcontent_display",
                "used_key_parts": ["Display"]
              },
              "intersect": {
                "range": {
                  "key": "IX_tcontent_approved",
                  "used_key_parts": ["Approved"]
                },
                "range": {
                  "key": "IX_tcontent_active",
                  "used_key_parts": ["Active"]
                },
                "range": {
                  "key": "IX_tcontent_display",
                  "used_key_parts": ["Display"]
                },
                "range": {
                  "key": "IX_TContent_2",
                  "used_key_parts": ["SiteID"]
                },
                "range": {
                  "key": "IX_TContent_5",
                  "used_key_parts": ["ModuleID"]
                }
              }
            }
          },
          "r_loops": 1,
          "rows": 2583,
          "r_rows": 3966,
          "r_total_time_ms": 15.183,
          "filtered": 96.129,
          "r_filtered": 98.664,
          "attached_condition": "tcontent.Active = 1 and tcontent.Approved = 1 and tcontent.searchExclude = 0 and tcontent.SiteID = 'CAE' and tcontent.ModuleID = '00000000000000000000000000000000000' and tcontent.ContentID <> '00000000000000000000000000000000001' and tcontent.`Type` <> 'Module' and (tcontent.Display = 1 or tcontent.Display = 2 and (tcontent.DisplayStart <= '2018-01-09 15:17:00' and (tcontent.DisplayStop >= '2018-01-09 15:17:00' or tcontent.DisplayStop is null) or tcontent.DisplayStart <= '2019-01-09 15:17:00' and (tcontent.DisplayStop >= '2018-01-09 15:17:00' or tcontent.DisplayStop is null))) and (tcontent.mobileExclude is null or tcontent.mobileExclude in (0,1))"
        },
        "table": {
          "table_name": "<subquery2>",
          "access_type": "eq_ref",
          "possible_keys": ["distinct_key"],
          "key": "distinct_key",
          "key_length": "105",
          "used_key_parts": ["contentHistID"],
          "ref": ["func"],
          "r_loops": 3913,
          "rows": 1,
          "r_rows": 5.1e-4,
          "r_total_time_ms": 6.2577,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "tcontent.Display = 1 or tcontent.Display = 2 and (tcontent.DisplayStart <= '2018-01-09 15:17:00' and (tcontent.DisplayStop >= '2018-01-09 15:17:00' or tcontent.DisplayStop is null) or tcontent.DisplayStart <= '2019-01-09 15:17:00' and (tcontent.DisplayStop >= '2018-01-09 15:17:00' or tcontent.DisplayStop is null))",
          "materialized": {
            "unique": 1,
            "query_block": {
              "select_id": 2,
              "table": {
                "table_name": "tcontentcategories",
                "access_type": "ALL",
                "possible_keys": ["PRIMARY"],
                "r_loops": 1,
                "rows": 166,
                "r_rows": 166,
                "r_total_time_ms": 0.2246,
                "filtered": 100,
                "r_filtered": 0.6024,
                "attached_condition": "tcontentcategories.path like '%D3386B7B-5056-8740-7CA949A8C39FACF3%'"
              },
              "table": {
                "table_name": "tcontentcategoryassign",
                "access_type": "ref",
                "possible_keys": [
                  "PRIMARY",
                  "IX_tcontentcategoryassign_categoryID"
                ],
                "key": "IX_tcontentcategoryassign_categoryID",
                "key_length": "105",
                "used_key_parts": ["categoryID"],
                "ref": ["dbMuraCMS.tcontentcategories.categoryID"],
                "r_loops": 1,
                "rows": 53,
                "r_rows": 33,
                "r_total_time_ms": 0.0413,
                "filtered": 100,
                "r_filtered": 100,
                "using_index": true
              }
            }
          }
        },
        "table": {
          "table_name": "tfiles",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY"],
          "key": "PRIMARY",
          "key_length": "105",
          "used_key_parts": ["fileID"],
          "ref": ["dbMuraCMS.tcontent.FileID"],
          "r_loops": 2,
          "rows": 1,
          "r_rows": 1,
          "r_total_time_ms": 0.0109,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "trigcond(trigcond(tcontent.FileID is not null))"
        },
        "table": {
          "table_name": "tcontentstats",
          "access_type": "eq_ref",
          "possible_keys": ["PRIMARY"],
          "key": "PRIMARY",
          "key_length": "182",
          "used_key_parts": ["contentID", "siteID"],
          "ref": ["dbMuraCMS.tcontent.ContentID", "dbMuraCMS.tcontent.SiteID"],
          "r_loops": 2,
          "rows": 1,
          "r_rows": 0,
          "r_total_time_ms": 0.0127,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "trigcond(trigcond(tcontent.ContentID is not null and tcontent.SiteID is not null))"
        },
        "table": {
          "table_name": "tparent",
          "access_type": "ref",
          "possible_keys": [
            "IX_TContent",
            "IX_TContent_2",
            "IX_tcontent_active",
            "ntID_Type_subType_Display_DisplayStart_DisplayStop_mobileExclude",
            "ix_tcontent_SiteID_Active_Filename_Type"
          ],
          "key": "IX_TContent",
          "key_length": "106",
          "used_key_parts": ["ContentID"],
          "ref": ["dbMuraCMS.tcontent.ParentID"],
          "r_loops": 2,
          "rows": 1,
          "r_rows": 238,
          "r_total_time_ms": 1.5375,
          "filtered": 100,
          "r_filtered": 0.4202,
          "attached_condition": "trigcond(tcontent.Display = 1 or tcontent.Display = 2 and (tparent.`Type` <> 'Calendar' and tcontent.DisplayStart <= '2018-01-09 15:17:00' and (tcontent.DisplayStop >= '2018-01-09 15:17:00' or tcontent.DisplayStop is null) or tparent.`Type` = 'Calendar' and tcontent.DisplayStart <= '2019-01-09 15:17:00' and (tcontent.DisplayStop >= '2018-01-09 15:17:00' or tcontent.DisplayStop is null))) and trigcond(tparent.SiteID = tcontent.SiteID and tparent.Active = 1 and trigcond(tcontent.ParentID is not null))"
        },
        "table": {
          "table_name": "tcontentfilemetadata",
          "access_type": "ALL",
          "possible_keys": [
            "IX_tcontentfilemetadata_contenthistid",
            "IX_tcontentfilemetadata_fileid"
          ],
          "r_loops": 2,
          "rows": 1,
          "r_rows": 0,
          "r_total_time_ms": 0.0045,
          "filtered": 100,
          "r_filtered": 100,
          "attached_condition": "trigcond(tcontentfilemetadata.fileid = tcontent.FileID and tcontentfilemetadata.contenthistid = tcontent.ContentHistID)"
        }
      }
    }
  }
}
1

1 Answer 1

0

I'm not certain why it's not showing up in the timings, but in this case, the time was being occupied by the index_merge step. After analyzing the issue further, I discovered that MariaDB isn't as good as other database platforms at recognizing and therefore ignoring bad/unhelpful indices (with very low selectivity). By removing several of these from the table in question, I was able to get it to skip those indices (and the index_merge altogether), and execution time went down from 160-ish ms to under 10 ms.

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.