Very Slow Random updates occuring

MySQL & MariaDB Other MySQL® Questions
1

I have inserts sometimes doing similar things but with opening tables however… I see

Current table_open_cache = 3072 tables
Current table_definition_cache = 3072 tables
You have a total of 614 tables
You have 1685 open tables.

So i don’t see why that table isnt in the table_cache.
The query was :
04/21/2010 07:35:42 6.4603s SELECT * FROM zipcodes WHERE ZipCode=‘60115’ LIMIT 0,1
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps |

| starting | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| checking query cache for query | 0.000038 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| checking permissions | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Opening tables | 6.446095 | 7.689831 | 0.135979 | 1339 | 80 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| System lock | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Table lock | 0.000023 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| init | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| optimizing | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| statistics | 0.005466 | 0.003999 | 0.001000 | 31 | 2 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| preparing | 0.000030 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Sending data | 0.008479 | 0.005999 | 0.000000 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| query end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| freeing items | 0.000023 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| storing result in query cache | 1.002840 | 0.948856 | 0.007999 | 140 | 14 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| cleaning up | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |

Can anyone tell me why this update is taking 83 seconds. That seems really excessive.

04/21/2010 07:26:24 83.0525s
INSERT INTO status_time (Class, ID, Datestamp, Hour, ReadyInbound, Enabled)
VALUES (‘CallCenter’,‘1’,‘2010-04-21’,‘07’,‘00:01:00’,‘00:01:00’), (‘CallCenter’,‘26’,‘2010-04-21’,‘07’,‘00:01:00’,‘00:01:00’)
ON DUPLICATE KEY UPDATE
ReadyInbound = ADDTIME(ReadyInbound, VALUES(ReadyInbound)), Enabled = ADDTIME(Enabled, VALUES(Enabled))

| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps |

| starting | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| checking query cache for query | 0.000029 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Opening tables | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| System lock | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Table lock | 0.000038 | 0.001000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| init | 0.000018 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| optimizing | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| statistics | 0.000060 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| preparing | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| executing | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Sending data | 21.327772 | 0.628905 | 0.427935 | 10797 | 251 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| end | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| query end | 0.000004 | 0.000999 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| freeing items | 0.000019 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| cleaning up | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps |

| starting | 0.000064 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| checking permissions | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Opening tables | 0.000025 | 0.001000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| System lock | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| Table lock | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| init | 0.000023 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| update | 82.926129 | 3.332493 | 2.354642 | 57252 | 1495 | 0 | 0 | 0 | 0 | 0 | 9 | 0 |
| end | 0.000027 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| query end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| freeing items | 0.127486 | 0.155977 | 0.012998 | 480 | 107 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| logging slow query | 0.000027 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |
| cleaning up | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 |

2

I’m not sure what you are asking. Why are you asking about the table cache? It looks like you are showing the output of SHOW PROFILES (you didn’t say, but it looks like it). If so, then what makes you think the table cache has anything to do with this?

3

There were 2 questions posed…

The first was about table caching. In some profiling i am seeing 12 - 15 seconds taken up by opening tables, but my table_cache seems perfectly normal .

The second question is why this update would be taking so long. (the one with the show profile code)

4

Start with [URL]http://catb.org/~esr/faqs/smart-questions.html[/URL] because asking two questions in one topic confuses the animals.

Problems such as this require a LOT more information than you’re showing, but as just a guess, both issues might be related to slow I/O performance. Check your I/O subsystem.