[MDEV-9916] Significant write performance drop after upgrading to MariaDB 10.1.13 from 10.1.12 Created: 2016-04-13  Updated: 2020-12-08  Resolved: 2016-05-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - XtraDB
Affects Version/s: 10.1.13
Fix Version/s: 10.1.14

Type: Bug Priority: Major
Reporter: Mathew Hornbeek Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 2
Labels: None
Environment:

InnoDB; Ubuntu 14.04.4 x86-64; Virtual Server


Sprint: 10.1.14

 Description   

I have reliably been able to reproduce an issue with version 10.1.13 of MariaDB wherein upgrading from 10.1.10, 10.1.11, or 10.1.12 to 10.1.13 results in a very significant drop in write performance. This became most noticeable on replication threads (we are using multi-source GTID replication) but does not appear to be limited to replication. System IOwait metrics more than doubled and stay at this high level post-upgrade. I'll dump the global variables here to give some idea of our configuration. Any help is welcomed and please let me know if there's any more information I can provide on this issue. Thanks!

SHOW GLOBAL VARIABLES:

Variable_name	Value
aria_block_size	8192
aria_checkpoint_interval	30
aria_checkpoint_log_activity	1048576
aria_encrypt_tables	OFF
aria_force_start_after_recovery_failures	0
aria_group_commit	none
aria_group_commit_interval	0
aria_log_file_size	1073741824
aria_log_purge_type	immediate
aria_max_sort_file_size	9223372036853727232
aria_page_checksum	ON
aria_pagecache_age_threshold	300
aria_pagecache_buffer_size	134217728
aria_pagecache_division_limit	100
aria_pagecache_file_hash_size	512
aria_recover	NORMAL
aria_repair_threads	1
aria_sort_buffer_size	268434432
aria_stats_method	nulls_unequal
aria_sync_log_dir	NEWFILE
aria_used_for_temp_tables	ON
auto_increment_increment	1
auto_increment_offset	1
autocommit	ON
automatic_sp_privileges	ON
back_log	900
basedir	/usr
big_tables	OFF
binlog_annotate_row_events	OFF
binlog_cache_size	32768
binlog_checksum	NONE
binlog_commit_wait_count	0
binlog_commit_wait_usec	100000
binlog_direct_non_transactional_updates	OFF
binlog_format	MIXED
binlog_optimize_thread_scheduling	ON
binlog_row_image	FULL
binlog_stmt_cache_size	32768
bulk_insert_buffer_size	8388608
character_set_client	latin1
character_set_connection	latin1
character_set_database	latin1
character_set_filesystem	binary
character_set_results	latin1
character_set_server	latin1
character_set_system	utf8
character_sets_dir	/usr/share/mysql/charsets/
collation_connection	latin1_swedish_ci
collation_database	latin1_swedish_ci
collation_server	latin1_swedish_ci
completion_type	NO_CHAIN
concurrent_insert	AUTO
connect_timeout	60
datadir	/var/lib/mysql/
date_format	%Y-%m-%d
datetime_format	%Y-%m-%d %H:%i:%s
deadlock_search_depth_long	15
deadlock_search_depth_short	4
deadlock_timeout_long	50000000
deadlock_timeout_short	10000
debug_no_thread_alarm	OFF
default_regex_flags	
default_storage_engine	InnoDB
default_tmp_storage_engine	
default_week_format	0
delay_key_write	ON
delayed_insert_limit	100
delayed_insert_timeout	300
delayed_queue_size	1000
div_precision_increment	4
encrypt_binlog	OFF
encrypt_tmp_disk_tables	OFF
encrypt_tmp_files	OFF
enforce_storage_engine	
event_scheduler	OFF
expensive_subquery_limit	100
expire_logs_days	5
explicit_defaults_for_timestamp	OFF
extra_max_connections	1
extra_port	0
flush	OFF
flush_time	0
foreign_key_checks	ON
ft_boolean_syntax	+ -><()~*:""&|
ft_max_word_len	84
ft_min_word_len	4
ft_query_expansion_limit	20
ft_stopword_file	(built-in)
general_log	OFF
general_log_file	mariadb-primary-6.log
group_concat_max_len	1024
gtid_binlog_pos	0-1001-8129428504,1-1001-194051,2-1001-24997286
gtid_binlog_state	0-1006-8127815616,0-1005-6504091164,0-1001-8129428504,1-1006-135543,1-1001-194051,2-1006-16964759,2-1001-24997286
gtid_current_pos	0-1001-8129428504,1-1001-194051,2-1001-24997286
gtid_domain_id	0
gtid_ignore_duplicates	OFF
gtid_slave_pos	0-1001-8129428506,1-1001-194051,2-1001-24997286
gtid_strict_mode	OFF
have_compress	YES
have_crypt	YES
have_dynamic_loading	YES
have_geometry	YES
have_openssl	YES
have_profiling	YES
have_query_cache	YES
have_rtree_keys	YES
have_ssl	DISABLED
have_symlink	YES
histogram_size	0
histogram_type	SINGLE_PREC_HB
host_cache_size	853
hostname	mariadb-primary-6
ignore_builtin_innodb	OFF
ignore_db_dirs	
init_connect	
init_file	
init_slave	
innodb_adaptive_flushing	ON
innodb_adaptive_flushing_lwm	10.000000
innodb_adaptive_hash_index	ON
innodb_adaptive_hash_index_partitions	1
innodb_adaptive_max_sleep_delay	150000
innodb_additional_mem_pool_size	8388608
innodb_api_bk_commit_interval	5
innodb_api_disable_rowlock	OFF
innodb_api_enable_binlog	OFF
innodb_api_enable_mdl	OFF
innodb_api_trx_level	0
innodb_autoextend_increment	64
innodb_autoinc_lock_mode	1
innodb_background_scrub_data_check_interval	3600
innodb_background_scrub_data_compressed	OFF
innodb_background_scrub_data_interval	604800
innodb_background_scrub_data_uncompressed	OFF
innodb_buf_dump_status_frequency	0
innodb_buffer_pool_dump_at_shutdown	OFF
innodb_buffer_pool_dump_now	OFF
innodb_buffer_pool_dump_pct	100
innodb_buffer_pool_filename	ib_buffer_pool
innodb_buffer_pool_instances	4
innodb_buffer_pool_load_abort	OFF
innodb_buffer_pool_load_at_startup	OFF
innodb_buffer_pool_load_now	OFF
innodb_buffer_pool_populate	OFF
innodb_buffer_pool_size	58293485568
innodb_change_buffer_max_size	25
innodb_change_buffering	all
innodb_checksum_algorithm	INNODB
innodb_checksums	ON
innodb_cleaner_lsn_age_factor	HIGH_CHECKPOINT
innodb_cmp_per_index_enabled	OFF
innodb_commit_concurrency	0
innodb_compression_algorithm	none
innodb_compression_failure_threshold_pct	5
innodb_compression_level	6
innodb_compression_pad_pct_max	50
innodb_concurrency_tickets	5000
innodb_corrupt_table_action	assert
innodb_data_file_path	ibdata1:12M:autoextend
innodb_data_home_dir	
innodb_default_encryption_key_id	1
innodb_defragment	OFF
innodb_defragment_fill_factor	0.900000
innodb_defragment_fill_factor_n_recs	20
innodb_defragment_frequency	40
innodb_defragment_n_pages	7
innodb_defragment_stats_accuracy	0
innodb_disable_sort_file_cache	OFF
innodb_disallow_writes	OFF
innodb_doublewrite	ON
innodb_empty_free_list_algorithm	BACKOFF
innodb_encrypt_log	OFF
innodb_encrypt_tables	OFF
innodb_encryption_rotate_key_age	1
innodb_encryption_rotation_iops	100
innodb_encryption_threads	0
innodb_fake_changes	OFF
innodb_fast_shutdown	1
innodb_fatal_semaphore_wait_threshold	600
innodb_file_format	Antelope
innodb_file_format_check	ON
innodb_file_format_max	Antelope
innodb_file_per_table	ON
innodb_flush_log_at_timeout	1
innodb_flush_log_at_trx_commit	2
innodb_flush_method	O_DIRECT
innodb_flush_neighbors	1
innodb_flushing_avg_loops	30
innodb_force_load_corrupted	OFF
innodb_force_primary_key	OFF
innodb_force_recovery	0
innodb_foreground_preflush	EXPONENTIAL_BACKOFF
innodb_ft_aux_table	
innodb_ft_cache_size	8000000
innodb_ft_enable_diag_print	OFF
innodb_ft_enable_stopword	ON
innodb_ft_max_token_size	84
innodb_ft_min_token_size	3
innodb_ft_num_word_optimize	2000
innodb_ft_result_cache_limit	2000000000
innodb_ft_server_stopword_table	
innodb_ft_sort_pll_degree	2
innodb_ft_total_cache_size	640000000
innodb_ft_user_stopword_table	
innodb_idle_flush_pct	100
innodb_immediate_scrub_data_uncompressed	OFF
innodb_instrument_semaphores	OFF
innodb_io_capacity	200
innodb_io_capacity_max	2000
innodb_kill_idle_transaction	0
innodb_large_prefix	OFF
innodb_lock_wait_timeout	240
innodb_locking_fake_changes	ON
innodb_locks_unsafe_for_binlog	OFF
innodb_log_arch_dir	./
innodb_log_arch_expire_sec	0
innodb_log_archive	OFF
innodb_log_block_size	512
innodb_log_buffer_size	4194304
innodb_log_checksum_algorithm	INNODB
innodb_log_compressed_pages	OFF
innodb_log_file_size	536870912
innodb_log_files_in_group	2
innodb_log_group_home_dir	./
innodb_lru_scan_depth	1024
innodb_max_bitmap_file_size	104857600
innodb_max_changed_pages	1000000
innodb_max_dirty_pages_pct	75.000000
innodb_max_dirty_pages_pct_lwm	0.001000
innodb_max_purge_lag	0
innodb_max_purge_lag_delay	0
innodb_mirrored_log_groups	1
innodb_monitor_disable	
innodb_monitor_enable	
innodb_monitor_reset	
innodb_monitor_reset_all	
innodb_mtflush_threads	8
innodb_old_blocks_pct	37
innodb_old_blocks_time	1000
innodb_online_alter_log_max_size	134217728
innodb_open_files	4096
innodb_optimize_fulltext_only	OFF
innodb_page_size	16384
innodb_prefix_index_cluster_optimization	OFF
innodb_print_all_deadlocks	OFF
innodb_purge_batch_size	300
innodb_purge_threads	1
innodb_random_read_ahead	OFF
innodb_read_ahead_threshold	56
innodb_read_io_threads	4
innodb_read_only	OFF
innodb_replication_delay	0
innodb_rollback_on_timeout	OFF
innodb_rollback_segments	128
innodb_sched_priority_cleaner	19
innodb_scrub_log	OFF
innodb_scrub_log_speed	256
innodb_show_locks_held	10
innodb_show_verbose_locks	0
innodb_simulate_comp_failures	0
innodb_sort_buffer_size	1048576
innodb_spin_wait_delay	6
innodb_stats_auto_recalc	ON
innodb_stats_method	nulls_equal
innodb_stats_modified_counter	0
innodb_stats_on_metadata	OFF
innodb_stats_persistent	ON
innodb_stats_persistent_sample_pages	20
innodb_stats_sample_pages	8
innodb_stats_traditional	ON
innodb_stats_transient_sample_pages	8
innodb_status_output	OFF
innodb_status_output_locks	OFF
innodb_strict_mode	OFF
innodb_support_xa	ON
innodb_sync_array_size	1
innodb_sync_spin_loops	30
innodb_table_locks	ON
innodb_thread_concurrency	4
innodb_thread_sleep_delay	0
innodb_track_changed_pages	OFF
innodb_undo_directory	.
innodb_undo_logs	128
innodb_undo_tablespaces	0
innodb_use_atomic_writes	OFF
innodb_use_fallocate	OFF
innodb_use_global_flush_log_at_trx_commit	ON
innodb_use_mtflush	OFF
innodb_use_native_aio	ON
innodb_use_stacktrace	OFF
innodb_use_sys_malloc	ON
innodb_use_trim	OFF
innodb_version	5.6.28-76.1
innodb_write_io_threads	4
interactive_timeout	600
join_buffer_size	262144
join_buffer_space_limit	2097152
join_cache_level	2
keep_files_on_create	OFF
key_buffer_size	536870912
key_cache_age_threshold	300
key_cache_block_size	1024
key_cache_division_limit	100
key_cache_file_hash_size	512
key_cache_segments	0
large_files_support	ON
large_page_size	0
large_pages	OFF
lc_messages	en_US
lc_messages_dir	/usr/share/mysql
lc_time_names	en_US
license	GPL
local_infile	ON
lock_wait_timeout	600
locked_in_memory	OFF
log_bin	ON
log_bin_basename	/var/log/mysql/mysql-bin
log_bin_index	/var/log/mysql/mysql-bin.index
log_bin_trust_function_creators	OFF
log_error	
log_output	FILE
log_queries_not_using_indexes	OFF
log_slave_updates	ON
log_slow_admin_statements	OFF
log_slow_filter	admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk
log_slow_rate_limit	1
log_slow_slave_statements	OFF
log_slow_verbosity	
log_tc_size	24576
log_warnings	1
long_query_time	10.000000
low_priority_updates	OFF
lower_case_file_system	OFF
lower_case_table_names	0
master_verify_checksum	OFF
max_allowed_packet	134217728
max_binlog_cache_size	18446744073709547520
max_binlog_size	104857600
max_binlog_stmt_cache_size	18446744073709547520
max_connect_errors	100
max_connections	5000
max_delayed_threads	20
max_digest_length	1024
max_error_count	64
max_heap_table_size	1073741824
max_insert_delayed_threads	20
max_join_size	18446744073709551615
max_length_for_sort_data	1024
max_long_data_size	134217728
max_prepared_stmt_count	16382
max_relay_log_size	104857600
max_seeks_for_key	4294967295
max_sort_length	1024
max_sp_recursion_depth	0
max_statement_time	0.000000
max_tmp_tables	32
max_user_connections	0
max_write_lock_count	4294967295
metadata_locks_cache_size	1024
metadata_locks_hash_instances	8
min_examined_row_limit	0
mrr_buffer_size	262144
multi_range_count	256
myisam_block_size	1024
myisam_data_pointer_size	6
myisam_max_sort_file_size	9223372036853727232
myisam_mmap_size	18446744073709551615
myisam_recover_options	BACKUP
myisam_repair_threads	1
myisam_sort_buffer_size	134216704
myisam_stats_method	NULLS_UNEQUAL
myisam_use_mmap	OFF
mysql56_temporal_format	ON
net_buffer_length	16384
net_read_timeout	60
net_retry_count	10
net_write_timeout	60
old	OFF
old_alter_table	OFF
old_mode	
old_passwords	OFF
open_files_limit	65535
optimizer_prune_level	1
optimizer_search_depth	62
optimizer_selectivity_sampling_limit	100
optimizer_switch	index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
optimizer_use_condition_selectivity	1
performance_schema	OFF
performance_schema_accounts_size	-1
performance_schema_digests_size	-1
performance_schema_events_stages_history_long_size	-1
performance_schema_events_stages_history_size	-1
performance_schema_events_statements_history_long_size	-1
performance_schema_events_statements_history_size	-1
performance_schema_events_waits_history_long_size	-1
performance_schema_events_waits_history_size	-1
performance_schema_hosts_size	-1
performance_schema_max_cond_classes	80
performance_schema_max_cond_instances	-1
performance_schema_max_digest_length	1024
performance_schema_max_file_classes	50
performance_schema_max_file_handles	32768
performance_schema_max_file_instances	-1
performance_schema_max_mutex_classes	200
performance_schema_max_mutex_instances	-1
performance_schema_max_rwlock_classes	40
performance_schema_max_rwlock_instances	-1
performance_schema_max_socket_classes	10
performance_schema_max_socket_instances	-1
performance_schema_max_stage_classes	150
performance_schema_max_statement_classes	178
performance_schema_max_table_handles	-1
performance_schema_max_table_instances	-1
performance_schema_max_thread_classes	50
performance_schema_max_thread_instances	-1
performance_schema_session_connect_attrs_size	-1
performance_schema_setup_actors_size	100
performance_schema_setup_objects_size	100
performance_schema_users_size	-1
pid_file	/var/run/mysqld/mysqld.pid
plugin_dir	/usr/lib/mysql/plugin/
plugin_maturity	unknown
port	3306
preload_buffer_size	32768
profiling	OFF
profiling_history_size	15
progress_report_time	5
protocol_version	10
query_alloc_block_size	16384
query_cache_limit	10485760
query_cache_min_res_unit	4096
query_cache_size	134217728
query_cache_strip_comments	OFF
query_cache_type	ON
query_cache_wlock_invalidate	OFF
query_prealloc_size	24576
range_alloc_block_size	4096
read_buffer_size	131072
read_only	OFF
read_rnd_buffer_size	262144
relay_log	
relay_log_basename	
relay_log_index	
relay_log_info_file	relay-log.info
relay_log_purge	ON
relay_log_recovery	OFF
relay_log_space_limit	0
replicate_annotate_row_events	OFF
replicate_do_db	
replicate_do_table	
replicate_events_marked_for_skip	REPLICATE
replicate_ignore_db	mysql
replicate_ignore_table	
replicate_wild_do_table	
replicate_wild_ignore_table	
report_host	
report_password	
report_port	3306
report_user	
rowid_merge_buff_size	8388608
secure_auth	ON
secure_file_priv	
server_id	1006
skip_external_locking	ON
skip_name_resolve	ON
skip_networking	OFF
skip_show_database	OFF
slave_compressed_protocol	OFF
slave_ddl_exec_mode	IDEMPOTENT
slave_domain_parallel_threads	6
slave_exec_mode	STRICT
slave_load_tmpdir	/tmp
slave_max_allowed_packet	1073741824
slave_net_timeout	3600
slave_parallel_max_queued	5242880
slave_parallel_mode	optimistic
slave_parallel_threads	6
slave_run_triggers_for_rbr	NO
slave_skip_errors	1032,1062
slave_sql_verify_checksum	ON
slave_transaction_retries	10
slave_type_conversions	
slow_launch_time	2
slow_query_log	ON
slow_query_log_file	/var/log/mysql/mysql-slow.log
socket	/var/run/mysqld/mysqld.sock
sort_buffer_size	2097152
sql_auto_is_null	OFF
sql_big_selects	ON
sql_buffer_result	OFF
sql_log_bin	ON
sql_log_off	OFF
sql_mode	NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
sql_notes	ON
sql_quote_show_create	ON
sql_safe_updates	OFF
sql_select_limit	18446744073709551615
sql_slave_skip_counter	0
sql_warnings	OFF
ssl_ca	
ssl_capath	
ssl_cert	
ssl_cipher	
ssl_crl	
ssl_crlpath	
ssl_key	
storage_engine	InnoDB
stored_program_cache	256
strict_password_validation	ON
sync_binlog	0
sync_frm	ON
sync_master_info	10000
sync_relay_log	10000
sync_relay_log_info	10000
system_time_zone	PDT
table_definition_cache	4096
table_open_cache	4096
thread_cache_size	1000
thread_concurrency	10
thread_handling	one-thread-per-connection
thread_pool_idle_timeout	60
thread_pool_max_threads	1000
thread_pool_oversubscribe	3
thread_pool_size	24
thread_pool_stall_limit	500
thread_stack	196608
time_format	%H:%i:%s
time_zone	SYSTEM
timed_mutexes	OFF
tmp_table_size	1073741824
tmpdir	/tmp
transaction_alloc_block_size	8192
transaction_prealloc_size	4096
tx_isolation	REPEATABLE-READ
tx_read_only	OFF
unique_checks	ON
updatable_views_with_limit	YES
use_stat_tables	NEVER
userstat	OFF
version	10.1.13-MariaDB-1~trusty
version_comment	mariadb.org binary distribution
version_compile_machine	x86_64
version_compile_os	debian-linux-gnu
version_malloc_library	system jemalloc
version_ssl_library	OpenSSL 1.0.1f 6 Jan 2014
wait_timeout	600
wsrep_osu_method	TOI
wsrep_auto_increment_control	ON
wsrep_causal_reads	OFF
wsrep_certify_nonpk	ON
wsrep_cluster_address	
wsrep_cluster_name	my_wsrep_cluster
wsrep_convert_lock_to_trx	OFF
wsrep_data_home_dir	/var/lib/mysql/
wsrep_dbug_option	
wsrep_debug	OFF
wsrep_desync	OFF
wsrep_drupal_282555_workaround	OFF
wsrep_forced_binlog_format	NONE
wsrep_gtid_domain_id	0
wsrep_gtid_mode	OFF
wsrep_load_data_splitting	ON
wsrep_log_conflicts	OFF
wsrep_max_ws_rows	131072
wsrep_max_ws_size	1073741824
wsrep_mysql_replication_bundle	0
wsrep_node_address	
wsrep_node_incoming_address	AUTO
wsrep_node_name	
wsrep_notify_cmd	
wsrep_on	OFF
wsrep_patch_version	wsrep_25.13
wsrep_provider	none
wsrep_provider_options	
wsrep_recover	OFF
wsrep_replicate_myisam	OFF
wsrep_restart_slave	OFF
wsrep_retry_autocommit	1
wsrep_slave_fk_checks	ON
wsrep_slave_uk_checks	OFF
wsrep_slave_threads	1
wsrep_sst_auth	
wsrep_sst_donor	
wsrep_sst_donor_rejects_queries	OFF
wsrep_sst_method	rsync
wsrep_sst_receive_address	AUTO
wsrep_start_position	00000000-0000-0000-0000-000000000000:-1
wsrep_sync_wait	0

SHOW GLOBAL STATUS:

Variable_name	Value
Aborted_clients	3716
Aborted_connects	64
Access_denied_errors	0
Acl_column_grants	1
Acl_database_grants	9
Acl_function_grants	0
Acl_procedure_grants	0
Acl_proxy_users	1
Acl_role_grants	0
Acl_roles	0
Acl_table_grants	196
Acl_users	22
Aria_pagecache_blocks_not_flushed	0
Aria_pagecache_blocks_unused	15706
Aria_pagecache_blocks_used	27
Aria_pagecache_read_requests	38976635
Aria_pagecache_reads	1027743
Aria_pagecache_write_requests	2576931
Aria_pagecache_writes	0
Aria_transaction_log_syncs	0
Binlog_commits	628659387
Binlog_group_commits	282533344
Binlog_group_commit_trigger_count	0
Binlog_group_commit_trigger_lock_wait	0
Binlog_group_commit_trigger_timeout	0
Binlog_snapshot_file	mysql-bin.011957
Binlog_snapshot_position	13629225
Binlog_bytes_written	455454382757
Binlog_cache_disk_use	3599498
Binlog_cache_use	629173744
Binlog_stmt_cache_disk_use	0
Binlog_stmt_cache_use	0
Busy_time	0.000000
Bytes_received	525894710524
Bytes_sent	112530780495
Com_admin_commands	419811
Com_alter_db	0
Com_alter_db_upgrade	0
Com_alter_event	0
Com_alter_function	0
Com_alter_procedure	0
Com_alter_server	0
Com_alter_table	11
Com_alter_tablespace	0
Com_analyze	0
Com_assign_to_keycache	0
Com_begin	630302796
Com_binlog	0
Com_call_procedure	0
Com_change_db	40813
Com_change_master	0
Com_check	0
Com_checksum	0
Com_commit	629592443
Com_compound_sql	0
Com_create_db	378782
Com_create_event	0
Com_create_function	0
Com_create_index	0
Com_create_procedure	0
Com_create_role	0
Com_create_server	0
Com_create_table	378675
Com_create_temporary_table	2
Com_create_trigger	0
Com_create_udf	0
Com_create_user	0
Com_create_view	0
Com_dealloc_sql	0
Com_delete	541487231
Com_delete_multi	443
Com_do	0
Com_drop_db	0
Com_drop_event	0
Com_drop_function	0
Com_drop_index	0
Com_drop_procedure	0
Com_drop_role	0
Com_drop_server	0
Com_drop_table	3
Com_drop_temporary_table	2
Com_drop_trigger	0
Com_drop_user	0
Com_drop_view	0
Com_empty_query	0
Com_execute_sql	0
Com_flush	12
Com_get_diagnostics	0
Com_grant	3157
Com_grant_role	0
Com_ha_close	0
Com_ha_open	0
Com_ha_read	0
Com_help	0
Com_insert	878935212
Com_insert_select	1453
Com_install_plugin	82
Com_kill	60
Com_load	0
Com_lock_tables	0
Com_optimize	0
Com_preload_keys	0
Com_prepare_sql	0
Com_purge	0
Com_purge_before_date	0
Com_release_savepoint	0
Com_rename_table	0
Com_rename_user	0
Com_repair	1
Com_replace	239541
Com_replace_select	0
Com_reset	0
Com_resignal	0
Com_revoke	0
Com_revoke_all	0
Com_revoke_role	0
Com_rollback	0
Com_rollback_to_savepoint	0
Com_savepoint	0
Com_select	48869655
Com_set_option	6306022
Com_show_authors	0
Com_show_binlog_events	0
Com_show_binlogs	0
Com_show_charsets	0
Com_show_collations	1
Com_show_contributors	0
Com_show_create_db	0
Com_show_create_event	0
Com_show_create_func	0
Com_show_create_proc	0
Com_show_create_table	0
Com_show_create_trigger	0
Com_show_databases	4
Com_show_engine_logs	0
Com_show_engine_mutex	0
Com_show_engine_status	17077
Com_show_errors	0
Com_show_events	0
Com_show_explain	0
Com_show_fields	668
Com_show_function_status	0
Com_show_generic	0
Com_show_grants	2993
Com_show_keys	0
Com_show_master_status	0
Com_show_open_tables	3428
Com_show_plugins	1
Com_show_privileges	0
Com_show_procedure_status	0
Com_show_processlist	370943
Com_show_profile	0
Com_show_profiles	0
Com_show_relaylog_events	0
Com_show_slave_hosts	0
Com_show_slave_status	538670
Com_show_status	1095360
Com_show_storage_engines	0
Com_show_table_status	0
Com_show_tables	4
Com_show_triggers	0
Com_show_variables	70585
Com_show_warnings	43565
Com_shutdown	0
Com_signal	0
Com_start_all_slaves	0
Com_start_slave	0
Com_stmt_close	0
Com_stmt_execute	1027717
Com_stmt_fetch	0
Com_stmt_prepare	5
Com_stmt_reprepare	0
Com_stmt_reset	0
Com_stmt_send_long_data	0
Com_stop_all_slaves	0
Com_stop_slave	0
Com_truncate	12
Com_uninstall_plugin	0
Com_unlock_tables	0
Com_update	213872503
Com_update_multi	23
Com_xa_commit	0
Com_xa_end	0
Com_xa_prepare	0
Com_xa_recover	0
Com_xa_rollback	0
Com_xa_start	0
Compression	OFF
Connection_errors_accept	0
Connection_errors_internal	0
Connection_errors_max_connections	0
Connection_errors_peer_address	0
Connection_errors_select	0
Connection_errors_tcpwrap	0
Connections	1711455
Cpu_time	0.000000
Created_tmp_disk_tables	1027759
Created_tmp_files	246570
Created_tmp_tables	3530313
Delayed_errors	0
Delayed_insert_threads	0
Delayed_writes	0
Empty_queries	17786673
Executed_events	0
Executed_triggers	0
Feature_delay_key_write	0
Feature_dynamic_columns	0
Feature_fulltext	0
Feature_gis	0
Feature_locale	0
Feature_subquery	646
Feature_timezone	0
Feature_trigger	0
Feature_xml	0
Flush_commands	1
Handler_commit	5181651422
Handler_delete	1769191969
Handler_discover	52
Handler_external_lock	0
Handler_icp_attempts	266263139
Handler_icp_match	148961418
Handler_mrr_init	0
Handler_mrr_key_refills	0
Handler_mrr_rowid_refills	0
Handler_prepare	4427349683
Handler_read_first	3055
Handler_read_key	10520134284
Handler_read_last	21213
Handler_read_next	10510629921
Handler_read_prev	186506903
Handler_read_rnd	224255981
Handler_read_rnd_deleted	1368478
Handler_read_rnd_next	28062720542
Handler_rollback	3237445
Handler_savepoint	0
Handler_savepoint_rollback	0
Handler_tmp_update	22975538
Handler_tmp_write	6319132851
Handler_update	240176707
Handler_write	2186468597
Innodb_available_undo_logs	128
Innodb_background_log_sync	1008064
Innodb_buffer_pool_bytes_data	56445485056
Innodb_buffer_pool_bytes_dirty	2867773440
Innodb_buffer_pool_dump_status	Dumping buffer pool(s) not yet started
Innodb_buffer_pool_load_status	Loading buffer pool(s) not yet started
Innodb_buffer_pool_pages_data	3445159
Innodb_buffer_pool_pages_dirty	175035
Innodb_buffer_pool_pages_flushed	440571851
Innodb_buffer_pool_pages_free	4090
Innodb_buffer_pool_pages_lru_flushed	0
Innodb_buffer_pool_pages_made_not_young	4679940938
Innodb_buffer_pool_pages_made_young	75697785
Innodb_buffer_pool_pages_misc	108699
Innodb_buffer_pool_pages_old	1271668
Innodb_buffer_pool_pages_total	3557948
Innodb_buffer_pool_read_ahead	4833284
Innodb_buffer_pool_read_ahead_evicted	0
Innodb_buffer_pool_read_ahead_rnd	0
Innodb_buffer_pool_read_requests	87432418261
Innodb_buffer_pool_reads	71328300
Innodb_buffer_pool_wait_free	0
Innodb_buffer_pool_write_requests	20335718965
Innodb_checkpoint_age	427130799
Innodb_checkpoint_max_age	868783842
Innodb_data_fsyncs	37865072
Innodb_data_pending_fsyncs	0
Innodb_data_pending_reads	0
Innodb_data_pending_writes	1
Innodb_data_read	1470116368384
Innodb_data_reads	89932309
Innodb_data_writes	1364921898
Innodb_data_written	15881766982144
Innodb_dblwr_pages_written	440571851
Innodb_dblwr_writes	4693276
Innodb_deadlocks	706
Innodb_have_atomic_builtins	ON
Innodb_history_list_length	2114
Innodb_ibuf_discarded_delete_marks	7312
Innodb_ibuf_discarded_deletes	7311
Innodb_ibuf_discarded_inserts	23783
Innodb_ibuf_free_list	710763
Innodb_ibuf_merged_delete_marks	138752378
Innodb_ibuf_merged_deletes	38711019
Innodb_ibuf_merged_inserts	128293291
Innodb_ibuf_merges	24903031
Innodb_ibuf_segment_size	809450
Innodb_ibuf_size	98686
Innodb_log_waits	0
Innodb_log_write_requests	2325776412
Innodb_log_writes	915831903
Innodb_lsn_current	25282269066270
Innodb_lsn_flushed	25282268668271
Innodb_lsn_last_checkpoint	25281841935471
Innodb_master_thread_active_loops	1008064
Innodb_master_thread_idle_loops	0
Innodb_max_trx_id	58697260361
Innodb_mem_adaptive_hash	2703848864
Innodb_mem_dictionary	232042748
Innodb_mem_total	60115189760
Innodb_mutex_os_waits	2555757580
Innodb_mutex_spin_rounds	78886247573
Innodb_mutex_spin_waits	2653123783
Innodb_oldest_view_low_limit_trx_id	0
Innodb_os_log_fsyncs	1880375
Innodb_os_log_pending_fsyncs	0
Innodb_os_log_pending_writes	1
Innodb_os_log_written	1445273387008
Innodb_page_size	16384
Innodb_pages_created	7911740
Innodb_pages_read	89732158
Innodb_pages_written	440571851
Innodb_purge_trx_id	58697260361
Innodb_purge_undo_no	0
Innodb_read_views_memory	864
Innodb_row_lock_current_waits	91
Innodb_row_lock_time	28992332
Innodb_row_lock_time_avg	3
Innodb_row_lock_time_max	241357
Innodb_row_lock_waits	7479543
Innodb_rows_deleted	653452699
Innodb_rows_inserted	910376096
Innodb_rows_read	29762872524
Innodb_rows_updated	237877579
Innodb_system_rows_deleted	628897643
Innodb_system_rows_inserted	630309283
Innodb_system_rows_read	628897647
Innodb_system_rows_updated	0
Innodb_s_lock_os_waits	251544829
Innodb_s_lock_spin_rounds	9833059953
Innodb_s_lock_spin_waits	389236664
Innodb_truncated_status_writes	0
Innodb_x_lock_os_waits	827059282
Innodb_x_lock_spin_rounds	30583224935
Innodb_x_lock_spin_waits	921405286
Innodb_page_compression_saved	0
Innodb_page_compression_trim_sect512	0
Innodb_page_compression_trim_sect1024	0
Innodb_page_compression_trim_sect2048	0
Innodb_page_compression_trim_sect4096	0
Innodb_page_compression_trim_sect8192	0
Innodb_page_compression_trim_sect16384	0
Innodb_page_compression_trim_sect32768	0
Innodb_num_index_pages_written	431838281
Innodb_num_non_index_pages_written	932821731
Innodb_num_pages_page_compressed	0
Innodb_num_page_compressed_trim_op	0
Innodb_num_page_compressed_trim_op_saved	0
Innodb_num_pages_page_decompressed	0
Innodb_num_pages_page_compression_error	0
Innodb_num_pages_encrypted	0
Innodb_num_pages_decrypted	0
Innodb_have_lz4	OFF
Innodb_have_lzo	OFF
Innodb_have_lzma	OFF
Innodb_have_bzip2	OFF
Innodb_have_snappy	OFF
Innodb_defragment_compression_failures	0
Innodb_defragment_failures	0
Innodb_defragment_count	0
Innodb_onlineddl_rowlog_rows	0
Innodb_onlineddl_rowlog_pct_used	0
Innodb_onlineddl_pct_progress	0
Innodb_secondary_index_triggered_cluster_reads	910584683
Innodb_secondary_index_triggered_cluster_reads_avoided	0
Innodb_encryption_rotation_pages_read_from_cache	0
Innodb_encryption_rotation_pages_read_from_disk	0
Innodb_encryption_rotation_pages_modified	0
Innodb_encryption_rotation_pages_flushed	0
Innodb_encryption_rotation_estimated_iops	0
Innodb_scrub_background_page_reorganizations	0
Innodb_scrub_background_page_splits	0
Innodb_scrub_background_page_split_failures_underflow	0
Innodb_scrub_background_page_split_failures_out_of_filespace	0
Innodb_scrub_background_page_split_failures_missing_index	0
Innodb_scrub_background_page_split_failures_unknown	0
Key_blocks_not_flushed	0
Key_blocks_unused	428654
Key_blocks_used	22
Key_blocks_warm	0
Key_read_requests	416867
Key_reads	22
Key_write_requests	0
Key_writes	0
Last_query_cost	0.000000
Master_gtid_wait_count	0
Master_gtid_wait_time	0
Master_gtid_wait_timeouts	0
Max_statement_time_exceeded	0
Max_used_connections	422
Memory_used	81850281024
Not_flushed_delayed_rows	0
Open_files	93
Open_streams	0
Open_table_definitions	263
Open_tables	648
Opened_files	6061728
Opened_plugin_libraries	2
Opened_table_definitions	296
Opened_tables	777
Opened_views	0
Performance_schema_accounts_lost	0
Performance_schema_cond_classes_lost	0
Performance_schema_cond_instances_lost	0
Performance_schema_digest_lost	0
Performance_schema_file_classes_lost	0
Performance_schema_file_handles_lost	0
Performance_schema_file_instances_lost	0
Performance_schema_hosts_lost	0
Performance_schema_locker_lost	0
Performance_schema_mutex_classes_lost	0
Performance_schema_mutex_instances_lost	0
Performance_schema_rwlock_classes_lost	0
Performance_schema_rwlock_instances_lost	0
Performance_schema_session_connect_attrs_lost	0
Performance_schema_socket_classes_lost	0
Performance_schema_socket_instances_lost	0
Performance_schema_stage_classes_lost	0
Performance_schema_statement_classes_lost	0
Performance_schema_table_handles_lost	0
Performance_schema_table_instances_lost	0
Performance_schema_thread_classes_lost	0
Performance_schema_thread_instances_lost	0
Performance_schema_users_lost	0
Prepared_stmt_count	5
Qcache_free_blocks	19427
Qcache_free_memory	120646368
Qcache_hits	18555535
Qcache_inserts	20728992
Qcache_lowmem_prunes	7821495
Qcache_not_cached	8493688
Qcache_queries_in_cache	11533
Qcache_total_blocks	42500
Queries	2374521976
Questions	59157894
Rows_read	29858066679
Rows_sent	3065820373
Rows_tmp_read	10091197468
Rpl_status	AUTH_MASTER
Select_full_join	18565
Select_full_range_join	64
Select_range	558269
Select_range_check	0
Select_scan	3797133
Slave_connections	0
Slave_heartbeat_period	1800.000
Slave_open_temp_tables	0
Slave_received_heartbeats	0
Slave_retried_transactions	1599763
Slave_running	ON
Slave_skipped_errors	6099
Slaves_connected	0
Slaves_running	1
Slow_launch_threads	0
Slow_queries	553
Sort_merge_passes	123306
Sort_priority_queue_sorts	1402367
Sort_range	4995087
Sort_rows	8953843786
Sort_scan	216271
Ssl_accept_renegotiates	0
Ssl_accepts	0
Ssl_callback_cache_hits	0
Ssl_cipher	
Ssl_cipher_list	
Ssl_client_connects	0
Ssl_connect_renegotiates	0
Ssl_ctx_verify_depth	0
Ssl_ctx_verify_mode	0
Ssl_default_timeout	0
Ssl_finished_accepts	0
Ssl_finished_connects	0
Ssl_server_not_after	
Ssl_server_not_before	
Ssl_session_cache_hits	0
Ssl_session_cache_misses	0
Ssl_session_cache_mode	NONE
Ssl_session_cache_overflows	0
Ssl_session_cache_size	0
Ssl_session_cache_timeouts	0
Ssl_sessions_reused	0
Ssl_used_session_cache_entries	0
Ssl_verify_depth	0
Ssl_verify_mode	0
Ssl_version	
Subquery_cache_hit	66642575
Subquery_cache_miss	6339580
Syncs	463801
Table_locks_immediate	15948842132
Table_locks_waited	838
Tc_log_max_pages_used	0
Tc_log_page_size	0
Tc_log_page_waits	0
Threadpool_idle_threads	0
Threadpool_threads	0
Threads_cached	410
Threads_connected	12
Threads_created	422
Threads_running	1
Uptime	1028322
Uptime_since_flush_status	1028322
wsrep_cluster_conf_id	18446744073709551615
wsrep_cluster_size	0
wsrep_cluster_state_uuid	
wsrep_cluster_status	Disconnected
wsrep_connected	OFF
wsrep_local_bf_aborts	0
wsrep_local_index	18446744073709551615
wsrep_provider_name	
wsrep_provider_vendor	
wsrep_provider_version	
wsrep_ready	OFF
wsrep_thread_count	0

SHOW ENGINE INNODB STATUS:

*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
2016-04-13 15:00:58 7f13cefce700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 14 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1008231 srv_active, 0 srv_shutdown, 0 srv_idle
srv_master_thread log flush and writes: 1008231
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 3666807805
OS WAIT ARRAY INFO: signal count 1772992321
Mutex spin waits 2653608512, rounds 78902436241, OS waits 2556287460
RW-shared spins 389359082, rounds 9836637483, OS waits 251636619
RW-excl spins 921609530, rounds 30590580953, OS waits 827260771
Spin rounds per wait: 29.73 mutex, 25.26 RW-shared, 33.19 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
------------
TRANSACTIONS
------------
Trx id counter 58697486513
Purge done for trx's n:o < 58697486509 undo n:o < 0 state: running
History list length 2097
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 1711460, OS thread handle 0x7f13cefce700, query id 2374829350 104.220.241.10 non_root init
show engine innodb status
---TRANSACTION 58181485546, not started
MySQL thread id 57, OS thread handle 0x7f23741f2700, query id 2374706738 127.0.0.1 vividcortex cleaning up
---TRANSACTION 0, not started
MySQL thread id 16, OS thread handle 0x7f2374254700, query id 2374826360 127.0.0.1 vividcortex cleaning up
---TRANSACTION 0, not started
MySQL thread id 198, OS thread handle 0x7f2371dbb700, query id 2374827488 127.0.0.1 vividcortex cleaning up
---TRANSACTION 0, not started
MySQL thread id 15, OS thread handle 0x7f2374285700, query id 2374827484 127.0.0.1 vividcortex cleaning up
---TRANSACTION 0, not started
MySQL thread id 11, OS thread handle 0x7f23742b6700, query id 2374827986 127.0.0.1 vividcortex cleaning up
---TRANSACTION 0, not started
MySQL thread id 60, OS thread handle 0x7f23741c1700, query id 2374827487 127.0.0.1 vividcortex cleaning up
---TRANSACTION 57627515141, not started
MySQL thread id 1, OS thread handle 0x7f23753f1700, query id 0 Waiting for background binlog tasks
---TRANSACTION 58697486512, ACTIVE 0 sec preparing
3 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 1
MySQL thread id 9, OS thread handle 0x7f237529a700, query id 2374829351 init
COMMIT
Trx #rec lock waits 1250822 #table lock waits 0
Trx total rec lock wait time 4386 SEC
Trx total table lock wait time 0 SEC
---TRANSACTION 58697486511, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 6, OS thread handle 0x7f23752fc700, query id 2374829347
Trx #rec lock waits 1249535 #table lock waits 0
Trx total rec lock wait time 4811 SEC
Trx total table lock wait time 0 SEC
---TRANSACTION 58697486510, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 2
MySQL thread id 5, OS thread handle 0x7f237532d700, query id 2374829345
COMMIT
Trx #rec lock waits 1249443 #table lock waits 0
Trx total rec lock wait time 4351 SEC
Trx total table lock wait time 0 SEC
---TRANSACTION 58697486509, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
2 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 4, OS thread handle 0x7f237535e700, query id 2374829342
Trx #rec lock waits 1246987 #table lock waits 0
Trx total rec lock wait time 4284 SEC
Trx total table lock wait time 0 SEC
---TRANSACTION 58697486506, ACTIVE (PREPARED) 0 sec
2 lock struct(s), heap size 360, 0 row lock(s), undo log entries 2
MySQL thread id 8, OS thread handle 0x7f23752cb700, query id 2374829340 Waiting for prior transaction to commit
Trx #rec lock waits 1246639 #table lock waits 0
Trx total rec lock wait time 4176 SEC
Trx total table lock wait time 0 SEC
---TRANSACTION 58697486505, ACTIVE (PREPARED) 0 sec
2 lock struct(s), heap size 360, 0 row lock(s), undo log entries 2
MySQL thread id 7, OS thread handle 0x7f2375269700, query id 2374829338 Waiting for prior transaction to commit
Trx #rec lock waits 1246950 #table lock waits 0
Trx total rec lock wait time 4328 SEC
Trx total table lock wait time 0 SEC
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
89936451 OS file reads, 1365209424 OS file writes, 37873040 OS fsyncs
31.00 reads/s, 16384 avg bytes/read, 1714.81 writes/s, 40.78 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 98673, free list len 710776, seg size 809450, 24905294 merges
merged operations:
 insert 128307697, delete mark 138752899, delete 38711413
discarded operations:
 insert 23783, delete mark 7312, delete 7311
287.69 hash searches/s, 7316.48 non-hash searches/s
---
LOG
---
Log sequence number 25282413398455
Log flushed up to   25282413391019
Pages flushed up to 25282000172598
Last checkpoint at  25281995691430
Max checkpoint age    868783842
Checkpoint age target 841634347
Modified age          413225857
Checkpoint age        417707025
0 pending log writes, 0 pending chkp writes
916186747 log i/o's done, 1283.79 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 60115189760; in additional pool allocated 0
Total memory allocated by read views 864
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 2705438112 	(922920248 + 1782517864)
    Page hash           14421464 (buffer pool 0 only)
    Dictionary cache    232042748 	(230731504 + 1311244)
    File system         910064 	(812272 + 97792)
    Lock system         144213864 	(144207176 + 6688)
    Recovery system     0 	(0 + 0)
Dictionary memory allocated 1311244
Buffer pool size        3557948
Buffer pool size, bytes 58293420032
Free buffers            4070
Database pages          3445082
Old database pages      1271638
Modified db pages       158758
Percent of dirty pages(LRU & free pages): 4.603
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 40, single page 0
Pages made young 75707467, not young 4679959241
65.71 youngs/s, 233.63 non-youngs/s
Pages read 89736300, created 7912473, written 440647383
31.00 reads/s, 4.00 creates/s, 423.04 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 3 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 3445082, unzip_LRU len: 0
I/O sum[85864]:cur[196], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size        889487
Buffer pool size, bytes 14573355008
Free buffers            1018
Database pages          861281
Old database pages      317913
Modified db pages       41580
Percent of dirty pages(LRU & free pages): 4.822
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 40, single page 0
Pages made young 19270370, not young 1181061902
16.07 youngs/s, 13.64 non-youngs/s
Pages read 22637549, created 1977991, written 116448210
8.64 reads/s, 0.79 creates/s, 113.56 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 861281, unzip_LRU len: 0
I/O sum[21466]:cur[49], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size        889487
Buffer pool size, bytes 14573355008
Free buffers            1014
Database pages          861072
Old database pages      317836
Modified db pages       39550
Percent of dirty pages(LRU & free pages): 4.588
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 18907160, not young 1171104873
17.43 youngs/s, 110.06 non-youngs/s
Pages read 22531569, created 1992810, written 107959388
8.93 reads/s, 1.86 creates/s, 101.21 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 4 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 861072, unzip_LRU len: 0
I/O sum[21466]:cur[49], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size        889487
Buffer pool size, bytes 14573355008
Free buffers            1017
Database pages          861300
Old database pages      317921
Modified db pages       38384
Percent of dirty pages(LRU & free pages): 4.451
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 18821452, not young 1150948090
15.57 youngs/s, 18.21 non-youngs/s
Pages read 22432634, created 1974434, written 107472058
6.00 reads/s, 0.64 creates/s, 99.35 writes/s
Buffer pool hit rate 998 / 1000, young-making rate 7 / 1000 not 9 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 861300, unzip_LRU len: 0
I/O sum[21466]:cur[49], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size        889487
Buffer pool size, bytes 14573355008
Free buffers            1021
Database pages          861429
Old database pages      317968
Modified db pages       39244
Percent of dirty pages(LRU & free pages): 4.550
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 18708485, not young 1176844376
16.64 youngs/s, 91.71 non-youngs/s
Pages read 22134548, created 1967238, written 108767727
7.43 reads/s, 0.71 creates/s, 108.92 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 9 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 861429, unzip_LRU len: 0
I/O sum[21466]:cur[49], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
6 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
6 out of 1000 descriptors used
Main thread process no. 11848, id 139725285340928, state: sleeping
Number of rows inserted 910491519, updated 237901404, deleted 653453218, read 29762903475
691.88 inserts/s, 154.56 updates/s, 7.21 deletes/s, 237.27 reads/s
Number of system rows inserted 630459860, updated 0, deleted 629048170, read 629048174
916.22 inserts/s, 0.00 updates/s, 915.79 deletes/s, 915.79 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================



 Comments   
Comment by Elena Stepanova [ 2016-04-17 ]

axel, could you please look into this?

Comment by Guillaume Lefranc [ 2016-04-26 ]

Verified today:

10.1.12:
OLTP test statistics:
queries performed:
read: 513865
write: 146836
other: 73412
total: 734113
transactions: 36710 (734.08 per sec.)
read/write requests: 660701 (13211.89 per sec.)

10.1.13:
OLTP test statistics:
queries performed:
read: 408667
write: 116771
other: 58383
total: 583821
transactions: 29195 (583.75 per sec.)
read/write requests: 525438 (10506.06 per sec.)

Test used:
sysbench \
--test=/home/tanj/Dev/source/sysbench/sysbench/tests/db/oltp.lua \
--mysql-table-engine=innodb \
--mysql-ignore-errors=all \
--oltp-test-mode=complex \
--oltp-read-only=off \
--oltp-reconnect=on \
--oltp-tables-count=16 \
--oltp-table-size=100000 \
--max-requests=100000000 \
--num-threads=8 \
--report-interval=1 \
--report-checkpoints=10 \
--max-time=60

Comment by Sergey Vojtovich [ 2016-04-27 ]

Some benchmark details:

> - did you compare community or enterprise versions?
>
I compared community versions.
 
> - please confirm the issue is 10.1.12 vs 10.1.13 comparison (and not
>   "10.1.11 is 10x slower than 10.0.24" as below in this thread)
>
I confirm this.
 
> - how did you compile them (or which binaries did you use)?
>
I used official docker images. Those are Debian Jessie installs.
I used the following command to start the two instances:
$ docker run -d -p 3302:3306 -e MYSQL_ROOT_PASSWORD=admin --name mariadb13
mariadb:10.1.13
$ docker run -d -p 3301:3306 -e MYSQL_ROOT_PASSWORD=admin --name mariadb12
mariadb:10.1.12
 
> - could you share your my.cnf?
>
It is the default Debian Jessie my.cnf.
 
> - which sysbench version did you use?
>
0.5.0
 
> - did it involve encryption/compression?
>
No
 
> - is it necessary to have binlog/galera/slave threads (what exactly?) to
>   reproduce it?
>
No
 
> - did you find out if it looks more like disk issue or some mutex
> contention?
>
It looks like disk issue, there seems to be more activity on disk during
the benchmark
 
> - what was the CPU/core count on the benchmark system?
>
4 cores

Comment by Sergey Vojtovich [ 2016-04-27 ]

jplindst, I'm assigning to you since it looks like "disk issue". Can this be relevant: https://github.com/MariaDB/server/commit/f71c45c71db8c7862fc50b8382ccdbff4772e258 ?

Comment by Jan Lindström (Inactive) [ 2016-04-27 ]

Are you sure about the change ? I do not follow how that could effect really here.

Comment by Sergey Vojtovich [ 2016-04-27 ]

No, it's only best guess.

Comment by Jan Lindström (Inactive) [ 2016-04-27 ]

Can you try is that the issue ?

Comment by Sergey Vojtovich [ 2016-04-27 ]

I'd certainly try it, but I wasn't able to reproduce this issue locally. May be tanj could?

Comment by Guillaume Lefranc [ 2016-04-27 ]

I suppose I could try reverting that commit locally and see how it goes.

Comment by Jan Lindström (Inactive) [ 2016-04-29 ]

Can I have error log and my.cnf files. What kind of storage is used?

Comment by Jan Lindström (Inactive) [ 2016-05-02 ]

I could not repeat. I used CentOS Linux release 7.1.1503 (Core) using the 3.10.0-229.el7.x86_64 Linux kernel, ioMemory SX300-1600 with VSL driver 4.2.1 build 1137 and NVMFS 1.1.1. 10.1.13:

OLTP test statistics:
    queries performed:
        read:                            2857596
        write:                           816456
        other:                           408228
        total:                           4082280
    transactions:                        204114 (3401.78 per sec.)
    read/write requests:                 3674052 (61231.98 per sec.)
    other operations:                    408228 (6803.55 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
General statistics:
    total time:                          60.0022s
    total number of events:              204114
    total time taken by event execution: 479.7271s
    response time:
         min:                                  1.82ms
         avg:                                  2.35ms
         max:                                  7.38ms
         approx.  95 percentile:               2.82ms
 
Threads fairness:
    events (avg/stddev):           25514.2500/157.82
    execution time (avg/stddev):   59.9659/0.00

10.1.12:

 
OLTP test statistics:
    queries performed:
        read:                            2831766
        write:                           809076
        other:                           404538
        total:                           4045380
    transactions:                        202269 (3371.05 per sec.)
    read/write requests:                 3640842 (60678.82 per sec.)
    other operations:                    404538 (6742.09 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
General statistics:
    total time:                          60.0019s
    total number of events:              202269
    total time taken by event execution: 479.7314s
    response time:
         min:                                  1.84ms
         avg:                                  2.37ms
         max:                                 40.99ms
         approx.  95 percentile:               2.81ms
 
Threads fairness:
    events (avg/stddev):           25283.6250/193.40
    execution time (avg/stddev):   59.9664/0.00

Comment by Sergey Vojtovich [ 2016-05-03 ]

Perf snapshots contributed by IBM (high concurrent benchmark)...

10.1.13:

    29.21%  mysqld                    [.] _Z8ut_delaym
   1.98%  mysqld                    [.]
_Z20row_search_for_mysqlPhmP14row_prebuilt_tmm
   1.50%  mysqld                    [.] _Z10MYSQLparseP3THD
   1.45%  mysqld                    [.] _Z15mutex_spin_waitPvbPKcm
   1.16%  mysqld                    [.]
_Z20rec_get_offsets_funcPKhPK12dict_index_tPmmPP16mem_block_info_t
   1.07%  mysqld                    [.]
_Z19rw_lock_x_lock_funcP9rw_lock_tmPKcmbb
   0.91%  mysqld                    [.] my_hash_sort_simple
   0.88%  [kernel]                  [k] _raw_spin_lock
   0.79%  mysqld                    [.] my_strnxfrm_simple
   0.67%  [kernel]                  [k] __schedule
   0.65%  libpthread-2.22.so        [.] pthread_mutex_lock
   0.58%  [kernel]                  [k] menu_select
   0.54%  [kernel]                  [k] refresh_cpu_vm_stats
   0.53%  [kernel]                  [k] __spin_yield
   0.52%  mysqld                    [.]
_Z16buf_page_get_genmmmmP11buf_block_tmPKcmP5mtr_tP7dberr_t
   0.51%  mysqld                    [.]
_ZL13lex_one_tokenP7YYSTYPEP3THD.constprop.83

10.1.11:

6.03%  mysqld                    [.] _Z8ut_delaym
   4.50%  libc-2.20.so              [.] __memcpy_power7
   3.68%  mysqld                    [.]
_Z20row_search_for_mysqlPhmP14row_prebuilt_tmm
   2.44%  mysqld                    [.] _Z10MYSQLparseP3THD
   2.07%  mysqld                    [.]
_Z20rec_get_offsets_funcPKhPK12dict_index_tPmmPP16mem_block_info_t
   1.57%  mysqld                    [.] my_hash_sort_simple
   1.29%  mysqld                    [.] my_strnxfrm_simple
   1.21%  mysqld                    [.]
_Z16buf_page_get_genmmmmP11buf_block_tmPKcmP5mtr_tP7dberr_t
   0.94%  mysqld                    [.]
_ZN11ha_innobase13general_fetchEPhjj
   0.89%  mysqld                    [.]
_ZL20evaluate_join_recordP4JOINP13st_join_tablei
   0.81%  mysqld                    [.]
_Z24btr_search_guess_on_hashP12dict_index_tP12btr_search_tPK8dtuple_tmmP9btr_cur_tmP5mtr_t
   0.77%  mysqld                    [.] _Z10mtr_commitP5mtr_t
   0.76%  mysqld                    [.] _ZL13lex_one_tokenP7YYSTYPEP3THD
   0.65%  mysqld                    [.] ptr_compare_0
   0.60%  [kernel]                  [k] __schedule
   0.59%  mysqld                    [.] alloc_root
   0.59%  mysqld                    [.] _ZN17Item_func_between7val_intEv
   0.56%  mysqld                    [.] _Z26page_rec_get_n_recs_beforePKh

Note ut_delay raise...

Comment by Jan Lindström (Inactive) [ 2016-05-03 ]

commit 3d1a7cba71f6c843639f0b9a48b12017ff610112 or commit d4ba50477e6f0092a3b83528c02c0f30a2b708a3 ?

Comment by Sergey Vojtovich [ 2016-05-03 ]

Unlikely, 10.1.13 tag was created March 24, while this revision was committed March 30.

Comment by Jan Lindström (Inactive) [ 2016-05-03 ]

Can't repeat on above Centos and MariaDB 10.1.11:

OLTP test statistics:
    queries performed:
        read:                            2810990
        write:                           803138
        other:                           401569
        total:                           4015697
    transactions:                        200784 (3346.29 per sec.)
    read/write requests:                 3614128 (60233.52 per sec.)
    other operations:                    401569 (6692.60 per sec.)
    ignored errors:                      1      (0.02 per sec.)
    reconnects:                          0      (0.00 per sec.)
 
General statistics:
    total time:                          60.0019s
    total number of events:              200784
    total time taken by event execution: 479.7341s
    response time:
         min:                                  1.86ms
         avg:                                  2.39ms
         max:                                 43.87ms
         approx.  95 percentile:               2.87ms
 
Threads fairness:
    events (avg/stddev):           25098.0000/185.49
    execution time (avg/stddev):   59.9668/0.00

Comment by Axel Schwenke [ 2016-05-04 ]

I just reproduced it on the cheetah01 benchmark machine. The effect is more pronounced with fast storage (SSD) and write-optimized settings (innodb_flush_log_at_trx_commit = 2). It exists only in XtraDB. Not InnoDB, not MyISAM. It's gone with the datadir in a ramdisk.

Transactions per second for 32 benchmark threads, OLTP rw with 50% writes:

configuration 10.1.12 10.1.13
disk, flush=1 565.65 543.47
SSD, flush=1 5482.8 990.37
SSD, flush=2 7109.2 616.84
ramdisk 7750.6 7777.2
InnoDB, SSD, flush=2 6992.9 6986.9

The my.cnf used:

[mysqld]
#####non innodb options
max_connections = 200
table_open_cache = 400
query_cache_type = 0
key_buffer_size = 512M
#####innodb options
#ignore-builtin-innodb
#plugin-load=innodb=ha_innodb.so
innodb_file_per_table = true
innodb_open_files = 100
innodb_data_file_path = ibdata1:50M:autoextend
innodb_flush_log_at_trx_commit = 2
innodb_flush_method = O_DIRECT
innodb_log_buffer_size = 32M
innodb_log_file_size = 512M
innodb_log_files_in_group = 2
innodb_thread_concurrency = 0
innodb_buffer_pool_size = 512M
innodb_buffer_pool_instances = 8
#innodb_adaptive_hash_index_partitions = 8
#####performance-schema
performance-schema = true                                                                                     
performance-schema-consumer-events_waits_current=on                                                           
performance-schema-consumer-events_statements_current=off                                                     
performance-schema-consumer-statements_digest=off                                                             
performance-schema-instrument='%=off'                                                                         
performance-schema-instrument='wait/synch/mutex/%=on'                                                         
performance-schema-instrument='wait/synch/rwlock/%=on'

What I notice is a different disk usage pattern. With 10.1.12 many disk writes can be merged by the operating system. With 10.1.13 I see high disk utilisation while the number of writes is lower:

typical "iostat -mx" output for 10.1.12 (notice: md0 is a RAID-0 composed of 2 SSD sdc and sdd)

avg-cpu:  %user   %nice %system %iowait  %steal  %idle
          71.65    0.00   13.64    0.22    0.00   14.49
                                                                                                                                           
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdc               0.00   250.00    0.00  693.50     0.00    31.12    91.91     0.65    0.94    0.00    0.94   0.16  11.00
sdd               0.00   283.00    0.00  719.50     0.00    39.34   111.98     0.77    1.07    0.00    1.07   0.17  12.00
md0               0.00     0.00    0.00 1795.50     0.00    70.46    80.37     0.00    0.00    0.00    0.00   0.00   0.00

and here for 10.1.13:

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          12.64    0.00    3.08    1.54    0.00   82.73
                                                                                                                                           
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdc               0.00     1.50    0.00  316.00     0.00     2.60    16.86     0.43    1.37    0.00    1.37   1.37  43.20
sdd               0.00     7.50    0.00  289.00     0.00     2.49    17.66     0.38    1.32    0.00    1.32   1.26  36.40
md0               0.00     0.00    0.00  602.00     0.00     5.09    17.33     0.00    0.00    0.00    0.00   0.00   0.00

Notice: disk utilization is much higher for 10.1.13 and nearly no write requests merged (the wrqm/s column). So it looks like 10.1.13 is scheduling writes in different order.

I collected a lot more data and will look through it. Maybe I spot a pattern there.

The benchmark command line:

sysbench-0.5 --test=lua/oltp.lua --oltp-index-updates=6 \
--oltp-non-index-updates=6 --oltp_tables_count=8 \
--oltp-table-size=100000 --rand-type=uniform \
--num-threads=32 --oltp-read-only=off --report-interval=2 \
--mysql-socket=... --max-time=181 --max-requests=0 \
--mysql-user=root --percentile=95 run

Comment by Axel Schwenke [ 2016-05-04 ]

PS: the writes during the benchmark are probably only to the redo log. The combined size of all tables is 160MB, so it should fit perfectly into the 512MB buffer pool. Also the redo log has a combined size of 1GB and no checkpointing should happen during the benchmark run. Also the performance is rather flat during the 181 seconds benchmark runtime. If there would be checkpointing, it would manifest as degradation after a while.

Comment by Sergey Vojtovich [ 2016-05-04 ]

Attempted to reproduce it locally with semi-success. Apparently my local machine doesn't have sufficient CPU power to load SSD. There is evidence that 10.1.13 has increased IO though.

Comment by Sergey Vojtovich [ 2016-05-04 ]

I confirm reverting f71c45c71db8c7862fc50b8382ccdbff4772e258 gives 15% improvement on my machine. axel, could you double check?

Comment by Axel Schwenke [ 2016-05-04 ]

OK, here comes something that looks semi-conclusive. I repeated the test with only the redo log on SSD, innodb_flush_log_at_trx_commit = 2 and the remainder of the datadir in ramdisk. Again 10.1.13 shows bad performance:

10.1.12: 7180.1 tps @ 32 threads
10.1.13: 614.99 tps @ 32 threads

iostat output looks like this:

10.1.12:

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          76.01    0.00   13.55    0.13    0.00   10.31
 
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdc               0.00     0.00    0.00   45.00     0.00    13.23   602.13     0.53   11.78    0.00   11.78   1.16   5.20
sdd               0.00    10.50    0.00   65.50     0.00    13.53   423.08     0.47    7.18    0.00    7.18   0.67   4.40
md0               0.00     0.00    0.00   98.00     0.00    26.76   559.27     0.00    0.00    0.00    0.00   0.00   0.00

10.1.13:

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          11.72    0.00    2.90    1.55    0.00   83.83
 
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdc               0.00     4.50    0.00  308.50     0.00     1.39     9.22     0.46    1.49    0.00    1.49   1.49  46.00
sdd               0.00     1.00    0.00  249.00     0.00     1.12     9.20     0.35    1.40    0.00    1.40   1.39  34.60
md0               0.00     0.00    0.00  553.50     0.00     2.51     9.29     0.00    0.00    0.00    0.00   0.00   0.00

The main difference is the average request size (avgrq-sz). It's 560 blocks for 10.1.12 and less than 10 blocks for 10.1.13. Looks like 10.1.13 is doing redo log writes with very small blocks.

The numbers from SHOW GLOBAL STATUS show that log buffering works ok and also that 10.1.13 does no excessive syncing.

10.1.12:
1.28M trx (in 181 seconds)
3657 fsyncs, every 1.5MB resp every 350 trx
10M log write requests, 1.13M log writes, 0.88 log writes/trx

10.1.13:
0.11M trx (in 181 seconds)
815 fsyncs, every 0.6MB resp every 135 trx
940K log write requests, 99K log writes, 0.9 log writes/trx

Comment by Axel Schwenke [ 2016-05-04 ]

svoj - good catch!

I confirm that 10.1.13 with commit f71c45c71db8c7862fc50b8382ccdbff4772e258 (MDEV-9678) reverted does not show that regression. Performance is back at 10.1.12.

jplindst should now check why his commit has such severe side effects.

Comment by Jan Lindström (Inactive) [ 2016-05-06 ]

Fix should be already be on upcoming MariaDB 10.1.14:

commit 4ddb9deaf30bf3be664f3427f0b5393dc5a6c09c
Author: Jan Lindström <jan.lindstrom@mariadb.com>
Date: Wed Mar 30 14:59:25 2016 +0300

MDEV-9678: Data Directory bug
MDEV-9833: Log files are opened using O_DIRECT causing problems if block size != 512

Fix typo.

Generated at Thu Feb 08 07:38:16 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.