Announcement

Announcement Module
Collapse
No announcement yet.

Very Slow Random updates occuring

Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Very Slow Random updates occuring

    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?

    Comment


    • #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)

      Comment


      • #4
        Start with http://catb.org/~esr/faqs/smart-questions.html 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.

        Comment

        Working...
        X