mirror/mariadb
1
0
Fork 0
mirror of https://github.com/MariaDB/server.git synced 2025-01-28 17:54:16 +01:00
Code Issues Projects Releases Packages Wiki Activity Actions
mariadb/mysql-test/main/log_slow_innodb.result

95 lines
5.8 KiB
Text
Raw Normal View History

MDEV-31558 Add InnoDB engine information to the slow query log The new statistics is enabled by adding the "engine", "innodb" or "full" option to --log-slow-verbosity Example output: # Pages_accessed: 184 Pages_read: 95 Pages_updated: 0 Old_rows_read: 1 # Pages_read_time: 17.0204 Engine_time: 248.1297 Page_read_time is time doing physical reads inside a storage engine. (Writes cannot be tracked as these are usually done in the background). Engine_time is the time spent inside the storage engine for the full duration of the read/write/update calls. It uses the same code as 'analyze statement' for calculating the time spent. The engine statistics is done with a generic interface that should be easy for any engine to use. It can also easily be extended to provide even more statistics. Currently only InnoDB has counters for Pages_% and Undo_% status. Engine_time works for all engines. Implementation details: class ha_handler_stats holds all engine stats. This class is included in handler and THD classes. While a query is running, all statistics is updated in the handler. In close_thread_tables() the statistics is added to the THD. handler::handler_stats is a pointer to where statistics should be collected. This is set to point to handler::active_handler_stats if stats are requested. If not, it is set to 0. handler_stats has also an element, 'active' that is 1 if stats are requested. This is to allow engines to avoid doing any 'if's while updating the statistics. Cloned or partition tables have the pointer set to the base table if status are requested. There is a small performance impact when using --log-slow-verbosity=engine: - All engine calls in 'select' will be timed. - IO calls for InnoDB reads will be timed. - Incrementation of counters are done on local variables and accesses are inline, so these should have very little impact. - Statistics has to be reset for each statement for the THD and each used handler. This is only 40 bytes, which should be neglectable. - For partition tables we have to loop over all partitions to update the handler_status as part of table_init(). Can be optimized in the future to only do this is log-slow-verbosity changes. For this to work we have to update handler_status for all opened partitions and also for all partitions opened in the future. Other things: - Added options 'engine' and 'full' to log-slow-verbosity. - Some of the new files in the test suite comes from Percona server, which has similar status information. - buf_page_optimistic_get(): Do not increment any counter, since we are only validating a pointer, not performing any buf_pool.page_hash lookup. - Added THD argument to save_explain_data_intern(). - Switched arguments for save_explain_.*_data() to have always THD first (generates better code as other functions also have THD first).
2023-07-07 08:38:55 +03:00
CREATE TABLE t1(a INT primary key, b int) ENGINE=InnoDB;
INSERT INTO t1 select seq, seq from seq_1_to_1000;
SET SESSION min_examined_row_limit=0;
SET SESSION long_query_time=0;
SET SESSION log_slow_verbosity='innodb,query_plan';
[slow_log_start.inc] log_slow_innodb-verbosity_1
SELECT sum(a+b) FROM t1;
sum(a+b)
1001000
UPDATE t1 set b=b+1 where a=1 or a=999;
[log_slow_stop.inc] log_slow_innodb-verbosity_1
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Thread_id: .+ Schema: .+ QC_hit: (Yes|No)$ expected_matches: 3
[log_grep.inc] found expected match count: 3
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Query_time: \d+\.\d+ Lock_time: \d+\.\d+ Rows_sent: \d+ Rows_examined: \d+$ expected_matches: 3
[log_grep.inc] found expected match count: 3
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Rows_affected: \d+ Bytes_sent: \d+$ expected_matches: 3
[log_grep.inc] found expected match count: 3
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Full_scan: (Yes|No) Full_join: (Yes|No) Tmp_table: (Yes|No) Tmp_table_on_disk: (Yes|No)$
[log_grep.inc] lines: 1
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Filesort: (Yes|No) Filesort_on_disk: (Yes|No) Merge_passes: \d+\ Priority_queue: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Filesort: (Yes|No) Filesort_on_disk: (Yes|No) Merge_passes: \d+\ Priority_queue: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Tmp_tables: \d+ Tmp_disk_tables: \d+$
[log_grep.inc] lines: 0
MDEV-34190: r_engine_stats.pages_read_count is unrealistically low The symptoms were: take a server with no activity and a table that's not in the buffer pool. Run a query that reads the whole table and observe that r_engine_stats.pages_read_count shows about 2% of the table was read. Who reads the rest? The cause was that page prefetching done inside InnoDB was not counted. This counts page prefetch requests made in buf_read_ahead_random() and buf_read_ahead_linear() and makes them visible in: - ANALYZE: r_engine_stats.pages_prefetch_read_count - Slow Query Log: Pages_prefetched: This patch intentionally doesn't attempt to count the time to read the prefetched pages: * there's no obvious place where one can do it * prefetch reads may be done in parallel (right?), it is not clear how to count the time in this case.
2024-05-27 17:00:12 +03:00
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Pages_accessed: \d+ Pages_read: \d+ Pages_prefetched: \d+ Pages_updated: \d+ Old_rows_read: \d+$ expected_matches: 2
Fix the testcase for MDEV-31558: log_slow_verbosity_innodb log_slow_innodb.test sets "log_slow_verbosity_innodb_expected_matches" in include/log_slow_grep.inc: - Fix a typo: take value from log_slow_*VERBOSITY*_innodb_expected_matches - Add a missing "--source include/log_grep.inc" - two-line search patterns do not work, search for each line individually.
2024-06-21 10:52:09 +03:00
[log_grep.inc] found expected match count: 2
[log_grep.inc] file: log_slow_innodb-verbosity_1 pattern: ^# Pages_read_time: \d+\.\d+ Engine_time: \d+\.\d+$ expected_matches: 2
[log_grep.inc] found expected match count: 2
MDEV-31558 Add InnoDB engine information to the slow query log The new statistics is enabled by adding the "engine", "innodb" or "full" option to --log-slow-verbosity Example output: # Pages_accessed: 184 Pages_read: 95 Pages_updated: 0 Old_rows_read: 1 # Pages_read_time: 17.0204 Engine_time: 248.1297 Page_read_time is time doing physical reads inside a storage engine. (Writes cannot be tracked as these are usually done in the background). Engine_time is the time spent inside the storage engine for the full duration of the read/write/update calls. It uses the same code as 'analyze statement' for calculating the time spent. The engine statistics is done with a generic interface that should be easy for any engine to use. It can also easily be extended to provide even more statistics. Currently only InnoDB has counters for Pages_% and Undo_% status. Engine_time works for all engines. Implementation details: class ha_handler_stats holds all engine stats. This class is included in handler and THD classes. While a query is running, all statistics is updated in the handler. In close_thread_tables() the statistics is added to the THD. handler::handler_stats is a pointer to where statistics should be collected. This is set to point to handler::active_handler_stats if stats are requested. If not, it is set to 0. handler_stats has also an element, 'active' that is 1 if stats are requested. This is to allow engines to avoid doing any 'if's while updating the statistics. Cloned or partition tables have the pointer set to the base table if status are requested. There is a small performance impact when using --log-slow-verbosity=engine: - All engine calls in 'select' will be timed. - IO calls for InnoDB reads will be timed. - Incrementation of counters are done on local variables and accesses are inline, so these should have very little impact. - Statistics has to be reset for each statement for the THD and each used handler. This is only 40 bytes, which should be neglectable. - For partition tables we have to loop over all partitions to update the handler_status as part of table_init(). Can be optimized in the future to only do this is log-slow-verbosity changes. For this to work we have to update handler_status for all opened partitions and also for all partitions opened in the future. Other things: - Added options 'engine' and 'full' to log-slow-verbosity. - Some of the new files in the test suite comes from Percona server, which has similar status information. - buf_page_optimistic_get(): Do not increment any counter, since we are only validating a pointer, not performing any buf_pool.page_hash lookup. - Added THD argument to save_explain_data_intern(). - Switched arguments for save_explain_.*_data() to have always THD first (generates better code as other functions also have THD first).
2023-07-07 08:38:55 +03:00
SET SESSION log_slow_verbosity='innodb,query_plan';
[slow_log_start.inc] log_slow_innodb-verbosity_2
SELECT 1;
1
1
[log_slow_stop.inc] log_slow_innodb-verbosity_2
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Thread_id: .+ Schema: .+ QC_hit: (Yes|No)$ expected_matches: 2
[log_grep.inc] found expected match count: 2
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Query_time: \d+\.\d+ Lock_time: \d+\.\d+ Rows_sent: \d+ Rows_examined: \d+$ expected_matches: 2
[log_grep.inc] found expected match count: 2
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Rows_affected: \d+ Bytes_sent: \d+$ expected_matches: 2
[log_grep.inc] found expected match count: 2
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Full_scan: (Yes|No) Full_join: (Yes|No) Tmp_table: (Yes|No) Tmp_table_on_disk: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Filesort: (Yes|No) Filesort_on_disk: (Yes|No) Merge_passes: \d+\ Priority_queue: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Filesort: (Yes|No) Filesort_on_disk: (Yes|No) Merge_passes: \d+\ Priority_queue: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Tmp_tables: \d+ Tmp_disk_tables: \d+$
[log_grep.inc] lines: 0
MDEV-34190: r_engine_stats.pages_read_count is unrealistically low The symptoms were: take a server with no activity and a table that's not in the buffer pool. Run a query that reads the whole table and observe that r_engine_stats.pages_read_count shows about 2% of the table was read. Who reads the rest? The cause was that page prefetching done inside InnoDB was not counted. This counts page prefetch requests made in buf_read_ahead_random() and buf_read_ahead_linear() and makes them visible in: - ANALYZE: r_engine_stats.pages_prefetch_read_count - Slow Query Log: Pages_prefetched: This patch intentionally doesn't attempt to count the time to read the prefetched pages: * there's no obvious place where one can do it * prefetch reads may be done in parallel (right?), it is not clear how to count the time in this case.
2024-05-27 17:00:12 +03:00
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Pages_accessed: \d+ Pages_read: \d+ Pages_prefetched: \d+ Pages_updated: \d+ Old_rows_read: \d+$
Fix the testcase for MDEV-31558: log_slow_verbosity_innodb log_slow_innodb.test sets "log_slow_verbosity_innodb_expected_matches" in include/log_slow_grep.inc: - Fix a typo: take value from log_slow_*VERBOSITY*_innodb_expected_matches - Add a missing "--source include/log_grep.inc" - two-line search patterns do not work, search for each line individually.
2024-06-21 10:52:09 +03:00
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_2 pattern: ^# Pages_read_time: \d+\.\d+ Engine_time: \d+\.\d+$
[log_grep.inc] lines: 0
MDEV-31558 Add InnoDB engine information to the slow query log The new statistics is enabled by adding the "engine", "innodb" or "full" option to --log-slow-verbosity Example output: # Pages_accessed: 184 Pages_read: 95 Pages_updated: 0 Old_rows_read: 1 # Pages_read_time: 17.0204 Engine_time: 248.1297 Page_read_time is time doing physical reads inside a storage engine. (Writes cannot be tracked as these are usually done in the background). Engine_time is the time spent inside the storage engine for the full duration of the read/write/update calls. It uses the same code as 'analyze statement' for calculating the time spent. The engine statistics is done with a generic interface that should be easy for any engine to use. It can also easily be extended to provide even more statistics. Currently only InnoDB has counters for Pages_% and Undo_% status. Engine_time works for all engines. Implementation details: class ha_handler_stats holds all engine stats. This class is included in handler and THD classes. While a query is running, all statistics is updated in the handler. In close_thread_tables() the statistics is added to the THD. handler::handler_stats is a pointer to where statistics should be collected. This is set to point to handler::active_handler_stats if stats are requested. If not, it is set to 0. handler_stats has also an element, 'active' that is 1 if stats are requested. This is to allow engines to avoid doing any 'if's while updating the statistics. Cloned or partition tables have the pointer set to the base table if status are requested. There is a small performance impact when using --log-slow-verbosity=engine: - All engine calls in 'select' will be timed. - IO calls for InnoDB reads will be timed. - Incrementation of counters are done on local variables and accesses are inline, so these should have very little impact. - Statistics has to be reset for each statement for the THD and each used handler. This is only 40 bytes, which should be neglectable. - For partition tables we have to loop over all partitions to update the handler_status as part of table_init(). Can be optimized in the future to only do this is log-slow-verbosity changes. For this to work we have to update handler_status for all opened partitions and also for all partitions opened in the future. Other things: - Added options 'engine' and 'full' to log-slow-verbosity. - Some of the new files in the test suite comes from Percona server, which has similar status information. - buf_page_optimistic_get(): Do not increment any counter, since we are only validating a pointer, not performing any buf_pool.page_hash lookup. - Added THD argument to save_explain_data_intern(). - Switched arguments for save_explain_.*_data() to have always THD first (generates better code as other functions also have THD first).
2023-07-07 08:38:55 +03:00
SET SESSION log_slow_verbosity='query_plan';
[log_slow_stop.inc] log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000)
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Thread_id: .+ Schema: .+ QC_hit: (Yes|No)$ expected_matches: 2
[log_grep.inc] found expected match count: 2
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Query_time: \d+\.\d+ Lock_time: \d+\.\d+ Rows_sent: \d+ Rows_examined: \d+$ expected_matches: 2
[log_grep.inc] found expected match count: 2
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Rows_affected: \d+ Bytes_sent: \d+$ expected_matches: 2
[log_grep.inc] found expected match count: 2
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Full_scan: (Yes|No) Full_join: (Yes|No) Tmp_table: (Yes|No) Tmp_table_on_disk: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Filesort: (Yes|No) Filesort_on_disk: (Yes|No) Merge_passes: \d+\ Priority_queue: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Filesort: (Yes|No) Filesort_on_disk: (Yes|No) Merge_passes: \d+\ Priority_queue: (Yes|No)$
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Tmp_tables: \d+ Tmp_disk_tables: \d+$
[log_grep.inc] lines: 0
Fix the testcase for MDEV-31558: log_slow_verbosity_innodb log_slow_innodb.test sets "log_slow_verbosity_innodb_expected_matches" in include/log_slow_grep.inc: - Fix a typo: take value from log_slow_*VERBOSITY*_innodb_expected_matches - Add a missing "--source include/log_grep.inc" - two-line search patterns do not work, search for each line individually.
2024-06-21 10:52:09 +03:00
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
MDEV-34190: r_engine_stats.pages_read_count is unrealistically low The symptoms were: take a server with no activity and a table that's not in the buffer pool. Run a query that reads the whole table and observe that r_engine_stats.pages_read_count shows about 2% of the table was read. Who reads the rest? The cause was that page prefetching done inside InnoDB was not counted. This counts page prefetch requests made in buf_read_ahead_random() and buf_read_ahead_linear() and makes them visible in: - ANALYZE: r_engine_stats.pages_prefetch_read_count - Slow Query Log: Pages_prefetched: This patch intentionally doesn't attempt to count the time to read the prefetched pages: * there's no obvious place where one can do it * prefetch reads may be done in parallel (right?), it is not clear how to count the time in this case.
2024-05-27 17:00:12 +03:00
INSERT INTO t1 VALUE(1000) pattern: ^# Pages_accessed: \d+ Pages_read: \d+ Pages_prefetched: \d+ Pages_updated: \d+ Old_rows_read: \d+$
Fix the testcase for MDEV-31558: log_slow_verbosity_innodb log_slow_innodb.test sets "log_slow_verbosity_innodb_expected_matches" in include/log_slow_grep.inc: - Fix a typo: take value from log_slow_*VERBOSITY*_innodb_expected_matches - Add a missing "--source include/log_grep.inc" - two-line search patterns do not work, search for each line individually.
2024-06-21 10:52:09 +03:00
[log_grep.inc] lines: 0
[log_grep.inc] file: log_slow_innodb-verbosity_3
--source include/log_slow_start.inc
INSERT INTO t1 VALUE(1000) pattern: ^# Pages_read_time: \d+\.\d+ Engine_time: \d+\.\d+$
[log_grep.inc] lines: 0
MDEV-31558 Add InnoDB engine information to the slow query log The new statistics is enabled by adding the "engine", "innodb" or "full" option to --log-slow-verbosity Example output: # Pages_accessed: 184 Pages_read: 95 Pages_updated: 0 Old_rows_read: 1 # Pages_read_time: 17.0204 Engine_time: 248.1297 Page_read_time is time doing physical reads inside a storage engine. (Writes cannot be tracked as these are usually done in the background). Engine_time is the time spent inside the storage engine for the full duration of the read/write/update calls. It uses the same code as 'analyze statement' for calculating the time spent. The engine statistics is done with a generic interface that should be easy for any engine to use. It can also easily be extended to provide even more statistics. Currently only InnoDB has counters for Pages_% and Undo_% status. Engine_time works for all engines. Implementation details: class ha_handler_stats holds all engine stats. This class is included in handler and THD classes. While a query is running, all statistics is updated in the handler. In close_thread_tables() the statistics is added to the THD. handler::handler_stats is a pointer to where statistics should be collected. This is set to point to handler::active_handler_stats if stats are requested. If not, it is set to 0. handler_stats has also an element, 'active' that is 1 if stats are requested. This is to allow engines to avoid doing any 'if's while updating the statistics. Cloned or partition tables have the pointer set to the base table if status are requested. There is a small performance impact when using --log-slow-verbosity=engine: - All engine calls in 'select' will be timed. - IO calls for InnoDB reads will be timed. - Incrementation of counters are done on local variables and accesses are inline, so these should have very little impact. - Statistics has to be reset for each statement for the THD and each used handler. This is only 40 bytes, which should be neglectable. - For partition tables we have to loop over all partitions to update the handler_status as part of table_init(). Can be optimized in the future to only do this is log-slow-verbosity changes. For this to work we have to update handler_status for all opened partitions and also for all partitions opened in the future. Other things: - Added options 'engine' and 'full' to log-slow-verbosity. - Some of the new files in the test suite comes from Percona server, which has similar status information. - buf_page_optimistic_get(): Do not increment any counter, since we are only validating a pointer, not performing any buf_pool.page_hash lookup. - Added THD argument to save_explain_data_intern(). - Switched arguments for save_explain_.*_data() to have always THD first (generates better code as other functions also have THD first).
2023-07-07 08:38:55 +03:00
DROP TABLE t1;
Reference in a new issue Copy permalink