| Bug #75231 | records are not purged after a delete operation | ||
|---|---|---|---|
| Submitted: | 16 Dec 2014 8:33 | Modified: | 13 Jan 2015 21:00 |
| Reporter: | zhai weixiang (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.6, 5.7, 5.7.6 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Triage: | Needs Triage: D3 (Medium) | ||
[16 Dec 2014 9:14]
zhai weixiang
It seems the purge thread is waked up ( in function trx_purge_add_update_undo_to_history ) before the transaction is completely commited ( in function trx_commit_in_memory) why not wakeup purge thread after trx_commit_in_memory ?
[19 Dec 2014 22:21]
Sveta Smirnova
Thank you for the report. I cannot repeat described behavior. I also think that your request is same as bug #70500. Please check and if you disagree provide your configuration file.
[20 Dec 2014 10:39]
zhai weixiang
Hi, Sveta. I think this is a different issue that related to purge thread rather than page cleaner thread :) Bellow is the configure file I used: [mysqld_safe] pid-file=/u01/my575/run/mysqld.pid #malloc-lib=/u01/mysql/lib/libjemalloc.so [mysql] port=13406 prompt=\\u@\\d \\r:\\m:\\s> default-character-set=utf8 no-auto-rehash skip-insecure-warning [client] port=13406 socket=/u01/my575/run/mysql.sock [mysqld] #dir basedir=/u01/my575 datadir=/u01/my575/data tmpdir=/u01/my575/tmp lc_messages_dir=/u01/my575/share log-error=/u01/my575/log/alert.log slow_query_log_file=/u01/my575/log/slow.log general_log_file=/u01/my575/log/general.log socket=/u01/my575/run/mysql.sock core-file #innodb innodb_page_cleaners = 4 innodb_doublewrite=1 innodb_stats_persistent=0 innodb_data_home_dir=/u01/my575/data innodb_log_group_home_dir=/u01/my575/data innodb_data_file_path = ibdata1:4G;ibdata2:16M:autoextend innodb_buffer_pool_size=80G innodb_buffer_pool_instances=8 innodb_log_files_in_group=4 innodb_log_file_size=1G innodb_log_buffer_size=80M innodb_flush_log_at_trx_commit=2 innodb_max_dirty_pages_pct_lwm=10 innodb_max_dirty_pages_pct=60 innodb_thread_concurrency=32 innodb_read_io_threads=8 innodb_write_io_threads=8 innodb_open_files=60000 innodb_file_format=Barracuda innodb_file_per_table=1 innodb_flush_method=O_DIRECT innodb_change_buffering=all innodb_adaptive_flushing=ON innodb_flush_neighbors=0 innodb_adaptive_hash_index=OFF innodb_old_blocks_time=1000 innodb_stats_on_metadata=ON innodb_read_ahead_threshold=0 innodb_use_native_aio=1 innodb_lock_wait_timeout=5 innodb_rollback_on_timeout=0 innodb_purge_threads=1 innodb_strict_mode=1 transaction-isolation=READ-COMMITTED innodb_disable_sort_file_cache=ON innodb_io_capacity_max=6000 innodb_io_capacity=2000 innodb_lru_scan_depth=8194 innodb_undo_tablespaces=20 metadata_locks_hash_instances=256 metadata_locks_cache_size=32768 innodb_sync_array_size=16 innodb_print_all_deadlocks innodb_checksum_algorithm=CRC32 #myisam myisam_sort_buffer_size=64M concurrent_insert=2 delayed_insert_timeout=300 #binlog log-bin=/u01/my575/log/mysql-bin server_id=3017441834 binlog_cache_size=32K max_binlog_cache_size=2G max_binlog_size=500M binlog-format=ROW sync_binlog=1000 log-slave-updates=1 expire_logs_days=0 #server port=13406 skip-name-resolve skip-ssl max_connections=21000 max_user_connections=20200 max_connect_errors=65536 max_allowed_packet=128M connect_timeout=8 net_read_timeout=30 net_write_timeout=60 back_log=1024 default-storage-engine=INNODB character-set-server=utf8 lower_case_table_names=1 skip-external-locking open_files_limit=65536 safe-user-create local-infile=1 sql_mode="STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE" performance_schema=ON performance_schema_instrument='%=ON' log_slow_admin_statements=1 long_query_time=1 slow_query_log=1 general_log=0 log_error_verbosity=3 query_cache_type=0 query_cache_limit=1M query_cache_min_res_unit=1K table_definition_cache=2000 table_open_cache_instances = 128 table_open_cache=16000 thread_stack=512K thread_cache_size=256 read_rnd_buffer_size=128K sort_buffer_size=256K join_buffer_size=128K read_buffer_size=128K # optimizer eq_range_index_dive_limit=200 # default is 10 #replication master-info-file=/u01/my575/log/master.info relay-log=/u01/my575/log/relaylog relay_log_info_file=/u01/my575/log/relay-log.info relay-log-index=/u01/my575/log/mysqld-relay-bin.index slave_load_tmpdir=/u01/my575/tmp slave_type_conversions="ALL_NON_LOSSY" slave_net_timeout=4 skip-slave-start sync_master_info=1000 sync_relay_log_info=1000 rpl_stop_slave_timeout=300 slave_checkpoint_group=1024 slave_checkpoint_period=300 slave_parallel_workers=8 slave_pending_jobs_size_max=1073741824 slave_rows_search_algorithms='TABLE_SCAN,INDEX_SCAN,HASH_SCAN' slave_sql_verify_checksum=OFF master_verify_checksum=OFF gtid_mode=OFF enforce_gtid_consistency=OFF master_info_repository=TABLE relay_log_info_repository=TABLE
[20 Dec 2014 10:47]
zhai weixiang
I can always repeat this issue on MySQL 5.7.5:
mysql> select @@version;
+----------------------+
| @@version |
+----------------------+
| 5.7.5-m15-tb2014-log |
+----------------------+
1 row in set (0.00 sec)
mysql> select count(*) from sbtest1;
+----------+
| count(*) |
+----------+
| 999999 |
+----------+
1 row in set (0.18 sec)
mysql> show table status like 'sbtest1'\G
*************************** 1. row ***************************
Name: sbtest1
Engine: InnoDB
Version: 10
Row_format: Compact
Rows: 1000109
Avg_row_length: 225
Data_length: 225132544
Max_data_length: 0
Index_length: 20496384
Data_free: 4194304
Auto_increment: NULL
Create_time: 2014-12-16 16:17:10
Update_time: 2014-12-20 18:43:05
Check_time: NULL
Collation: utf8_general_ci
Checksum: NULL
Create_options: max_rows=1000000
Comment:
1 row in set (0.00 sec)
mysql> delete from sbtest1;
Query OK, 999999 rows affected (18.95 sec)
mysql> show table status like 'sbtest1'\G
*************************** 1. row ***************************
Name: sbtest1
Engine: InnoDB
Version: 10
Row_format: Compact
Rows: 1000109
Avg_row_length: 225
Data_length: 225132544
Max_data_length: 0
Index_length: 20496384
Data_free: 4194304
Auto_increment: NULL
Create_time: 2014-12-16 16:17:10
Update_time: 2014-12-20 18:45:17
Check_time: NULL
Collation: utf8_general_ci
Checksum: NULL
Create_options: max_rows=1000000
Comment:
1 row in set (0.00 sec)
mysql> select count(*) from sbtest1;
+----------+
| count(*) |
+----------+
| 0 |
+----------+
1 row in set (0.11 sec)
mysql> show table status like 'sbtest1'\G
*************************** 1. row ***************************
Name: sbtest1
Engine: InnoDB
Version: 10
Row_format: Compact
Rows: 1000109
Avg_row_length: 225
Data_length: 225132544
Max_data_length: 0
Index_length: 20496384
Data_free: 4194304
Auto_increment: NULL
Create_time: 2014-12-16 16:17:10
Update_time: 2014-12-20 18:45:17
Check_time: NULL
Collation: utf8_general_ci
Checksum: NULL
Create_options: max_rows=1000000
Comment:
1 row in set (0.00 sec)
mysql> analyze table sbtest1;
+-------------+---------+----------+----------+
| Table | Op | Msg_type | Msg_text |
+-------------+---------+----------+----------+
| sb1.sbtest1 | analyze | status | OK |
+-------------+---------+----------+----------+
1 row in set (0.00 sec)
mysql> show table status like 'sbtest1'\G
*************************** 1. row ***************************
Name: sbtest1
Engine: InnoDB
Version: 10
Row_format: Compact
Rows: 1000109
Avg_row_length: 225
Data_length: 225132544
Max_data_length: 0
Index_length: 20496384
Data_free: 4194304
Auto_increment: NULL
Create_time: 2014-12-16 16:17:10
Update_time: 2014-12-20 18:45:17
Check_time: NULL
Collation: utf8_general_ci
Checksum: NULL
Create_options: max_rows=1000000
Comment:
1 row in set (0.00 sec)
mysql> update sbtest2 set k=k+1 where id = 2;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
mysql> show table status like 'sbtest1'\G
*************************** 1. row ***************************
Name: sbtest1
Engine: InnoDB
Version: 10
Row_format: Compact
Rows: 374864
Avg_row_length: 232
Data_length: 87146496
Max_data_length: 0
Index_length: 17055744
Data_free: 144703488
Auto_increment: NULL
Create_time: 2014-12-16 16:17:10
Update_time: 2014-12-20 18:45:17
Check_time: NULL
Collation: utf8_general_ci
Checksum: NULL
Create_options: max_rows=1000000
Comment:
1 row in set (0.00 sec)
mysql> show table status like 'sbtest1'\G
*************************** 1. row ***************************
Name: sbtest1
Engine: InnoDB
Version: 10
Row_format: Compact
Rows: 0
Avg_row_length: 0
Data_length: 16384
Max_data_length: 0
Index_length: 16384
Data_free: 249561088
Auto_increment: NULL
Create_time: 2014-12-16 16:17:10
Update_time: 2014-12-20 18:45:17
Check_time: NULL
Collation: utf8_general_ci
Checksum: NULL
Create_options: max_rows=1000000
Comment:
1 row in set (0.00 sec)
[13 Jan 2015 21:00]
Sveta Smirnova
Thank you for the feedback. Verified as described.
Description: Create a sysbench table, with 1,000,000 records. root@sb1 04:18:36>show table status like 'sbtest1'\G *************************** 1. row *************************** Name: sbtest1 Engine: InnoDB Version: 10 Row_format: Compact Rows: 1000109 Avg_row_length: 225 Data_length: 225132544 Max_data_length: 0 Index_length: 20496384 Data_free: 4194304 Auto_increment: NULL Create_time: 2014-12-16 16:17:10 Update_time: 2014-12-16 16:17:37 Check_time: NULL Collation: utf8_general_ci Checksum: NULL Create_options: max_rows=1000000 Comment: 1 row in set (0.00 sec) root@sb1 04:18:39>select count(*) from sbtest1; +----------+ | count(*) | +----------+ | 1000000 | +----------+ 1 row in set (0.19 sec) // delete most of records from the table. root@sb1 04:18:54>delete from sbtest1 where id <= 990000; Query OK, 990000 rows affected (18.72 sec) // so now only 10,000 records root@sb1 04:20:07>select count(*) from sbtest1; +----------+ | count(*) | +----------+ | 10000 | +----------+ 1 row in set (0.11 sec) root@sb1 04:20:33>show table status like 'sbtest1'\G *************************** 1. row *************************** Name: sbtest1 Engine: InnoDB Version: 10 Row_format: Compact Rows: 1000109 ---------- //not changed Avg_row_length: 225 Data_length: 225132544 Max_data_length: 0 Index_length: 20496384 Data_free: 4194304 Auto_increment: NULL Create_time: 2014-12-16 16:17:10 Update_time: 2014-12-16 16:20:07 Check_time: NULL Collation: utf8_general_ci Checksum: NULL Create_options: max_rows=1000000 Comment: 1 row in set (0.00 sec) // let's sleep for a while... root@sb1 04:20:39>select sleep(10); +-----------+ | sleep(10) | +-----------+ | 0 | +-----------+ 1 row in set (10.00 sec) root@sb1 04:21:17>show table status like 'sbtest1'\G *************************** 1. row *************************** Name: sbtest1 Engine: InnoDB Version: 10 Row_format: Compact Rows: 1000109 -----------------// still not changed Avg_row_length: 225 Data_length: 225132544 Max_data_length: 0 Index_length: 20496384 Data_free: 4194304 Auto_increment: NULL Create_time: 2014-12-16 16:17:10 Update_time: 2014-12-16 16:20:07 Check_time: NULL Collation: utf8_general_ci Checksum: NULL Create_options: max_rows=1000000 Comment: 1 row in set (0.00 sec) //Do some other work to make the purge thread active: root@sb1 04:21:28>update sbtest2 set k = k + 1 where id = 2; Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0 root@sb1 04:22:08>show table status like 'sbtest1'\G *************************** 1. row *************************** Name: sbtest1 Engine: InnoDB Version: 10 Row_format: Compact Rows: 223316 ----------------// purge thread started to purge the del-marked record Avg_row_length: 239 Data_length: 53542912 Max_data_length: 0 Index_length: 17989632 Data_free: 177209344 Auto_increment: NULL Create_time: 2014-12-16 16:17:10 Update_time: 2014-12-16 16:20:07 Check_time: NULL Collation: utf8_general_ci Checksum: NULL Create_options: max_rows=1000000 Comment: 1 row in set (0.00 sec) This problem happened on a read only instance, and I deleted most records from one table Workaround: A followed DML can make purge thread active to purge the record. How to repeat: described above. Suggested fix: Still debug the code.