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:
None 
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 8:33] zhai weixiang
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.
[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.