Large number of MYSQL connections get time out or time wait

Not sure how frequently people run to this issue. Sometime when you suddenly have a flood MYSQL connection request to MYSQL servers in a very short time. You might get connection timeout errors or see a lot of connection in time wait state. 

This is because MYSQL can't serve the connection fast enough and it's default listening queue size is rather small at 50.

You can set MYSQL variable back_log to lift this limit.

However this require a MYSQL server bounce.

back_log
 

Command-Line Format	--back_log=#
Option-File Format	back_log
Option Sets Variable	Yes, back_log
Variable Name	back_log
Variable Scope	Global
Dynamic Variable	No
	Permitted Values
	Type	numeric
	Default	50
	Range	1 .. 65535

The number of outstanding connection requests MySQL can have. This comes into play when the main MySQL thread gets very many connection requests in a very short time. It then takes some time (although very little) for the main thread to check the connection and start a new thread. The back_log value indicates how many requests can be stacked during this short time before MySQL momentarily stops answering new requests. You need to increase this only if you expect a large number of connections in a short period of time.
In other words, this value is the size of the listen queue for incoming TCP/IP connections. Your operating system has its own limit on the size of this queue. The manual page for the Unix listen() system call should have more details. Check your OS documentation for the maximum value for this variable. back_log cannot be set higher than your operating system limit.

In response to: What is the query plan for a running query?

Mark in Facebook recently posted a great article about how to peek the query plan for a running query. 
What is the query plan for a running query?
Because there's number of cases where you can't use explain to find out which plan the running query is using.


One reason Mark pointed out in his article is when query using temporary table in join condition, you don't have the temporary table definition as well as the actual data got populated in it. Even you could get the create table statement for the temp table, the data you populated into it may not same as that running query depends on how dynamic your data is.


Another reason I can think of is similar to bind variable peeking issue in Oracle database. When you have skew in your data, different bind variable could result different SQL plan as demonstrated below. 
So if that case, explain can't really help you unless you know what bind variable was used at the time.


mysql> select table_type, count(*) from test_plan group by table_type;
+-------------+----------+
| table_type  | count(*) |
+-------------+----------+
| BASE TABLE  |     4910 | 
| SYSTEM VIEW |       95 | 
+-------------+----------+
2 rows in set (0.01 sec)


mysql> explain select * from test_plan where table_type='BASE TABLE' \G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: test_plan
         type: ALL
possible_keys: table_type_inx
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 5017
        Extra: Using where
1 row in set (0.00 sec)


mysql> explain select * from test_plan where table_type='SYSTEM VIEW' \G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: test_plan
         type: ref
possible_keys: table_type_inx
          key: table_type_inx
      key_len: 194
          ref: const
         rows: 95
        Extra: Using where
1 row in set (0.00 sec)

Very slow query with high number of Rows_examined

We had some interesting problem on one production MYSQL server today.
One developer reported there's a delete statement taking very long time to run on small tables. 
The three tables involved this query, category_group, tmp_category_group category_group_info have 7400, 7600 and 25 rows respectively.
While checking slow query logs, shockingly I found the query has 3.8MM examined rows. Change the query to select statement will yield the same result.


# Query_time: 9  Lock_time: 0  Rows_sent: 0  Rows_examined: 3809728
delete from category_group where group_id = (select group_id from category_group_info x where x.group_name = 'Storylines') and category_id in ( select category_id from tmp_category_group cg where group_id = (select group_id from category_group_info x where x.group_name = 'KidsCharacter'));


# Query_time: 8  Lock_time: 0  Rows_sent: 0  Rows_examined: 3810182
select * from category_group where group_id = (select group_id from category_group_info x
 where x.group_name = 'Storylines') and category_id in
 ( select category_id from tmp_category_group cg where group_id =
 (select group_id from category_group_info x where x.group_name = 'KidsCharacter'));


The explain plan doesn't provide much help.

mysql> explain select * from category_group where group_id = (select group_id from category_group_info x where x.group_name = 'Storylines') and category_id in ( select category_id from tmp_category_group cg where group_id = (select group_id from category_group_info x where x.group_name = 'KidsCharacter'));

+----+--------------------+----------------+------+---------------+----------+---------+-------+------+--------------------------+

| id | select_type        | table          | type | possible_keys | key      | key_len | ref   | rows | Extra                    |

+----+--------------------+----------------+------+---------------+----------+---------+-------+------+--------------------------+

|  1 | PRIMARY            | category_group | ref  | group_id      | group_id | 4       | const |  501 | Using where; Using index | 

|  3 | DEPENDENT SUBQUERY | cg             | ALL  | NULL          | NULL     | NULL    | NULL  | 7396 | Using where              | 

|  4 | SUBQUERY           | x              | ALL  | NULL          | NULL     | NULL    | NULL  |   25 | Using where              | 

|  2 | SUBQUERY           | x              | ALL  | NULL          | NULL     | NULL    | NULL  |   25 | Using where              | 

+----+--------------------+----------------+------+---------------+----------+---------+-------+------+--------------------------+

4 rows in set (0.01 sec)

After extensive testing, I figure out the query will run fast if we take off where clause of this subquery.

select category_id from tmp_category_group cg where group_id = ...

That means the query run much faster on whole table of tmp_category_group than having a predicate. That doesn't make sense right?
That end up leading me to add an index on group_id of tmp_category_group and the query running lightening fast now. 


Could this be some sort of Bug?

mysql> select * from category_group where group_id = (select distinct group_id from category_group_info x where x.group_name = 'Storylines') and category_id in ( select distinct category_id from tmp_category_group cg where group_id = (select distinct group_id from category_group_info x where x.group_name = 'KidsCharacter'));
Empty set (0.31 sec)

mysql> delete from category_group
-> where group_id = (select group_id from category_group_info x where x.group_name = 'Storylines')
-> and category_id in (
-> select category_id
-> from tmp_category_group cg
-> where group_id = (select group_id from category_group_info x where x.group_name = 'KidsCharacter'));
Query OK, 0 rows affected (0.36 sec) 

How Seconds_behind_master is computed

Found a very good explanation of how Seconds_behind_master is computed in this bug report.

http://bugs.mysql.com/bug.php?id=2826


Here's how Seconds_behind_master is computed.

* When the slave connects to the master (when the slave I/O thread connects to the
master),
it does a = SELECT UNIX_TIMESTAMP() on master,
and b= SELECT UNIX_TIMESTAMP() on slave, and computes c=b-a.

* Every statement executed on the master is stored on the master's binary log together
with the timestamp when it was executed.

* So when the slave SQL thread reads a statement from the binary log, it executes it and
then it does:

seconds_behind_master= SELECT UNIX_TIMESTAMP() on slave
- timestamp of the master's binary log event
- c

2010 Oracle Open World - MYSQL Sunday

Just come back from MYSQL Sunday sessions of 2010 Oracle Open World. Share some thoughts while memory is still fresh, the two Facebook sessions are pretty good. Harrison shared some insight of how Facebook using MYSQL replication from operation perspective. Mark's session is similar to the one he did in MYSQL Conf this April.

Global Transaction IDs
  We recently experienced some network issue between our Data Center and Cloud provider. Finding the right binlog position for slaves in cloud after network issue some time can be tricky. And in many cases, the relylog is totally toasted, we need to change master to previous position based on exec_master_log_pos. The thing is we can't guarantee the integrity of slave data because some corrupted statement could get applied. In most case, the slave SQL thread stopped because it reads invalid statement from corrupted relylog. Who's to say there's no corrupted 'valid' statement applied?
  Well, we are still considered lucky in this case as master is operational and all binlogs are in good shape. Image if Master crashes and we need to prompt one slave to new master and sync other slaves to the new master. Theoretically we need to find a slave that closest to master and prompt it to master and then sync the rest slaves. It’s easy saying than to be done in real world crashes. Because MYSQL didn’t provide an easy mapping between master BINLOG position and slave Rely LOG position.  On top of that, each slave maintain its own rely log that means the rely log number and position can’t be shared globally among slaves. This makes the tasks to sync all slaves with new master particularly difficult if not impossible. What Facebook and Google MYSQL team was using is a Global Transaction ID (similar to SCN in Oracle), they use this Global Transaction ID to map to rely log and binlog position, this makes slave master synchronization a lot easier. Unfortunately, this Global Transaction ID only exists in Mysql Google patch and Facebook patch. Not in main line MySQL.

DRBD Master 
   The second thought is derived from first, switch between master and slaves is not an easy task especially with multi-slaves setup. It’s particularly difficult when master crashes instead of graceful shutdown. Even with Global Transaction ID it’s still involve manual work and prolonged downtime. So some users actually setup protected masters using DRBD. http://www.drbd.org/  DRBD is a pair of DB in a cluster that has block to block mirroring. If case of crashes, the other one can quickly take over with minimum data loss.
Thus we got master protected and guaranteed. We can then build slaves against the cluster. Greatly reduced the need to synchronize slaves as master pretty much crash free.
Of course this is not solution for everything, by eliminating the need to switch between master and slave it also loss some advantage of master slave rotation. For example, we can’t run expensive DDL like ALTER TABLE on slaves and switch to master and do the same DDL on former master. Because in this case, slave is not in the same league as master.

Seconds behind master
   I think most of you already noticed this is not a reliable indicator to determine if slave is running behind master. The problem is because this indicator is not a heartbeat indicator. It’s only updated when there’s update events received by slaves. So Slave will happily register 0 seconds behind master even after it’s not getting any event for a long time. In some case it might be legitimate that there’s really no event on master and a lot of time it’s because we have network issue between master and slave, the connection simply got dropped. The solution is update a heartbeat table and check the difference manually. MySQL 5.5 has built in Heartbeat mechanism which definitely a big plus for MYSQL replication.

log-bin.~rec~ in BINLOG directory

Anyone noticed there's a log-bin.~rec~ file under MySQL BinLog directory?

I didn't notice this file until recently our rsync script that syncing 
Binlog to backup server failed with this error.

building file list ... rsync: link_stat 
"/DB/MYPROD/arch/MPROD_arch.~rec~" failed: 
No such file or directory (2) rsync error: 
some files could not be transferred (code 23) at main.c(892)
[sender=2.6.8]

A little research revealed that this is actually a by product of MySQL bug fix.
It's a temporary register file MySQL used to record BinLog files before adding or purging them.
It only exists briefly in the BinLOG dir, our rsync script was lucky enough to catch it and failed to sync it before it's gone.

http://bugs.mysql.com/bug.php?id=45292

To fix these issues, we record the files to be purged or created before really removing or adding them. So if a failure happens such records can be used to automatically remove dangling files.
The new steps might be outlined as follows:
(purge routine - sql/log.cc - MYSQL_BIN_LOG::purge_logs)
1 - register the files to be removed in the log-bin.~rec~ placed in the data directory.
2 - update the log-bin.index.
3 - flush the log-bin.index.
4 - delete the log-bin.~rec~.
(create routine - sql/log.cc - MYSQL_BIN_LOG::open)
1 - register the file to be created in the log-bin.~rec~ placed in the data directory.
2 - open the new log-bin.
3 - update the log-bin.index.
4 - delete the log-bin.~rec~.
(recovery routine - sql/log.cc - MYSQL_BIN_LOG::open_index_file)
1 - open the log-bin.index.
2 - open the log-bin.~rec~.
3 - for each file in log-bin.~rec~.
3.1 Check if the file is in the log-bin.index and if so ignore it.
3.2 Otherwise, delete it.
The third issue can be described as follows.
The purge operation was allowing to remove a file in use thus leading to the loss of data and possible inconsistencies between the master and slave. Roughly, the routine was only taking into account the dump threads and so if a slave was not connect the file might be delete even though it was in use.

'Unknown command' from loading mysqldump file

If so happen when you load a mysqldump file get these errors,

mysql < mysqldump_021010.sql
ERROR at line 5122: Unknown command 'ufffd'

You need to increase max_allowed_packet and try again.
The error itself is not very informative, actually somewhat misleading.
It's probably because you have big insert statement in your dumpfile the exceeded the limit and mysql interpret row data after that as command.

In my case, running mysql --max_allowed_packet=64M fixed the issue. The default is 16M in mysql 5.0 and 5.1

Actually according to MySQL doc, it is safe to increase the value of this variable because the extra memory is allocated only when needed. So 1G here we go.

MySQL Cacti Templates finally working

After days of configuration, my Cacti MySQL template finally working.
At first, after I loaded MySQL template, the graphy is not updated by poller. It turns out MySQL template require spine poller than regular CMD poller. The spine poller has a bug , you will likely to get following error:

08/06/2008 12:20:02 PM - SPINE: Poller[0] ERROR: A database insert failed! Error:'1064', SQL Fragment:'INSERT INTO poller_output (local_data_id, rrd_name, time, output) VALUES (3,'mem_buffers','2008-08-06 12:20:01','70456'),(4,'mem_swap','2008-08-06 12:20:01','8388376'),(5,'','2008-08-06 12:20:01','1min:0.27 5min:0.29 10min:0.23'),(6,'users','2008-08-06 12:20:01','3'),(7,'proc','2008-08-06 12:20:01','140'),(8,'','2008-08-06 12:20:01','Key_read_requests:190457 Key_reads:148 Key_write_requests:79884 Key_writes:27194 history_list:3 innodb_transactions:479840 read_views:1 current_transactions:1 locked_transactions:0 active_transactions:0 pool_size:32000 free_pages:0 database_pages:31999 modified_pages:0 pages_read:5187008 pages_created:1153894 pages_written:6257069 file_fsyncs:185447 file_reads:4606447 file_writes:3070647 log_writes:90720 pending_aio_log_ios:0 pending_aio_sync_ios:0 pending_buf_pool_flushes:0 pending_chkp_writes:0 pending_ibuf_aio_reads:0 pending_log_flushes:0 pending_log_writes:0 pending_normal_aio_reads:0 pending_normal_aio_writes:0 ibuf_inserts:277316 ibuf_merged:277316 ibuf_merges:7235 spin_w'


the problem is default query statement buffer for insert is set to small, I manually changes buffer size in spine.h and recompiled spine.

/* #define BUFSIZE 1024 */
#define BUFSIZE 65535


Everything seems to be working after this last twick.

Here's some screen shots,

MySQL Cacti Templates installation

I was trying to install MySQL Cacti monitoring tool last few days. This is a cool RRDTOOL based monitoring package that can be downloaded from here.

http://code.google.com/p/mysql-cacti-templates

To get the template working, it requires Cacti to be installed. http://www.cacti.net/

Cacti is design around RRDTOOLs http://oss.oetiker.ch/rrdtool/

that in turn require many other packages installed,

pkgconfig, zlib, libpng, freetype, LibXML2, fontconfig, Pixman, Cairo, Glib, Pango

That's right every single of these packages need to downloaded, compiled and installed successfully.

The best way to enable wget for your server if you are behind a proxy, set following environment variable,

http_proxy=http://user:password@proxy2.yourcom.com:8080

Most package installation is pretty straight forward, just download the package, unzip it, configure, make and make install. I encountered some error message while compiling fontconfig, the error is

gcc -shared .libs/fcatomic.o .libs/fcblanks.o .libs/fccache.o .libs/fccfg.o .libs/fccharset.o .libs/fcdbg.o .libs/fcdefault.o .libs/fcdir.o .libs/fcfreetype.o .libs/fcfs.o .libs/fcinit.o .libs/fclang.o .libs/fclist.o .libs/fcmatch.o .libs/fcmatrix.o .libs/fcname.o .libs/fcpat.o .libs/fcserialize.o .libs/fcstr.o .libs/fcxml.o .libs/ftglue.o -Wl,--rpath -Wl,/usr/local/lib -Wl,--rpath -Wl,/usr/local/lib -L/usr/local/lib /usr/local/lib/libfreetype.so -lz -lexpat -Wl,--rpath -Wl,/usr/local/lib -Wl,-soname -Wl,libfontconfig.so.1 -o .libs/libfontconfig.so.1.2.0/usr/bin/ld: /usr/local/lib/libz.a(inflate.o): relocation R_X86_64_32 against `zcalloc' can not be used when making a shared object; recompile with -fPIC/usr/local/lib/libz.a: could not read symbols: Bad valuecollect2: ld returned 1 exit status

The error is actually because Zlib was not compiled properly. I end up recompiled Zlib with

env CFLAGS="-O3 -fPIC";./configure --shared;make;make install;

Clean the old fontconfig file, 'make clean' and recompile.

Bump into another error at final compile of RRDTOOL,

collect2: ld returned 1 exit status make[2]: *** [rrdtool] Error 1

It turns out because I skipped libxml2 installation because download link broken. Well, I hope the error message was little more informative.

Ok, next I need to make Cacti working. Which will not happen until PHP, MYSQL and Apache properly configured.
Then hit the DocumentRoot must be a directory problem, even I am pretty sure the document root is directory. This is because SELinux stopping apache taking it. This can be fixed by disable SELinux or

chcon -R -h -t httpd_sys_content_t /path/to/directory

Hit a php bug while compiling php5 with apache2. Get following error while start apache

Cannot load /etc/httpd/modules/libphp5.so into server:/etc/httpd/modules/libphp5.so: undefined symbol: zend_qsort

Have to recompile php5 with

./configure --enable-mbstring --with-mysql --with-apxs2=/usr/sbin/apxs --with-libdir=lib64

I was not using --with-libdir=lib64 switch.

Again, php seems not working with mysql properly. I doubt checked ./configure message of php , there's an error

configure: error: Cannot find libmysqlclient

Apparently, ./configure is looking for /lib64 under mysql installation but there's not any. Linked lib to lib64. I have to reconfigure php again :(

I was struggling in the last few days to figure out why my php page refuse connecting to local mysql database. Always has error from index.php complaining something is not right in 'include/config.php' . However I am very much sure everything is correct. I wrote a quick test php code to test the database connection. The interesting thing is I can run the code from command line without problem, but when I check it from web through apache it failed with "Can't connect to local MySQL server through socket " error. It's kind of frustrating.

Finally a note from google search helped me, I changed hostname from 'localhost' to '127.0.0.1' just to check if this will work. Guess what, it worked!

Ok, run into another problem trying to compile cacti-spine-0.8.7a,

*** [Gentoo] sanity check failed! ****** libtool.m4 and ltmain.sh have a version mismatch! ****** (libtool.m4 = 1.5.22, ltmain.sh = 1.5.24) ***Please run: libtoolize --copy --force

Running libtoolize --copy --force

create another error,

libtoolize: `/usr/share/aclocal/libtool.m4' is serial 47, less than 48 in `aclocal.m4'To remain compatible, you should update your `aclocal.m4' by running aclocal.Putting files in AC_CONFIG_AUX_DIR, `config'.

Having no idea what's going on here, I searched internet and the solution is

autoreconf --force --install --symlink

If you google mysql and youtube, there're many people talk about Paul Tuckfield's keynote presentation at MySQL world 2007.

However few noticed there's another great presentation of youtube mysql story by Cuong Do.
Seattle Conference on Scalability: YouTube Scalability

Cuong talked about the scaling problem of youtube's growing pain with in depth technoical detail.

Hidden feature of innodb monitor

It's quite fascinating to find out MySQL allow user to turn on/off extra monitoring information in a interesting way.

Create/Drop special tables like innodb_monitor and innodb_lock_monitor etc.

http://dev.mysql.com/doc/refman/5.0/en/innodb-monitor.html