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
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