innodb_dict_size_limit tries to do LRU eviction of an index that is in use

[Ovais Tariq]

The Percona Server version is 5.5.33-31.1.

The server crashed while doing an UNDO of a long running UPDATE query that had modified thousands of rows. The assertion raised was as follows:

131110 14:09:59 InnoDB: Assertion failure in thread 16 in file sync0rw.c line 319
InnoDB: Failing assertion: lock->lock_word == X_LOCK_DECR
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.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:09:59 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=0
max_threads=5002
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 10952556 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
/mysql/bin/mysqld'my_print_stacktrace+0x1e [0xa5915e]
/mysql/bin/mysqld'handle_fatal_signal+0x3d6 [0x9164d6]
/lib/amd64/libc.so.1'__sighndlr+0x6 [0xfffffd7fff29d5f6]
/lib/amd64/libc.so.1'call_user_handler+0x1db [0xfffffd7fff29044b]
/lib/amd64/libc.so.1'_lwp_kill+0xa [0xfffffd7fff2a473a] [Signal 6 (ABRT)]
/lib/amd64/libc.so.1'raise+0x20 [0xfffffd7fff23d840]
/lib/amd64/libc.so.1'abort+0x60 [0xfffffd7fff217ea0]
/mysql/bin/mysqld'0x6f909b [0xaf909b]
/mysql/bin/mysqld'dict_index_remove_from_cache+0x120 [0xb66110]
/mysql/bin/mysqld'dict_table_remove_from_cache+0x70 [0xb66230]
/mysql/bin/mysqld'dict_table_LRU_trim+0x10d [0xb6655d]
/mysql/bin/mysqld'dict_table_get_on_id+0x189 [0xb666f9]
/mysql/bin/mysqld'row_undo_mod+0x5f [0xbf863f]
/mysql/bin/mysqld'row_undo_step+0x68 [0xbf02b8]
/mysql/bin/mysqld'que_run_threads+0x578 [0xbe5638]
/mysql/bin/mysqld'trx_rollback_or_clean_recovered+0x48b [0xb06a9b]
/mysql/bin/mysqld'trx_rollback_or_clean_all_recovered+0x3f [0xb070cf]
/lib/amd64/libc.so.1'_thrp_setup+0x8a [0xfffffd7fff29d21a]
/lib/amd64/libc.so.1'_lwp_start+0x0 [0xfffffd7fff29d530]
Please read http://dev.mysql.com/doc/refman/5.1/en/resolve-stack-dump.html
and follow instructions on how to resolve the stack trace.
Resolved stack trace is much more helpful in diagnosing the
problem, so please do resolve it
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.

And the resolved stack trace is as follows:
af909b rw_lock_free_func + 411
b66110 dict_index_remove_from_cache + 288
b66230 dict_table_remove_from_cache + 112
b6655d dict_table_LRU_trim + 269
b666f9 dict_table_get_on_id + 393
bf863f row_undo_mod + 95
bf02b8 row_undo_step + 104
be5638 que_run_threads + 1400
b06a9b trx_rollback_or_clean_recovered + 1163
b070cf trx_rollback_or_clean_all_recovered + 63

This is how data dictionary has been limited:
innodb_dict_size_limit = 256M

[Ovais Tariq (ovais-tariq)]

I also find the below semaphore waits possibly related to LRU eviction of index.

InnoDB: Warning: a long semaphore wait:
--Thread 22 has waited at row0purge.c line 682 for 241.00 seconds the semaphore:
Mutex at 27294d8a8 '&dict_sys->mutex', lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
131111 0:41:17 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 15 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 36034 1_second, 36033 sleeps, 3601 10_second, 442 background, 442 flush
srv_master_thread log flush and writes: 37289
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 392362, signal count 406553
--Thread 22 has waited at row0purge.c line 682 for 246.00 seconds the semaphore:
Mutex at 27294d8a8 '&dict_sys->mutex', lock var 1
waiters flag 1
--Thread 27 has waited at btr0sea.c line 1778 for 0.0000 seconds the semaphore:
X-lock (wait_ex) on RW-latch at e52d77d8 'btr_search_latch_part[i]'
a writer (thread id 27) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.c line 1420
Last time write locked in file /var/tmp/tmp.a5aenR/Percona-Server-5.5.33-rel31.1/storage/innobase/btr/btr0sea.c line 1374
Mutex spin waits 6117445, rounds 21430759, OS waits 326581
RW-shared spins 54246, rounds 639853, OS waits 16738
RW-excl spins 253164, rounds 1848521, OS waits 44718
Spin rounds per wait: 3.50 mutex, 11.80 RW-shared, 7.30 RW-excl

Purge operation is waiting on the dict_sys->mutex to be able to do purge of an undo log record, while it appears that the dict_sys->mutex is being held as part of the data dictionary LRU eviction process:

- storage/innobase/dict/dict0dict.c
1940 void
1941 dict_index_remove_from_cache(
...
1953 ut_ad(mutex_own(&(dict_sys->mutex)));

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3069