Bug #91517 User threads wait to reclaim redo log space,checkpoint donot to advancer
Submitted: 2 Jul 2018 9:36 Modified: 3 Jul 2018 5:49
Reporter: s a Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S2 (Serious)
Version:8.0.11 OS:Linux
Assigned to: CPU Architecture:Any

[2 Jul 2018 9:36] s a
Description:
  user threads was hung  at log_wait_for_space_in_log_file when I run the write benchmark with 6 tables,25,000,000 rows,256 clients. log checkpointer at buf_flush_wait_flushed,checkpoint  donot to advancer,checkpoint LSN no change.
with same my.cnf,mysql5.7 no hung.
  this is deadlock? --"that the oldest dirty page is latched and
    user thread, which keeps the latch, is waiting for space
    in log buffer (for log_writer writing to disk). In such
    case it would be deadlock (we can't flush the latched
    page and advance the checkpoint). We only ask for the
    checkpoint, and wait for some time."
  

  database error log(checkpont lsn donot to advancer):
2018-07-02T17:07:50.669028+08:00 0 [Warning] [MY-013060] [InnoDB] InnoDB: Log writer is waiting for checkpointer to to catch up lag: 966450176 bytes, checkpoint LSN: 975729207808
2018-07-02T17:07:50.769127+08:00 0 [Warning] [MY-013060] [InnoDB] InnoDB: Log writer is waiting for checkpointer to to catch up lag: 966450176 bytes, checkpoint LSN: 975729207808
2018-07-02T17:07:50.869226+08:00 0 [ERROR] [MY-013059] [InnoDB] InnoDB: Log writer overwriting data after checkpoint - waited too long (1 second), lag: 966450176 bytes, checkpoint LSN: 975729207808

  pstack log:
Thread 8 (Thread 0x7f6a29e4e700 (LWP 19191)):
#0  0x00007f6c699d100d in nanosleep () from /lib64/libpthread.so.0
#1  0x0000000001bcef5d in log_wait_for_space_in_log_file(log_t&, unsigned long) ()
#2  0x0000000001ca3a3c in row_upd_step(que_thr_t*) ()
#3  0x0000000001c76f35 in row_update_for_mysql_using_upd_graph ()
#4  0x0000000001c7bd50 in row_update_for_mysql(unsigned char const*, row_prebuilt_t*) ()
#5  0x0000000001b67180 in ha_innobase::update_row(unsigned char const*, unsigned char*) ()
#6  0x0000000000dbe77b in handler::ha_update_row(unsigned char const*, unsigned char*) ()
#7  0x0000000000c73c3b in Sql_cmd_update::update_single_table(THD*) ()
#8  0x0000000000c17547 in Sql_cmd_dml::execute(THD*) ()
#9  0x0000000000bcbf11 in mysql_execute_command(THD*, bool) ()
#10 0x0000000000bfa2c0 in Prepared_statement::execute(String*, bool) ()
#11 0x0000000000bfc894 in Prepared_statement::execute_loop(String*, bool) ()
#12 0x0000000000bfddd9 in mysqld_stmt_execute(THD*, Prepared_statement*, bool, unsigned long, PS_PARAM*) ()
#13 0x0000000000bd2916 in dispatch_command(THD*, COM_DATA const*, enum_server_command) ()
#14 0x0000000000bd3be9 in do_command(THD*) ()
#15 0x0000000000cbfd80 in handle_connection ()
#16 0x0000000001aa5f5f in pfs_spawn_thread ()
#17 0x00007f6c699c9aa1 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f6c67ed0bcd in clone () from /lib64/libc.so.6
Thread 7 (Thread 0x7f6a29dcd700 (LWP 19192)):
#0  0x00007f6c699d100d in nanosleep () from /lib64/libpthread.so.0
#1  0x0000000001bcef5d in log_wait_for_space_in_log_file(log_t&, unsigned long) ()
#2  0x0000000001ca3a3c in row_upd_step(que_thr_t*) ()
#3  0x0000000001c76f35 in row_update_for_mysql_using_upd_graph ()
#4  0x0000000001c7bd50 in row_update_for_mysql(unsigned char const*, row_prebuilt_t*) ()
#5  0x0000000001b6aad7 in ha_innobase::delete_row(unsigned char const*) ()
#6  0x0000000000dbe968 in handler::ha_delete_row(unsigned char const*) ()
#7  0x0000000000b909f1 in Sql_cmd_delete::delete_from_single_table(THD*) ()
#8  0x0000000000c17547 in Sql_cmd_dml::execute(THD*) ()
#9  0x0000000000bcbf11 in mysql_execute_command(THD*, bool) ()
#10 0x0000000000bfa2c0 in Prepared_statement::execute(String*, bool) ()
#11 0x0000000000bfc894 in Prepared_statement::execute_loop(String*, bool) ()
#12 0x0000000000bfddd9 in mysqld_stmt_execute(THD*, Prepared_statement*, bool, unsigned long, PS_PARAM*) ()
#13 0x0000000000bd2916 in dispatch_command(THD*, COM_DATA const*, enum_server_command) ()
#14 0x0000000000bd3be9 in do_command(THD*) ()
#15 0x0000000000cbfd80 in handle_connection ()
#16 0x0000000001aa5f5f in pfs_spawn_thread ()
#17 0x00007f6c699c9aa1 in start_thread () from /lib64/libpthread.so.0
#18 0x00007f6c67ed0bcd in clone () from /lib64/libc.so.6

How to repeat:
  
 use sysbench:
1:prepare data
/usr/local/bin/sysbench \
    oltp_read_only \
    --mysql-host=xx \
    --mysql-port=xx \
    --mysql-user=xx \
    --mysql-password=xx \
    --mysql-db=sbtest \
    --mysql-storage-engine=innodb \
    --tables=6 \
    --table_size=25000000 \
    prepare

2: /etc/init.d/mysql restart

3:warmup 600s,run
/usr/local/bin/sysbench
oltp_write_only
--mysql-host=xxx
--mysql-port=xxx
--mysql-user=xxx
--mysql-password=xxx
--mysql-db=sbtest
--mysql-storage-engine=innodb
--tables=6
--table_size=25000000
--percentile=99
--histogram=on
--report-interval=10
--report-checkpoints=10,20,30,40,50,60,70,80,90,100,150,200,250,300,350,400,450,500,550,600
--warmup-time=600
--mysql-ignore-errors=all
--events=0
--rate=0
--skip_trx=on
--threads=256
--time=600 run
 
my.cnf is:
[mysql]
prompt = \\u@\\d\\r:\\m:\\s>
no-auto-rehash

[client]
port = 3307
socket = /data/data3307/mysql//mysql.sock

[mysqld]
port = 3307
basedir = /data/mysql3307
lc-messages_dir = /data/mysql3307/share
lc-messages = en_US
datadir = /data/data3307/mysql/
tmpdir = /data/data3307/mysql-tmpdir/
log-error = /data/data3307/mysql/mysql-error.log
#max_prepared_stmt_count=32764
log_timestamps = SYSTEM
default-time-zone = '+8:00'
slow_query_log_file = /data/data3307/mysql/dianping-slow.log
general_log_file = /data/data3307/mysql/dianping-gen.log
socket = /data/data3307/mysql//mysql.sock
pid-file = /data/data3307/mysql/mysql.pid
innodb_undo_tablespaces = 6
innodb_undo_directory = /data/data3307/undo
#innodb_file_format = Barracuda
#innodb_file_format_max = Barracuda
innodb_data_home_dir = /data/data3307/mysql/
innodb_log_group_home_dir = /data/data3307/mysql/
innodb_data_file_path = ibdata1:1000M;ibdata2:1000M;ibdata3:1000M;ibdata4:100M:autoextend
innodb_buffer_pool_size = 40G
innodb_buffer_pool_instances = 8
innodb_log_files_in_group = 2
innodb_log_file_size = 512M

#innodb_log_spin_cpu_abs_lwm=0
#innodb_log_spin_cpu_pct_hwm=0
#innodb_log_wait_for_flush_spin_hwm=0

innodb_log_buffer_size = 16M
innodb_checksum_algorithm = crc32
innodb_default_row_format = DYNAMIC
internal_tmp_disk_storage_engine = innodb
innodb_fast_shutdown = 1
innodb_doublewrite = 1
innodb_flush_log_at_trx_commit = 2
innodb_flush_log_at_timeout = 1
innodb_max_dirty_pages_pct = 75
innodb_io_capacity = 200
innodb_thread_concurrency = 0
innodb_read_io_threads = 8
innodb_write_io_threads = 16
innodb-page-cleaners = 8
innodb_open_files = 60000
innodb_file_per_table = 1
innodb_flush_method = O_DIRECT
innodb_flush_neighbors = 0
innodb_change_buffering = all
innodb_adaptive_flushing = 1
innodb_old_blocks_time = 1000
innodb_use_native_aio = 1
innodb_adaptive_hash_index_parts = 32
innodb_adaptive_hash_index = OFF
lock_wait_timeout = 60
innodb_print_all_deadlocks = ON
innodb_rollback_on_timeout = 0
innodb_lock_wait_timeout = 50
innodb_buffer_pool_dump_at_shutdown = ON
innodb_buffer_pool_load_at_startup = ON
innodb_buffer_pool_dump_pct = 100
innodb_strict_mode = OFF
innodb_buffer_pool_chunk_size = 128M
max_heap_table_size = 128M
key_buffer_size = 32M
myisam_sort_buffer_size = 128M
concurrent_insert = ALWAYS
delayed_insert_timeout = 300
read_rnd_buffer_size = 128K
myisam-recover-options = default
skip-slave-start
default_authentication_plugin=mysql_native_password
relay-log = mysql-relay-bin
binlog_group_commit_sync_delay = 1000
binlog_group_commit_sync_no_delay_count = 0
slave_parallel_type = DATABASE
slave_parallel_workers = 0
slave_pending_jobs_size_max = 1G
binlog_order_commits = 1
slave_preserve_commit_order = 1
log-bin = /data/data3307/owbinlogbackup/mysql-bin
server-id = 59330621
binlog_cache_size = 1M
max_binlog_cache_size = 2G
max_binlog_size = 1024M
binlog-format = ROW
sync_binlog = 100
log-slave-updates
read_only = OFF
expire_logs_days = 7
#max_binlog_files = 0
binlog_error_action = ABORT_SERVER
default-storage-engine = INNODB
character-set-server = utf8mb4
collation_server = utf8mb4_unicode_ci
#loose-character-set-client = utf8mb4
open_files_limit = 140000
log_slow_admin_statements = 1
#log_slow_verbosity = microtime,query_plan,innodb
#log_warnings = 2
log_queries_not_using_indexes = 0
long_query_time = 0.1
slow_query_log = 1
log_slow_slave_statements = 1
#query_cache_type = 0
#query_cache_size = 256M
#query_cache_limit = 1M
#query_cache_min_res_unit = 1K
table_definition_cache = 65536
table_open_cache = 65536
thread_stack = 512K
thread_cache_size = 256
#thread_pool_size = 50
#thread_pool_stall_limit = 10
#thread_handling = pool-of-threads
#thread_pool_oversubscribe = 40
sort_buffer_size = 8M
join_buffer_size = 8M
read_buffer_size = 128K
skip-name-resolve
skip-ssl
max_connections = 20000
max_connect_errors = 65536
max_allowed_packet = 1G
connect_timeout = 8
net_read_timeout = 30
net_write_timeout = 60
slave_net_timeout = 60
back_log = 1024
innodb_stats_on_metadata = OFF
log_statements_unsafe_for_binlog = OFF
performance_schema = ON
#show_compatibility_56 = ON
relay_log_recovery = 1
relay_log_info_repository = TABLE
master_info_repository = TABLE
slave_compressed_protocol = ON
#userstat = ON
default_password_lifetime = 0
sql_mode = 'NO_ENGINE_SUBSTITUTION'
secure_file_priv = ''
local-infile = 1
event_scheduler = OFF
explicit_defaults_for_timestamp = off
#extra_port = 93306
#extra_max_connections = 10
transaction-isolation = READ-COMMITTED

[mysqld_safe]
malloc-lib = /usr/lib64/libjemalloc.so
[3 Jul 2018 5:49] Umesh Shastry
Thank you for the report.
This is most likely duplicate of Bug #90993, please see Bug #90993.

Regards,
Umesh