My site is very slow sometimes, so I activated the php-slowlog to find out whats wrong. It is full of mysql-functions like mysql_query. So I activated the mysql-slowlog and found out that some querys took up to 35 (!) seconds like the following:
# Thread_id: 4866 Schema: mytable QC_hit: No # Query_time: 35.803294 Lock_time: 0.000042 Rows_sent: 0 Rows_examined: 1 SET timestamp=1393847628; UPDATE cache SET locktime = 1393847592 WHERE cacheid = 'cms_priv_user_23459';
Others are faster, but for such a MySQL-Query stil very slow:
# Thread_id: 4137 Schema: mytable QC_hit: No # Query_time: 1.119290 Lock_time: 0.000047 Rows_sent: 0 Rows_examined: 1 SET timestamp=1393846824; UPDATE session SET lastactivity = 1393846818, badlocation = 0 WHERE sessionhash = 'mysessionhash';
Its not a single problem, I get one slow query every 10-50 seconds (long_query_time is set to 1). Most of the querys are a kind of INSERT (for example UPDATE-Querys as you can see above), but there are also some selects.
From 418 slow querys
$ cat mysql-slow.log | grep Query_time | wc -l 418
there were 5 SELECTs
$ cat mysql-slow.log | grep SELECT | wc -l 22
By writing an addon that integrates SHOW PROFILE in my CMS I found out that the database-server is spending most of the time to wait for locks
Array ( [Query_ID] => 227 [Duration] => 5.74142869 [Query] => SELECT user.username, (user.options & 512) AS invisible, user.usergroupid, user.lastvisit, session.userid, session.inforum, session.lastactivity, session.badlocation, IF(displaygroupid=0, user.usergroupid, displaygroupid) AS displaygroupid, infractiongroupid FROM session AS session ) Duration Status 0.000030 starting 0.000011 Waiting for query cache lock 0.000076 checking query cache for query 0.000012 checking permissions 0.000011 checking permissions 0.000027 Opening tables 0.000012 System lock 0.000010 Table lock 5.126086 Waiting for table level lock 0.000020 Table lock 0.613440 Waiting for table level lock 0.000066 Table lock 0.000151 Waiting for query cache lock 0.000121 init 0.000108 optimizing 0.000066 statistics 0.000050 preparing 0.000074 executing 0.000115 Creating tmp table 0.000427 Copying to tmp table 0.000119 Sorting result 0.000116 Sending data 0.000064 end 0.000044 removing tmp table 0.000020 end 0.000019 query end 0.000027 closing tables 0.000025 freeing items 0.000056 updating status 0.000024 cleaning up
Thats strange, because in the slow-log mysql told me that Lock_time is very low and so I thought this can't be responsible for the long query time.
And why are tables locked on SELECT-Statements? What can I do to reduce the waiting here? The status variables tell me that this affects about 2% of the querys (About 3000k querys have to wait for a table lock out of 125000k). This is similar to my personal experience: Sometimes my page is loading very fast, sometimes it take about 4-5 seconds, other times about 15 seconds and in some cases I even get timeouts.
I take a look at about 3 hours of slow query logs and it seems that the session-table is one of the main issues for slow querys. From about 550 querys are alone 160 UPDATE-querys to the session-table. But I really can't understand why just this table causes slowlogs, because It's a memory table. The table is also very small (currently about 200 rows, at peak maybe up to 400). So even with bad indexes there such a small query shouldn't nearly take 30 seconds and more. I thought a memory table should be optimal for performance in this case, but because it looks like it isn't I converted them to MyISAM for testing. The server is running now for only 20 minutes but it looks like this make nothing better: 53 slow 'UPDATE session' querys of 173 total slow querys. That's a factor of 0,30 and nearly even a little bit more than before with the memory tables (0,29). 0,3063583815028902
Edit2: A lot of opened tables
I see that I've a lot of opened tables, currently about 21,000, and the server is only running for about 6 hours. I have set table_open_cache to 6000. Would it make sense to increase this to lets say 25,000? Enough RAM is avaliable, I've currently 4-6GB which can be used for this.