mirror of
https://github.com/MariaDB/server.git
synced 2025-10-31 19:06:14 +01:00
513c827041
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.
94 lines
5.8 KiB
Text
94 lines
5.8 KiB
Text
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
|
|
[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
|
|
[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
|
|
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
|
|
[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+$
|
|
[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
|
|
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
|
|
[log_grep.inc] file: log_slow_innodb-verbosity_3
|
|
--source include/log_slow_start.inc
|
|
INSERT INTO t1 VALUE(1000) pattern: ^# Pages_accessed: \d+ Pages_read: \d+ Pages_prefetched: \d+ Pages_updated: \d+ Old_rows_read: \d+$
|
|
[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
|
|
DROP TABLE t1;
|