server unpredictable random performance hiccups

[noqlew]

occasionally my mysql 4.0.26 server is having slow querry issues which shouldn’t happen (judging by the tuned mem settings and indexes). How can i get more information about the processes that may be locking a particular row - the slow querry log only shows this information:

Query_time: 3 Lock_time: 0 Rows_sent: 0 Rows_examined: 0

UPDATE server SET current_kbytes_used = ‘0’, current_kbytes_free = ‘0’, current_load = ‘0.88’ WHERE SRVID=‘1717’;

The server table has about 2000 rows with an index on SRVID and it is INNODB (so the entire table should not be locked). There are multiple reads and infrequent updates and very rare inserts in this table.

Also, please note that in the majority of operation this query is instantaneous. ex:

UPDATE server SET current_kbytes_used = ‘0’, current_kbytes_free = ‘0’, current_load = ‘0.88’ WHERE SRVID=‘1717’;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0

My only guess is if this could happen when the disk is particularly busy at a certain point in time. Can this be found out through logs?

Here is some relevant disk information:

Linux 2.6.9-1.667smp 11/21/2006

Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn
sda 67.34 489.77 707.73 6227865 8999332

04:10:01 PM CPU %user %nice %system %iowait %idle
04:20:01 PM all 4.26 0.00 1.91 1.25 92.58
04:30:01 PM all 3.23 0.00 1.89 1.25 93.63
Average: all 3.74 0.00 1.90 1.25 93.11

[Peter]

Most likely it is Innodb row level locks which are causing a wait here (if disk is idle as you’re showing)

It may be seen in SHOW INNODB STATUS when query is running but only when it is running so it would be hard to catch in your case.

In MySQL 5.0 there is also SHOW STATUS variable which shows how long it was spent waiting on row level locks.

[noqlew]

Peter, thanks for the reply. The strange thing is I am not doing 100 updates/second on those rows. Instead, maybe 1 update every 10 minute for each row. Is this type of extended lock really possible on such low activity? Are there any memory tweaks possible in this situation?

Here is some more info about the drive:

/dev/sda:
Timing buffered disk reads: 184 MB in 3.03 seconds = 60.72 MB/sec

Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda 3.62 120.90 19.45 46.28 891.91 1340.26 445.96 670.13 33.96 8.10 123.26 2.43 16.00

I am not swapping either:

Linux 2.6.9-1.667smp 11/21/2006

04:10:01 PM pswpin/s pswpout/s
04:20:01 PM 0.00 0.00
04:30:01 PM 0.00 0.00
04:40:01 PM 0.00 0.00
Average: 0.00 0.00

[noqlew]

more info - from recent data, it appears that this only happens to my INNODB tables and not the MyISAM. I run a mixture of these table types in my database configuration.

[Peter]

Right. That is why I’m saying it is most likely row level locks.

Something else might be holding the lock which you do not know about.

It also can be short term stall with disk IO. The data you’re showing does not help much as it is important to understand what happens exactly in this 3 seconds query is waiting.

[noqlew]

That’s a bummer - the tmp table creating querries are rarely going past 1 second in execution.

[Peter]

Well. You can try out patch to log all queries or specify slow query time up to millisecond

Or you can enable general query log and check all queries from it )