MySQL Bugs: #45988: InnoDB: Error: semaphore wait has lasted

Bug #45988	InnoDB: Error: semaphore wait has lasted > 600 seconds
Submitted:	7 Jul 2009 5:23	Modified:	8 Sep 2009 9:31
Reporter:	Pavel Shevaev	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	mysql-5.0.70-r1	OS:	Linux (2.6.24-gentoo-r7 x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	innodb semaphore

Description:
For a couple of days MySQL crashes every night with the following error:

InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
090707  3:42:25InnoDB: Assertion failure in thread 47299103967568 in file srv0srv.c line 2097
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html
InnoDB: about forcing recovery.
090707  3:42:25 - mysqld got signal 11 ;

How to repeat:
I really don't know how to repeat it since it happens pretty sporadically. There is no higload on the server, ganglia reported the following MySQL statistics on the moment of crash:

mysql_max_used_connections 8
mysql_com_select 2
mysql_com_insert 0
mysql_com_delete 0
mysql_threads_connected 2
mysql_slow_queries 0

I also browsed mysqld.err logs for some time and discovered that the following warning happens periodically:

InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 47299114490192 has waited at ./../include/trx0undo.ic line 127 for 911.00 seconds the semaphore:
X-lock on RW-latch at 0x2b04aa55da78 created in file buf0buf.c line 497
a writer (thread id 47299114490192) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1
Last time read locked in file buf0flu.c line 585
Last time write locked in file ./../include/trx0undo.ic line 127
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

INNODB MONITOR OUTPUT

Attachment: mysqld.err.last (application/octet-stream, text), 4.48 KiB.

Suspicious warnings just before the crash

Attachment: mysqld.err.before (application/octet-stream, text), 465.85 KiB.

Thank you for the problem report. Looks like this happens during COMMIT when flushing a lot of pages to disk. Do you have some huge transactions changing a lot of rows? See also http://forums.mysql.com/read.php?22,116765,118626.

Send your my.cnf file content (or SHOW GLOBAL VARIABLES results), please.

my.cnf

Attachment: my.cnf (application/octet-stream, text), 4.13 KiB.

> Do you have some huge transactions changing a lot of rows?

Well, first of all what is a huge transaction? :) In my app I do have some transactions but they are all pretty simple, mostly: UPDATE .. SET .. WHERE id=N and some INSERT queries. No ALTER TABLE queries at all.

BTW, I have only one database with ~20 tables which all have about ~75k records in total.

$ mysql -e"SHOW GLOBAL VARIABLES" -B

auto_increment_increment	1
auto_increment_offset	1
automatic_sp_privileges	ON
back_log	50
basedir	/usr/
binlog_cache_size	32768
bulk_insert_buffer_size	8388608
character_set_client	utf8
character_set_connection	utf8
character_set_database	utf8
character_set_filesystem	binary
character_set_results	utf8
character_set_server	utf8
character_set_system	utf8
character_sets_dir	/usr/share/mysql/charsets/
collation_connection	utf8_general_ci
collation_database	utf8_general_ci
collation_server	utf8_general_ci
completion_type	0
concurrent_insert	1
connect_timeout	10
datadir	/var/lib/mysql/
date_format	%Y-%m-%d
datetime_format	%Y-%m-%d %H:%i:%s
default_week_format	0
delay_key_write	ON
delayed_insert_limit	100
delayed_insert_timeout	300
delayed_queue_size	1000
div_precision_increment	4
keep_files_on_create	OFF
engine_condition_pushdown	OFF
expire_logs_days	0
flush	OFF
flush_time	0
ft_boolean_syntax	+ -><()~*:""&|
ft_max_word_len	84
ft_min_word_len	4
ft_query_expansion_limit	20
ft_stopword_file	(built-in)
group_concat_max_len	1024
have_archive	NO
have_bdb	NO
have_blackhole_engine	NO
have_compress	YES
have_crypt	YES
have_csv	NO
have_dynamic_loading	YES
have_example_engine	NO
have_federated_engine	NO
have_geometry	YES
have_innodb	YES
have_isam	NO
have_merge_engine	YES
have_ndbcluster	NO
have_openssl	DISABLED
have_ssl	DISABLED
have_query_cache	YES
have_raid	NO
have_rtree_keys	YES
have_symlink	YES
hostname	gamed.zveriki.com
init_connect	
init_file	
init_slave	
innodb_additional_mem_pool_size	2097152
innodb_autoextend_increment	8
innodb_buffer_pool_awe_mem_mb	0
innodb_buffer_pool_size	16777216
innodb_checksums	ON
innodb_commit_concurrency	0
innodb_concurrency_tickets	500
innodb_data_file_path	ibdata1:10M:autoextend:max:128M
innodb_data_home_dir	
innodb_adaptive_hash_index	ON
innodb_doublewrite	ON
innodb_fast_shutdown	1
innodb_file_io_threads	4
innodb_file_per_table	ON
innodb_flush_log_at_trx_commit	1
innodb_flush_method	
innodb_force_recovery	0
innodb_lock_wait_timeout	50
innodb_locks_unsafe_for_binlog	OFF
innodb_log_arch_dir	
innodb_log_archive	OFF
innodb_log_buffer_size	8388608
innodb_log_file_size	5242880
innodb_log_files_in_group	2
innodb_log_group_home_dir	./
innodb_max_dirty_pages_pct	90
innodb_max_purge_lag	0
innodb_mirrored_log_groups	1
innodb_open_files	300
innodb_rollback_on_timeout	OFF
innodb_support_xa	ON
innodb_sync_spin_loops	20
innodb_table_locks	ON
innodb_thread_concurrency	8
innodb_thread_sleep_delay	10000
interactive_timeout	28800
join_buffer_size	131072
key_buffer_size	16777216
key_cache_age_threshold	300
key_cache_block_size	1024
key_cache_division_limit	100
language	/usr/share/mysql/english/
large_files_support	ON
large_page_size	0
large_pages	OFF
lc_time_names	en_US
license	GPL
local_infile	ON
locked_in_memory	OFF
log	OFF
log_bin	ON
log_bin_trust_function_creators	OFF
log_error	/var/log/mysql/mysqld.err
log_queries_not_using_indexes	OFF
log_slave_updates	OFF
log_slow_queries	OFF
log_warnings	1
long_query_time	10
low_priority_updates	OFF
lower_case_file_system	OFF
lower_case_table_names	0
max_allowed_packet	1048576
max_binlog_cache_size	18446744073709547520
max_binlog_size	1073741824
max_connect_errors	10
max_connections	100
max_delayed_threads	20
max_error_count	64
max_heap_table_size	16777216
max_insert_delayed_threads	20
max_join_size	18446744073709551615
max_length_for_sort_data	1024
max_prepared_stmt_count	16382
max_relay_log_size	0
max_seeks_for_key	18446744073709551615
max_sort_length	1024
max_sp_recursion_depth	0
max_tmp_tables	32
max_user_connections	0
max_write_lock_count	18446744073709551615
multi_range_count	256
myisam_data_pointer_size	6
myisam_max_sort_file_size	9223372036853727232
myisam_recover_options	OFF
myisam_repair_threads	1
myisam_sort_buffer_size	8388608
myisam_stats_method	nulls_unequal
net_buffer_length	8192
net_read_timeout	30
net_retry_count	10
net_write_timeout	60
new	OFF
old_passwords	OFF
open_files_limit	1024
optimizer_prune_level	1
optimizer_search_depth	62
pid_file	/var/run/mysqld/mysqld.pid
plugin_dir	
port	3306
preload_buffer_size	32768
protocol_version	10
query_alloc_block_size	8192
query_cache_limit	1048576
query_cache_min_res_unit	4096
query_cache_size	0
query_cache_type	ON
query_cache_wlock_invalidate	OFF
query_prealloc_size	8192
range_alloc_block_size	4096
read_buffer_size	262144
read_only	OFF
read_rnd_buffer_size	524288
relay_log	
relay_log_index	
relay_log_info_file	relay-log.info
relay_log_purge	ON
relay_log_space_limit	0
rpl_recovery_rank	0
secure_auth	OFF
secure_file_priv	
server_id	1
skip_external_locking	ON
skip_networking	OFF
skip_show_database	OFF
slave_compressed_protocol	OFF
slave_load_tmpdir	/tmp/
slave_net_timeout	3600
slave_skip_errors	OFF
slave_transaction_retries	10
slow_launch_time	2
socket	/var/run/mysqld/mysqld.sock
sort_buffer_size	524288
sql_big_selects	ON
sql_mode	
sql_notes	ON
sql_warnings	OFF
ssl_ca	
ssl_capath	
ssl_cert	
ssl_cipher	
ssl_key	
storage_engine	MyISAM
sync_binlog	0
sync_frm	ON
system_time_zone	MSD
table_cache	64
table_lock_wait_timeout	50
table_type	MyISAM
thread_cache_size	0
thread_stack	262144
time_format	%H:%i:%s
time_zone	SYSTEM
timed_mutexes	OFF
tmp_table_size	33554432
tmpdir	/tmp/
transaction_alloc_block_size	8192
transaction_prealloc_size	4096
tx_isolation	REPEATABLE-READ
updatable_views_with_limit	YES
version	5.0.70-log
version_comment	Gentoo Linux mysql-5.0.70-r1
version_compile_machine	x86_64
version_compile_os	pc-linux-gnu
wait_timeout	28800

I'm getting an almost identical issue under 5.0.83 on Windows XP.

Please, send the results of

free

Linux command. I wonder how much (free) RAM do you have as I had noted this:

innodb_buffer_pool_size = 16M

in your my.cnf. This is too small for most practical cases...

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Still feedback is needed.

I think I've spotted the use case when this happens. I have a log rotation routine running by cron every night and when a really large log file is processed(about 6GB) it seems the IO subsystem becomes the real bottleneck. I have ganglia monitoring and it shows that mysqld crashes with such error during this log rotation period...

This is a duplicate of bug #47183

Susanne Ebrecht....WTF? SERIOUSLY....W.T.F?

How can an old bug reported with lots of feedback from 7 July be marked as a duplicate of a new bug from 8 September which is marked as "Needs Feedback"?

Please explain?