[MDEV-31558] Add InnoDB engine information to the slow query log Created: 2023-06-27  Updated: 2023-11-30  Resolved: 2023-07-07

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Fix Version/s: 10.6.15, 10.9.8, 10.10.6, 10.11.5

Type: Task Priority: Critical
Reporter: Michael Widenius Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
causes MDEV-30875 main.analyze_stmt_orderby/rowid_filte... Closed
causes MDEV-32159 AIX crash on mariadbd --bootstrap - i... Closed
causes MDEV-32910 cycles can overflow and result in lar... Stalled
Relates
relates to MDEV-31577 Make ANALYZE FORMAT=JSON print innodb... Closed
relates to MDEV-31589 Secondary index MVCC access is unnece... Stalled

 Description   

Percona server has some useful InnoDB status information in the slow query log.
The Percona Performance Monitor can provide useful graphs from these

This task is to add some of the most useful ones, but with less code.
The code should also be engine independent, so that it is easy to add
monitoring of other engines!

The current task will add the following new information to the slow query log if enabled with
--log-slow-verbosity=innodb

 # Pages_accessed: 184  Pages_read: 95  Pages_updated: 0  Undo_rows_read: 1
 # Pages_read_time: 17.0204  Engine_time: 248.1297

Engine_time is how many milliseconds is spent inside engine calls (similar as with analyze).
Page_* variables are for now only for InnoDB.



 Comments   
Comment by Marko Mäkelä [ 2023-06-27 ]

To assess the impact of purge lag (MDEV-29401), it could be useful to separately track the reads of pages that reside in the undo tablespaces, or in the system tablespace. That is, we could have a separate System_pages_read or System_pages_accessed. I do not currently have an idea how to do this without adding conditional branches (which destroy the performance of superscalar CPUs). For the Pages_read counter, which would cover reads from the file system to the buffer pool, we can afford to add a condition, because that code path is slow and hopefully rarely invoked.

Possibly, we could add another counter at the high level (say, trx_undo_prev_version_build(), row_vers_impl_x_locked_low()) for tracking undo log record access, and let the page counters cover all types of page reads.

Comment by Michael Widenius [ 2023-06-28 ]

Undo_rows_read added

Comment by Marko Mäkelä [ 2023-06-30 ]

The undo_records_read that monty added to trx_undo_prev_version_build() is covering also "semi-consistent reads" and implicit lock checks. So, the code is complete. I would like to see this being pushed to 10.6 after some performance and correctness testing.

psergei implemented an ANALYZE interface and helped me develop the following test case, which I think should be added so that we will have some validation that the counters actually work:

diff --git a/mysql-test/suite/innodb/t/mvcc_secondary.test b/mysql-test/suite/innodb/t/mvcc_secondary.test
index 93c91c40076..40ece3d33a7 100644
--- a/mysql-test/suite/innodb/t/mvcc_secondary.test
+++ b/mysql-test/suite/innodb/t/mvcc_secondary.test
@@ -17,10 +17,14 @@ UPDATE t1 SET c=REPEAT('d',170);
 
 connect (con1,localhost,root,,);
 SELECT pk FROM t1 FORCE INDEX (c);
+let $js=`ANALYZE FORMAT=json_ext SELECT pk FROM t1 FORCE INDEX (c)`;
+evalp select json_extract('$js', '\$**.undo_records_read') undo_records_read;
 connection default;
 COMMIT;
 connection con1;
 SELECT pk FROM t1 FORCE INDEX (c);
+let $js=`ANALYZE FORMAT=json_ext SELECT pk FROM t1 FORCE INDEX (c)`;
+evalp select json_extract('$js', '\$**.undo_records_read') undo_records_read;
 disconnect con1;
 connection default;
 DROP TABLE t1;
diff --git a/mysql-test/suite/innodb/r/mvcc_secondary.result b/mysql-test/suite/innodb/r/mvcc_secondary.result
index 2289742e830..ae30f96b5a2 100644
--- a/mysql-test/suite/innodb/r/mvcc_secondary.result
+++ b/mysql-test/suite/innodb/r/mvcc_secondary.result
@@ -13,12 +13,18 @@ connect  con1,localhost,root,,;
 SELECT pk FROM t1 FORCE INDEX (c);
 pk
 1
+select json_extract('$js', '\$**.undo_records_read') undo_records_read;
+undo_records_read
+[2]
 connection default;
 COMMIT;
 connection con1;
 SELECT pk FROM t1 FORCE INDEX (c);
 pk
 1
+select json_extract('$js', '\$**.undo_records_read') undo_records_read;
+undo_records_read
+NULL
 disconnect con1;
 connection default;
 DROP TABLE t1;

This test case actually revealed a performance bug. There is only 1 record in the table, with 2 versions, yet the previous version of the clustered index record will be fetched twice in Row_sel_get_clust_rec_for_mysql::operator(). I will have to check how the logic would be if I revert MDEV-20301.

Comment by Marko Mäkelä [ 2023-06-30 ]

I filed MDEV-31589 for the anomaly. MDEV-20301 is innocent for it.

Comment by Michael Widenius [ 2023-07-07 ]

Backporting code to 10.6 (original code was for 10.11)

Generated at Thu Feb 08 10:24:46 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.