{"id":43,"date":"2012-05-19T15:00:00","date_gmt":"2012-05-19T15:00:00","guid":{"rendered":"http:\/\/www.olivierdoucet.info\/wordpress\/?p=43"},"modified":"2012-05-19T15:00:00","modified_gmt":"2012-05-19T15:00:00","slug":"debugging-a-mysql-stall","status":"publish","type":"post","link":"https:\/\/www.olivierdoucet.info\/blog\/2012\/05\/19\/debugging-a-mysql-stall\/","title":{"rendered":"Debugging a MySQL stall"},"content":{"rendered":"
This article follows \u00ab\u00a0finding an usual cause of max_user_connections\u00a0\u00bb.<\/div>\n
After debugging a max_user_connections and a cache expiration problem in the customer app, we still experienced stalls of the mysqld process. MySQL refused all connections for 5 to 20 seconds, with no obvious reason. I’ll try to explain what I did to solve it.<\/div>\n

<\/p>\n

Go on, sherlock<\/h1>\n
CPU usage was the following : <\/div>\n
\"IOSTAT<\/div>\n
Legend: light green is user usage ; dark green is system usage ; violet is IOwait. Y-axis is thread usage (one thread at 100% == 100 in the graph).<\/div>\n
Some useful informations on this image : <\/div>\n
– there is no visible pattern on when the problem is happening (confirmed with a graph on 2 days).<\/div>\n
– CPU usage is increasing for a minute …<\/div>\n
  and this usage is done by the system<\/div>\n
I created a small bash script to get all data I needed when problem happened : <\/div>\n

<\/p>\n

while sleep 1; do<\/div>\n
mysql -e \"SELECT 1\" > \/dev\/null<\/div>\n
  if [ \"$?\" != \"0\" ]; then<\/div>\n
    echo \"Collect !\"<\/div>\n
        STAMP=$(date \"+%H%M%S\")<\/div>\n
        echo \"Problem ! Start collecing\"<\/div>\n
# add here command line to be executed<\/div>\n
sleep 5<\/div>\n
   else echo -ne \".\\r\"<\/div>\n
   fi<\/div>\n
done ;<\/div>\n

<\/code><\/p>\n

I first used this script to record a ‘top’ session to check which processes were eating all CPU. To get top output for 10 seconds I used the following command line :<\/div>\n
top -b -d 1 -n 10 > $STAMP\"_top\" &<\/pre>\n
Remember $STAMP is the timestamp used in my bash script to group outputs.<\/div>\n
Result ? mysqld is the top process, with linux kernel process [kworker]. Not a useful information by itself, but it definitely shows there is something wrong happening in the kernel.<\/div>\n
How do you debug a kernel on a production server ? After checking various websites, I decided to use \u00ab\u00a0oprofile\u00a0\u00bb (http:\/\/oprofile.sourceforge.net). It consists of a kernel driver and a daemon for collecting sample data, and several post-profiling tools for turning data into information. To my mind, pros of this tool are : <\/div>\n
\n