Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-31558

Add InnoDB engine information to the slow query log

Details

    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.

      Attachments

        Issue Links

          Activity

            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.

            marko Marko Mäkelä added a comment - 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.

            Undo_rows_read added

            monty Michael Widenius added a comment - Undo_rows_read added

            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.

            marko Marko Mäkelä added a comment - 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 .

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

            marko Marko Mäkelä added a comment - I filed MDEV-31589 for the anomaly. MDEV-20301 is innocent for it.

            Backporting code to 10.6 (original code was for 10.11)

            monty Michael Widenius added a comment - Backporting code to 10.6 (original code was for 10.11)

            People

              monty Michael Widenius
              monty Michael Widenius
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.