| Bug #65109 | Contention caused by buf_pool_zip_mutex | ||
|---|---|---|---|
| Submitted: | 26 Apr 2012 7:56 | Modified: | 15 Apr 2013 12:53 |
| Reporter: | Ben Mildren | Email Updates: | |
| Status: | No Feedback | Impact on me: | |
| Category: | MySQL Server: InnoDB Plugin storage engine | Severity: | S5 (Performance) |
| Version: | MySQL 5.1.61 | OS: | Linux (CentOS release 6.2 x86_64) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | buffer pool, contention, innodb, mutex | ||
[26 Apr 2012 8:54]
Valeriy Kravchuk
Please, send your my.cnf file content and SHOW GLOBAL STATUS output. I also wonder what your threads are doing when you see these waits, so SHOW FULL PROCESSLIST output at the moment of contention may be also useful. Check bug #51325 and bug #61188. I wonder if DROP TABLE and/or partitioned tables are involved in your case.
[26 Apr 2012 9:22]
Ben Mildren
Hi Valeriy The my.cnf is below. I'll also look to attach files with the output from show global status, show full processlist and show engine innodb status. Thanks Ben cat /etc/my.cnf [client] socket=/data/mysql-datadir/mysqld.sock [mysqld] datadir=/data/mysql-datadir tmpdir=/dev/shm/mysql-tmpdir back_log=75 thread_cache=32 connect_timeout=10 max_connections=5000 max_allowed_packet=128M socket=/data/mysql-datadir/mysqld.sock skip_name_resolve old_passwords=1 table_cache=16384 max_heap_table_size=256M tmp_table_size=256M key_buffer_size=32M default-table-type=innodb lower_case_table_names=1 collation_server=utf8_unicode_ci character_set_server=utf8 query_cache_size=0 query_cache_type=0 query_cache_limit=2M ignore-builtin-innodb plugin-load=innodb=ha_innodb_plugin.so;innodb_trx=ha_innodb_plugin.so;innodb_locks=ha_innodb_plugin.so;innodb_cmp=ha_innodb_plugin.so;innodb_cmp_reset=ha_innodb_plugin.so;innodb_cmpmem=ha_innodb_plugin.so;innodb_cmpmem_reset=ha_innodb_plugin.so innodb_thread_concurrency=0 innodb_lock_wait_timeout=50 innodb_buffer_pool_size=64G innodb_log_buffer_size=512M innodb_log_files_in_group=2 innodb_log_file_size=1G innodb_file_per_table innodb_open_files=2048 innodb_stats_on_metadata=0 log-warnings=2 general_log=0 general_log_file=/data/mysql-datadir/general.log slow_query_log=1 slow_query_log_file=/data/mysql-datadir/slow.log long_query_time=1
[26 Apr 2012 9:24]
Ben Mildren
show global status
Attachment: globalstatus.txt (text/plain), 17.43 KiB.
[26 Apr 2012 9:56]
Ben Mildren
There's no partitioning for any database tables on this server. In terms of dropping tables I do see some temporary tables being dropped when the output has been captured.
[15 Mar 2013 12:53]
MySQL Verification Team
Hi Ben, Quite frankly, we need more useful information. A few relevant samples from poor mans profiler would be good to see during the contention problem. http://poormansprofiler.org/ Also, please consider using 5.5 or 5.6, who have innodb_buffer_pool_instances, which certainly will help on a 64GB buffer pool.
[16 Apr 2013 1:00]
Bugs System
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".
Description: We're seeing a lot of semaphore waits that seem to center around the buf_pool_zip_mutex (Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891). The waits can be observed for both user threads and the main innodb_thread. The waits all seem to relate to relate to acquiring the buf_pool_mutex with various calls to buf_pool_mutex_enter(). buf_pool_mutex_enter() references buf_pool_zip_mutex to ensure the buf_pool_zip_mutex isn't held when the buf_pool_mutex is acquired. do { \ ut_ad(!mutex_own(&buf_pool_zip_mutex)); \ mutex_enter(&buf_pool_mutex); \ } while (0) Example of semaphore waits: Engine InnoDB Status -------------------- ===================================== 120425 2:22:01 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 24 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 5162561 1_second, 5150701 sleeps, 516239 10_second, 1208 background, 1207 flush srv_master_thread log flush and writes: 5280783 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 23497784, signal count 64975938 --Thread 140655347103488 has waited at row/row0purge.c line 565 for 1.00 seconds the semaphore: S-lock on RW-latch at 0x7ffdcfa2c960 created in file dict/dict0dict.c line 695 a writer (thread id 140655333201664) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file row/row0purge.c line 565 Last time write locked in file row/row0mysql.c line 3067 --Thread 140642130106112 has waited at buf/buf0buf.c line 1618 for 0.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140643277616896 has waited at buf/buf0buf.c line 1618 for 0.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140642262152960 has waited at buf/buf0buf.c line 1618 for 0.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140643323778816 has waited at buf/buf0buf.c line 1618 for 0.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140643412436736 has waited at buf/buf0buf.c line 1618 for 0.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140643309528832 has waited at buf/buf0buf.c line 1618 for 0.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 Mutex spin waits 328380909, rounds 1684800659, OS waits 20064111 RW-shared spins 12516813, OS waits 1861635; RW-excl spins 3709620, OS waits 760489 Spin rounds per wait: 5.13 mutex, 7.17 RW-shared, 30.43 RW-excl Engine InnoDB Status -------------------- ===================================== 120425 6:40:02 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 8 seconds ----------------- BACKGROUND THREAD ----------------- srv_master_thread loops: 5175901 1_second, 5164040 sleeps, 517572 10_second, 1214 background, 1213 flush srv_master_thread log flush and writes: 5294999 ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 23635762, signal count 65396424 --Thread 140643307521792 has waited at buf/buf0buf.c line 1618 for 1.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140642306307840 has waited at buf/buf0buf.c line 1618 for 1.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140643411232512 has waited at buf/buf0buf.c line 1618 for 1.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140642261149440 has waited at buf/buf0buf.c line 1618 for 1.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 --Thread 140642179114752 has waited at buf/buf0buf.c line 1618 for 1.00 seconds the semaphore: Mutex at 0x7ffdcfa2c8a0 created file buf/buf0buf.c line 891, lock var 1 waiters flag 1 Mutex spin waits 331411361, rounds 1698321539, OS waits 20169373 RW-shared spins 12613812, OS waits 1877579; RW-excl spins 3741369, OS waits 769689 Spin rounds per wait: 5.12 mutex, 7.17 RW-shared, 30.43 RW-excl How to repeat: The system is running MySQL 5.1.61-community-log MySQL Community Server (for unknown-linux-gnu (x86_64) using readline 5.1) on CentOS 6.2 (x86_64). The profile of the server sees ~200 identical schemas accessed by individual customer connections, all tables are innodb, there are usually ~2000 connections to the server. We do see some spikes in active threads due to the table_open_cache and threads temporarily stalling in an Opening tables / Closing tables state.