ANALYZE FORMAT=JSON now shows InnoDB buffer pool reads

Short: Starting from the latest MariaDB 10.6.15 and latest releases of other versions (yes, even stable ones), ANALYZE FORMAT=JSON prints counts of InnoDB page accesses and reads. Look for r_engine_stats. This is similar to PostgreSQL’s EXPLAIN (ANALYZE, BUFFERS).

Long: It was needed for diagnosing performance issues at a customer. The information is printed into slow query log (MDEV-31558), in a similar (but not identical) way how it’s done in Percona Server. The log shows total query increments for the query. ANALYZE FORMAT=JSON (MDEV-31577) output shows counters for each query plan node. It looks like this on a cold buffer pool:

MariaDB> analyze format=json select min(filler1), count(kp2)
      -> from t1 where kp1 between 1 and 1000\G
*************************** 1. row ***************************
ANALYZE: {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 10.832,
    "table": {
      "table_name": "t1",
      "access_type": "range",
      "possible_keys": ["kp1"],
      "key": "kp1",
      "key_length": "5",
      "used_key_parts": ["kp1"],
      "r_loops": 1,
      "rows": 981,
      "r_rows": 981,
      "r_table_time_ms": 10.488,
      "r_other_time_ms": 0.328,
      "r_engine_stats": {
        "pages_accessed": 2947,
        "pages_read_count": 1240,
        "pages_read_time_ms": 6.314
      },
      "filtered": 100,
      "r_filtered": 100,
      "index_condition": "t1.kp1 between 1 and 1000"
    }
  }
}

One can see that reading the table accessed 2947 pages which resulted in 1240 page reads which took 6.314 milliseconds.

If I re-run the query, it still accesses "pages_accessed": 2947 pages, but the pages are now in the buffer pool, so pages_read_count and pages_read_time_ms are zero and are not printed:

MariaDB> analyze format=json select min(filler1), count(kp2)
      -> from t1 where kp1 between 1 and 1000\G
*************************** 1. row ***************************
ANALYZE: {
  "query_block": {
    "select_id": 1,
    "r_loops": 1,
    "r_total_time_ms": 6.512,
    "table": {
      "table_name": "t1",
      "access_type": "range",
      "possible_keys": ["kp1"],
      "key": "kp1",
      "key_length": "5",
      "used_key_parts": ["kp1"],
      "r_loops": 1,
      "rows": 981,
      "r_rows": 981,
      "r_table_time_ms": 5.905,
      "r_other_time_ms": 0.59,
      "r_engine_stats": {
        "pages_accessed": 2947
      },
      "filtered": 100,
      "r_filtered": 100,
      "index_condition": "t1.kp1 between 1 and 1000"
    }
  }
}

Leave a comment