| Bug #112964 | SELECT COUNT is slow with O_DIRECT | ||
|---|---|---|---|
| Submitted: | 4 Nov 2023 1:54 | Modified: | 6 Nov 2023 6:47 |
| Reporter: | Agustín G | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S5 (Performance) |
| Version: | 8.0, 8.0.35 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[6 Nov 2023 6:47]
MySQL Verification Team
Hello Agustín G, Thank you for the report and feedback. regards, Umesh
[6 Nov 2023 7:09]
MySQL Verification Team
Test results - 8.0.11+ results
Attachment: 112964_8.0.11_8.0.34_8.0.35.results (application/octet-stream, text), 33.21 KiB.
[15 Nov 2023 6:56]
huahua xu
The innodb would not implement secondary index parallel scan , and forces use of cluster index.
```
int records_from_index(ha_rows *num_rows, uint) override {
/* Force use of cluster index until we implement sec index parallel scan. */
return ha_innobase::records(num_rows);
}
```
[3 Jun 2024 11:49]
Rahul Sisondia
Posted by developer: Hello Agustín G, Thank you for reporting this bug. I see there were two problems reported. (1) SELECT COUNT(*) was not using secondary index for index scan even though Optimizer was hinting it. This issue is fixed in 8.0.37 https://bugs.mysql.com/bug.php?id=112767 . (2) There was a co-relation reported that if innodb uses --innodb_flush_method=O_DIRECT then query performance dips compared to when it uses the --innodb_flush_method=fsync. To delve into the second issue, I performed some experiments with on a machine that has SSD `INTEL SSDSC2BA800G4` with "Write cache" and "Look-ahead" enabled. I used the latest commit from mysql-8.0 branch(8.0.38 in progress). I prepared larger table with 536M records. I did not notice performance impact on the query reported in the bug by changing the innodb_flush_method. I believe this is expected since we are trying to scan the pages and relying on the buffer pool as a cache. Therefore, I believe the issues reported in this bug are addressed hence it could be resolved. You may verify it at your end on the latest released version 8.0.37. I kept default settings except --innodb_buffer_pool_size=1G. I then changed the -innodb_flush_method=fsync|O_DIRECT. Here are snippets from the my experiments. ********************************** innodb_flush_method=fsync ********************************** (root@localhost:15000) {8.0.38} [count_example]> SELECT NOW(); +---------------------+ | NOW() | +---------------------+ | 2024-06-03 12:01:14 | +---------------------+ 1 row in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SELECT @@VERSION; +-----------+ | @@VERSION | +-----------+ | 8.0.38 | +-----------+ 1 row in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH TABLE performance_schema.file_instances; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH TABLE performance_schema.file_summary_by_event_name; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH TABLE performance_schema.file_summary_by_instance; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH STATUS; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SET PROFILING = ON; Query OK, 0 rows affected, 1 warning (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_buffer_pool%'; +-------------------------------------+----------------+ | Variable_name | Value | +-------------------------------------+----------------+ | innodb_buffer_pool_chunk_size | 134217728 | | innodb_buffer_pool_dump_at_shutdown | ON | | innodb_buffer_pool_dump_now | OFF | | innodb_buffer_pool_dump_pct | 25 | | innodb_buffer_pool_filename | ib_buffer_pool | | innodb_buffer_pool_in_core_file | ON | | innodb_buffer_pool_instances | 1 | | innodb_buffer_pool_load_abort | OFF | | innodb_buffer_pool_load_at_startup | OFF | | innodb_buffer_pool_load_now | OFF | | innodb_buffer_pool_size | 134217728 | +-------------------------------------+----------------+ 11 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_log_file_size'; +----------------------+----------+ | Variable_name | Value | +----------------------+----------+ | innodb_log_file_size | 50331648 | +----------------------+----------+ 1 row in set (0.01 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_flush_%'; +--------------------------------+-------+ | Variable_name | Value | +--------------------------------+-------+ | innodb_flush_log_at_timeout | 1 | | innodb_flush_log_at_trx_commit | 1 | | innodb_flush_method | fsync | | innodb_flush_neighbors | 0 | | innodb_flush_sync | ON | | innodb_flushing_avg_loops | 30 | +--------------------------------+-------+ 6 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_io_capacity'; +--------------------+-------+ | Variable_name | Value | +--------------------+-------+ | innodb_io_capacity | 200 | +--------------------+-------+ 1 row in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE '%_io_threads'; +-------------------------+-------+ | Variable_name | Value | +-------------------------+-------+ | innodb_read_io_threads | 4 | | innodb_write_io_threads | 4 | +-------------------------+-------+ 2 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'query_cache%'; Empty set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'handler%'; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Handler_commit | 3 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 46 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 0 | | Handler_read_key | 12 | | Handler_read_last | 0 | | Handler_read_next | 4 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 3969 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 21 | +----------------------------+-------+ 18 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'Innodb_pages_%'; +----------------------+-------+ | Variable_name | Value | +----------------------+-------+ | Innodb_pages_created | 143 | | Innodb_pages_read | 738 | | Innodb_pages_written | 188 | +----------------------+-------+ 3 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> explain SELECT COUNT(*) FROM test; +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+-----------+----------+-------------+ | id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra | +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+-----------+----------+-------------+ | 1 | SIMPLE | test | NULL | index | NULL | small_field_key | 1 | NULL | 500520006 | 100.00 | Using index | +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+-----------+----------+-------------+ 1 row in set, 1 warning (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SELECT COUNT(*) FROM test; +-----------+ | COUNT(*) | +-----------+ | 536870944 | +-----------+ 1 row in set (1 min 19.98 sec) (root@localhost:15000) {8.0.38} [count_example]> (root@localhost:15000) {8.0.38} [count_example]> SHOW PROFILES; +----------+-------------+--------------------------------------------+ | Query_ID | Duration | Query | +----------+-------------+--------------------------------------------+ | 1 | 0.00297125 | SHOW VARIABLES LIKE 'innodb_buffer_pool%' | | 2 | 0.00119600 | SHOW VARIABLES LIKE 'innodb_log_file_size' | | 3 | 0.00102300 | SHOW VARIABLES LIKE 'innodb_flush_%' | | 4 | 0.00100525 | SHOW VARIABLES LIKE 'innodb_io_capacity' | | 5 | 0.00108350 | SHOW VARIABLES LIKE '%_io_threads' | | 6 | 0.00100100 | SHOW VARIABLES LIKE 'query_cache%' | | 7 | 0.00141050 | SHOW SESSION STATUS LIKE 'handler%' | | 8 | 0.00057550 | SHOW SESSION STATUS LIKE 'Innodb_pages_%' | | 9 | 0.00016300 | explain SELECT COUNT(*) FROM test | | 10 | 79.97431225 | SELECT COUNT(*) FROM test | +----------+-------------+--------------------------------------------+ 10 rows in set, 1 warning (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> select * from sys.io_global_by_file_by_bytes where count_read>0 or count_write>0; +--------------------------------------+------------+------------+------------+-------------+---------------+------------+------------+-----------+ | file | count_read | total_read | avg_read | count_write | total_written | avg_write | total | write_pct | +--------------------------------------+------------+------------+------------+-------------+---------------+------------+------------+-----------+ | @@datadir/count_example/test.ibd | 347473 | 5.30 GiB | 16.00 KiB | 0 | 0 bytes | 0 bytes | 5.30 GiB | 0.00 | | @@datadir/ibtmp1 | 0 | 0 bytes | 0 bytes | 143 | 14.05 MiB | 100.59 KiB | 14.05 MiB | 100.00 | | @@datadir/#ib_16384_1.dblwr | 1 | 8.19 MiB | 8.19 MiB | 0 | 0 bytes | 0 bytes | 8.19 MiB | 0.00 | | @@datadir/mysql.ibd | 308 | 4.86 MiB | 16.16 KiB | 32 | 512.00 KiB | 16.00 KiB | 5.36 MiB | 9.33 | | @@datadir/undo_002 | 327 | 5.16 MiB | 16.15 KiB | 8 | 128.00 KiB | 16.00 KiB | 5.28 MiB | 2.37 | | @@datadir/undo_001 | 144 | 2.30 MiB | 16.33 KiB | 6 | 96.00 KiB | 16.00 KiB | 2.39 MiB | 3.92 | | @@datadir/#ib_16384_0.dblwr | 1 | 192.00 KiB | 192.00 KiB | 15 | 768.00 KiB | 51.20 KiB | 960.00 KiB | 80.00 | | @@basedir/share/english/errmsg.sys | 3 | 378.25 KiB | 126.08 KiB | 0 | 0 bytes | 0 bytes | 378.25 KiB | 0.00 | | @@datadir/ibdata1 | 10 | 208.00 KiB | 20.80 KiB | 2 | 32.00 KiB | 16.00 KiB | 240.00 KiB | 13.33 | | @@datadir/#innodb_redo/#ib_redo46128 | 6 | 66.50 KiB | 11.08 KiB | 32 | 84.00 KiB | 2.62 KiB | 150.50 KiB | 55.81 | | @@datadir/#innodb_temp/temp_1.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_2.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_3.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_4.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_5.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_6.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_7.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_8.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_9.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_10.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/auto.cnf | 3 | 56 bytes | 18 bytes | 0 | 0 bytes | 0 bytes | 56 bytes | 0.00 | | @@basedir/icudt73l.lnk | 1 | 32 bytes | 32 bytes | 0 | 0 bytes | 0 bytes | 32 bytes | 0.00 | | @@datadir/tetra02.pid | 0 | 0 bytes | 0 bytes | 1 | 6 bytes | 6 bytes | 6 bytes | 100.00 | +--------------------------------------+------------+------------+------------+-------------+---------------+------------+------------+-----------+ 23 rows in set (0.02 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'handler%'; +----------------------------+-----------+ | Variable_name | Value | +----------------------------+-----------+ | Handler_commit | 39 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 294 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 1 | | Handler_read_key | 148 | | Handler_read_last | 0 | | Handler_read_next | 536871258 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 4025 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 21 | +----------------------------+-----------+ 18 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'Innodb_pages_%'; +----------------------+--------+ | Variable_name | Value | +----------------------+--------+ | Innodb_pages_created | 143 | | Innodb_pages_read | 348256 | | Innodb_pages_written | 189 | +----------------------+--------+ 3 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SELECT COUNT(*) FROM test; +-----------+ | COUNT(*) | +-----------+ | 536870944 | +-----------+ 1 row in set (1 min 19.99 sec) ********************************** innodb_flush_method=O_DIRECT ********************************** (root@localhost:15000) {8.0.38} [count_example]> SELECT NOW(); +---------------------+ | NOW() | +---------------------+ | 2024-06-03 11:55:00 | +---------------------+ 1 row in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SELECT @@VERSION; +-----------+ | @@VERSION | +-----------+ | 8.0.38 | +-----------+ 1 row in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH TABLE performance_schema.file_instances; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH TABLE performance_schema.file_summary_by_event_name; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH TABLE performance_schema.file_summary_by_instance; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> FLUSH STATUS; Query OK, 0 rows affected (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SET PROFILING = ON; Query OK, 0 rows affected, 1 warning (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_buffer_pool%'; +-------------------------------------+----------------+ | Variable_name | Value | +-------------------------------------+----------------+ | innodb_buffer_pool_chunk_size | 134217728 | | innodb_buffer_pool_dump_at_shutdown | ON | | innodb_buffer_pool_dump_now | OFF | | innodb_buffer_pool_dump_pct | 25 | | innodb_buffer_pool_filename | ib_buffer_pool | | innodb_buffer_pool_in_core_file | ON | | innodb_buffer_pool_instances | 1 | | innodb_buffer_pool_load_abort | OFF | | innodb_buffer_pool_load_at_startup | OFF | | innodb_buffer_pool_load_now | OFF | | innodb_buffer_pool_size | 134217728 | +-------------------------------------+----------------+ 11 rows in set (0.01 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_log_file_size'; +----------------------+----------+ | Variable_name | Value | +----------------------+----------+ | innodb_log_file_size | 50331648 | +----------------------+----------+ 1 row in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_flush_%'; +--------------------------------+----------+ | Variable_name | Value | +--------------------------------+----------+ | innodb_flush_log_at_timeout | 1 | | innodb_flush_log_at_trx_commit | 1 | | innodb_flush_method | O_DIRECT | | innodb_flush_neighbors | 0 | | innodb_flush_sync | ON | | innodb_flushing_avg_loops | 30 | +--------------------------------+----------+ 6 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'innodb_io_capacity'; +--------------------+-------+ | Variable_name | Value | +--------------------+-------+ | innodb_io_capacity | 200 | +--------------------+-------+ 1 row in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE '%_io_threads'; +-------------------------+-------+ | Variable_name | Value | +-------------------------+-------+ | innodb_read_io_threads | 4 | | innodb_write_io_threads | 4 | +-------------------------+-------+ 2 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW VARIABLES LIKE 'query_cache%'; Empty set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'handler%'; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Handler_commit | 3 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 46 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 0 | | Handler_read_key | 12 | | Handler_read_last | 0 | | Handler_read_next | 4 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 3969 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 21 | +----------------------------+-------+ 18 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'Innodb_pages_%'; +----------------------+-------+ | Variable_name | Value | +----------------------+-------+ | Innodb_pages_created | 143 | | Innodb_pages_read | 734 | | Innodb_pages_written | 187 | +----------------------+-------+ 3 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> explain SELECT COUNT(*) FROM test; +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+-----------+----------+-------------+ | id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra | +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+-----------+----------+-------------+ | 1 | SIMPLE | test | NULL | index | NULL | small_field_key | 1 | NULL | 500520006 | 100.00 | Using index | +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+-----------+----------+-------------+ 1 row in set, 1 warning (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SELECT COUNT(*) FROM test; +-----------+ | COUNT(*) | +-----------+ | 536870944 | +-----------+ 1 row in set (1 min 17.81 sec) (root@localhost:15000) {8.0.38} [count_example]> (root@localhost:15000) {8.0.38} [count_example]> SHOW PROFILES; +----------+-------------+--------------------------------------------+ | Query_ID | Duration | Query | +----------+-------------+--------------------------------------------+ | 1 | 0.00319000 | SHOW VARIABLES LIKE 'innodb_buffer_pool%' | | 2 | 0.00120450 | SHOW VARIABLES LIKE 'innodb_log_file_size' | | 3 | 0.00102925 | SHOW VARIABLES LIKE 'innodb_flush_%' | | 4 | 0.00097550 | SHOW VARIABLES LIKE 'innodb_io_capacity' | | 5 | 0.00110400 | SHOW VARIABLES LIKE '%_io_threads' | | 6 | 0.00098750 | SHOW VARIABLES LIKE 'query_cache%' | | 7 | 0.00127150 | SHOW SESSION STATUS LIKE 'handler%' | | 8 | 0.00053600 | SHOW SESSION STATUS LIKE 'Innodb_pages_%' | | 9 | 0.00016150 | explain SELECT COUNT(*) FROM test | | 10 | 77.80401325 | SELECT COUNT(*) FROM test | +----------+-------------+--------------------------------------------+ 10 rows in set, 1 warning (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> select * from sys.io_global_by_file_by_bytes where count_read>0 or count_write>0; +--------------------------------------+------------+------------+------------+-------------+---------------+------------+------------+-----------+ | file | count_read | total_read | avg_read | count_write | total_written | avg_write | total | write_pct | +--------------------------------------+------------+------------+------------+-------------+---------------+------------+------------+-----------+ | @@datadir/count_example/test.ibd | 347476 | 5.30 GiB | 16.00 KiB | 0 | 0 bytes | 0 bytes | 5.30 GiB | 0.00 | | @@datadir/ibtmp1 | 0 | 0 bytes | 0 bytes | 143 | 14.05 MiB | 100.59 KiB | 14.05 MiB | 100.00 | | @@datadir/#ib_16384_1.dblwr | 1 | 8.19 MiB | 8.19 MiB | 0 | 0 bytes | 0 bytes | 8.19 MiB | 0.00 | | @@datadir/mysql.ibd | 304 | 4.80 MiB | 16.16 KiB | 32 | 512.00 KiB | 16.00 KiB | 5.30 MiB | 9.44 | | @@datadir/undo_002 | 326 | 5.14 MiB | 16.15 KiB | 7 | 112.00 KiB | 16.00 KiB | 5.25 MiB | 2.08 | | @@datadir/undo_001 | 145 | 2.31 MiB | 16.33 KiB | 6 | 96.00 KiB | 16.00 KiB | 2.41 MiB | 3.90 | | @@datadir/#ib_16384_0.dblwr | 1 | 192.00 KiB | 192.00 KiB | 14 | 752.00 KiB | 53.71 KiB | 944.00 KiB | 79.66 | | @@basedir/share/english/errmsg.sys | 3 | 378.25 KiB | 126.08 KiB | 0 | 0 bytes | 0 bytes | 378.25 KiB | 0.00 | | @@datadir/ibdata1 | 10 | 208.00 KiB | 20.80 KiB | 2 | 32.00 KiB | 16.00 KiB | 240.00 KiB | 13.33 | | @@datadir/#innodb_redo/#ib_redo46128 | 6 | 66.50 KiB | 11.08 KiB | 33 | 84.50 KiB | 2.56 KiB | 151.00 KiB | 55.96 | | @@datadir/#innodb_temp/temp_1.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_2.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_3.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_4.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_5.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_6.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_7.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_8.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_9.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/#innodb_temp/temp_10.ibt | 0 | 0 bytes | 0 bytes | 2 | 32.00 KiB | 16.00 KiB | 32.00 KiB | 100.00 | | @@datadir/auto.cnf | 3 | 56 bytes | 18 bytes | 0 | 0 bytes | 0 bytes | 56 bytes | 0.00 | | @@basedir/icudt73l.lnk | 1 | 32 bytes | 32 bytes | 0 | 0 bytes | 0 bytes | 32 bytes | 0.00 | | @@datadir/tetra02.pid | 0 | 0 bytes | 0 bytes | 1 | 6 bytes | 6 bytes | 6 bytes | 100.00 | +--------------------------------------+------------+------------+------------+-------------+---------------+------------+------------+-----------+ 23 rows in set (0.04 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'handler%'; +----------------------------+-----------+ | Variable_name | Value | +----------------------------+-----------+ | Handler_commit | 39 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 294 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 1 | | Handler_read_key | 148 | | Handler_read_last | 0 | | Handler_read_next | 536871258 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 4025 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 21 | +----------------------------+-----------+ 18 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SHOW SESSION STATUS LIKE 'Innodb_pages_%'; +----------------------+--------+ | Variable_name | Value | +----------------------+--------+ | Innodb_pages_created | 143 | | Innodb_pages_read | 348251 | | Innodb_pages_written | 188 | +----------------------+--------+ 3 rows in set (0.00 sec) (root@localhost:15000) {8.0.38} [count_example]> SELECT COUNT(*) FROM test; +-----------+ | COUNT(*) | +-----------+ | 536870944 | +-----------+ 1 row in set (1 min 18.45 sec)
[25 Jun 2024 17:03]
Rahul Sisondia
I missed to add an important observation in the previous comment that is set the --innodb_buffer_pool_load_at_startup=OFF while restarting the server to repeat the test runs. It is for fair comparison avoid reading the pages from the buffer pool cache.
[27 Sep 2024 9:44]
Rahul Sisondia
I realized when this situation may arise, if SELECT queries are running faster with "fsync" (buffered IO via FS cache) comparing to O_DIRECT (IO by-passing FS cache, accessing Storage directly), this is "generally" because your InnoDB BP size is too small comparing to your RAM size, and you're able to cache more data in FS cache. Which also "generally" can be easily solved by increasing BP size. Additionally to validate that "fsync" speed-up is really coming due cached data IO reads from FS cache, you can force FS cache drop before starting your tests to see the difference: execute 'sync' as "root" user. If your queries are mainly about read-only SELECTs and you haven't tuned the BP yet, then queries may run fine with "fsync". However, if you are also expecting to have some Write-intensive activity, they may hit severe penalties in such cases by not using O_DIRECT+AIO tandem.
Description: In latest MySQL 8.0.35, if we set innodb_flush_method to a non-default o-direct value (O_DIRECT or O_DIRECT_NO_FSYNC), the SELECT count query will take 10x or even more to finish. The explain shows as if the index were used, but it is not the case (although there is a secondary bug with Handler counters here that doesn't allow us to show it correctly). This is not happening if innodb_flush_method is left at default (fsync) value. It can be improved if we lower read parallelism, but still, it's like 6x of what it should be. How to repeat: ===== The following commands will not have their outputs, for brevity ===== -- CREATE NEW SCHEMA drop schema if exists count_example; create schema count_example; use count_example; -- CREATE NEW TABLE drop table if exists test; create table test ( id int unsigned not null auto_increment primary key, wide_field varchar(200) not null default 'ABCDEFGHIJKLMNOPQRSTUVWXYZ ABCDEFGHIJKLMNOPQRSTUVWXYZ ABCDEFGHIJKLMNOPQRSTUVWXYZ ABCDEFGHIJKLMNOPQRSTUVWXYZ ABCDEFGHIJKLMNOPQRSTUVWXYZ ABCDEFGHIJKLMNOPQRSTUVWXYZ', small_field boolean not null default 1, index small_field_key (small_field) ); -- CREATE PROCEDURE TO LOAD DATA -- CHANGE v_max IF LESS ROWS ARE NEEDED drop procedure if exists load_data; delimiter # create procedure load_data() begin declare v_max int default 24; declare v_counter int default 0; insert into test (small_field) values (1); while v_counter < v_max do select concat('current iter: ',v_counter,' max: ',v_max-1) as progress; insert into test (small_field) select small_field from test; set v_counter=v_counter+1; end while; end # delimiter ; -- CALL DATA LOAD PROC call load_data(); ===== We run the workload with defaults ===== mysql [localhost:24350] {msandbox} (count_example) > SELECT @@version, @@innodb_flush_method; +-----------+-----------------------+ | @@version | @@innodb_flush_method | +-----------+-----------------------+ | 8.0.35 | fsync | +-----------+-----------------------+ 1 row in set (0.00 sec) mysql [localhost:24350] {msandbox} (count_example) > SELECT @@innodb_parallel_read_threads; +--------------------------------+ | @@innodb_parallel_read_threads | +--------------------------------+ | 4 | +--------------------------------+ 1 row in set (0.00 sec) mysql [localhost:24350] {msandbox} (count_example) > FLUSH STATUS; Query OK, 0 rows affected (0.00 sec) mysql [localhost:24350] {msandbox} (count_example) > SELECT COUNT(*) FROM count_example.test; +----------+ | COUNT(*) | +----------+ | 16777216 | +----------+ 1 row in set (2.41 sec) mysql [localhost:24350] {msandbox} (count_example) > SHOW STATUS LIKE 'Handler%'; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Handler_commit | 1 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 2 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 0 | | Handler_read_key | 0 | | Handler_read_last | 0 | | Handler_read_next | 0 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 0 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 0 | +----------------------------+-------+ 18 rows in set (0.00 sec) --> The query runs in 2 seconds. However, we have no idea about the handlers (all 0). ===== We now change flush method and restart ===== echo "innodb_flush_method = O_DIRECT" >> my.sandbox.cnf ./restart ===== And run the query again ===== mysql [localhost:24350] {msandbox} (count_example) > FLUSH STATUS; Query OK, 0 rows affected (0.00 sec) mysql [localhost:24350] {msandbox} (count_example) > SELECT COUNT(*) FROM count_example.test; +----------+ | COUNT(*) | +----------+ | 16777216 | +----------+ 1 row in set (20.91 sec) mysql [localhost:24350] {msandbox} (count_example) > SHOW STATUS LIKE 'Handler%'; +----------------------------+-------+ | Variable_name | Value | +----------------------------+-------+ | Handler_commit | 1 | | Handler_delete | 0 | | Handler_discover | 0 | | Handler_external_lock | 2 | | Handler_mrr_init | 0 | | Handler_prepare | 0 | | Handler_read_first | 0 | | Handler_read_key | 0 | | Handler_read_last | 0 | | Handler_read_next | 0 | | Handler_read_prev | 0 | | Handler_read_rnd | 0 | | Handler_read_rnd_next | 0 | | Handler_rollback | 0 | | Handler_savepoint | 0 | | Handler_savepoint_rollback | 0 | | Handler_update | 0 | | Handler_write | 0 | +----------------------------+-------+ 18 rows in set (0.01 sec) ===== We try with no parallelism ===== mysql [localhost:24350] {msandbox} (count_example) > SET innodb_parallel_read_threads = 1; Query OK, 0 rows affected (0.00 sec) mysql [localhost:24350] {msandbox} (count_example) > SELECT COUNT(*) FROM count_example.test; +----------+ | COUNT(*) | +----------+ | 16777216 | +----------+ 1 row in set (12.63 sec) ===== Check the explain plan ===== mysql [localhost:24350] {msandbox} (count_example) > explain SELECT COUNT(*) FROM count_example.test; +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+----------+----------+-------------+ | id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra | +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+----------+----------+-------------+ | 1 | SIMPLE | test | NULL | index | NULL | small_field_key | 1 | NULL | 15979015 | 100.00 | Using index | +----+-------------+-------+------------+-------+---------------+-----------------+---------+------+----------+----------+-------------+ 1 row in set, 1 warning (0.00 sec) Suggested fix: MySQL should honor the EXPLAIN, and use the index it shows for the SELECT count query, which should be much faster and will require less I/O (or memory) usage. I'm not sure why the flush method is influencing so much in the result here.