Wednesday Jul 23, 2008
Wednesday Jul 23, 2008
While comparing sysbench runs using two different versions of MySQL 5.1, I noticed a big difference in the system utilization. One version had much more idle time than the other. This difference was much more apparent with high thread counts on machines with lots of CPU. A look at the system calls showed a large number of lwp_park system calls. That is, threads were being put to sleep.
bash # $ dtrace -qn 'syscall:::entry{@c[probefunc]=count()}' -n tick-5s'{trunc(@c, 10);exit(0)}'
p_online 1535
ioctl 2255
fcntl 6134
priocntlsys 6462
write 6492
read 12775
yield 19065
gtime 313927
pollsys 321074
lwp_park 951749
Investigating why threads are being parked showed a very interesting
stacktrace
libc.so.1`__lwp_park+0x10
libc.so.1`cond_wait_queue+0x28
libc.so.1`cond_wait+0x10
libc.so.1`pthread_cond_wait+0x8
mysqld`os_event_wait_low+0x3c
mysqld`sync_array_wait_event+0x1c0
mysqld`mutex_spin_wait+0x1c4
mysqld`mutex_enter_func+0x1c
mysqld`rw_lock_x_lock_func+0x3b4
mysqld`mtr_x_lock_func+0x10
mysqld`fsp_get_available_space_in_free_extents+0x30
mysqld`int ha_innobase::info(unsigned)+0x164
mysqld`bool make_join_statistics(JOIN*,TABLE.. +0x180
mysqld`int JOIN::optimize()+0x670
mysqld`bool mysql_select(THD*,Item***,TABLE_.. +0x224
mysqld`bool handle_select(THD*,st_lex*,selec.. +0xc4
mysqld`bool execute_sqlcom_select(THD*,TABLE.. +0x1c8
mysqld`int mysql_execute_command(THD*)+0x380
mysqld`bool Prepared_statement::execute(Stri.. +0x29c
mysqld`bool Prepared_statement::execute_loop.. +0xbc
Looking at make_join_statistics() we see that it calls
ha_innobase::info() with HA_STATUS_VARIABLE |
HA_STATUS_NO_LOCK. A quick search for the definition of
HA_STATUS_NO_LOCK shows
/* assuming the table keeps shared actual copy of the 'info' and local, possibly outdated copy, the following flag means that it should not try to get the actual data (locking the shared structure) slightly outdated version will suffice */ #define HA_STATUS_NO_LOCK 2So the mysql server is requesting ha_innobase::info() to not hold a lock, and it is being ignored by ha_innobase::info()!.
I compared against MySQL 5.0 and saw that this particular lock was not held when ha_innobase::info() was called. Searching through the commit logs I found that this was introduced by Bug#32440.
Quickly hacking the code to revert to the old behaviour gave a big boost in performance. Hence I filed Bug #38185 ha_innobase::info can hold locks even when called with HA_STATUS_NO_LOCK. Luckily its a very small change and a fix is already in progress.
Moral of the story? A simple contended lock can bring down your performance by quite a lot.
Neelakanth,
awesome work! It's always impressive to see what the performance dudes at Sun can do to improve speed and scalability of MySQL. I know a lot of users will be very happy about this!
--Zack
Posted by ZUrlocker on July 24, 2008 at 09:03 AM PDT #