Announcement

Announcement Module
Collapse
No announcement yet.

Innodb Threads Settings

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

  • Innodb Threads Settings

    We are running MySQL 5.5.9 on a Dual XEON Server with 8 cores and 120GB of RAM. The tablespace is on a fast SSD Drive.

    I was experiencing very low mysql performance while the overall CPU load was under 10% and very low SSD access.

    After looking at innodb monitor I lowered innodb_thread_concurrency from 256 to 32. Result: a huge performance boost. Seems the threads were waiting for mutexes most of the time...

    My questions are:
    Could 32 threads still be to much?
    What is a good mutex spin wait/ os wait ratio?
    Is it normal to have all I/O threads in state: "wait Windows aio" (I never saw another state)?

    Current Settings:
    innodb_read_io_threads = 8
    innodb_write_io_threads = 8
    innodb_thread_concurrency = 32

    Thank you very much for your help!
    Maurizio


    --- APPENDIX ----

    Some semaphores innodb monitor outputs:
    20 seconds:
    ----------
    SEMAPHORES
    ----------
    OS WAIT ARRAY INFO: reservation count 1237274, signal count 1718960
    Mutex spin waits 61927390, rounds 88274233, OS waits 1191097
    RW-shared spins 292403, rounds 1200748, OS waits 22765
    RW-excl spins 30001, rounds 1436869, OS waits 18966
    Spin rounds per wait: 1.43 mutex, 4.11 RW-shared, 47.89 RW-excl

    ----------
    SEMAPHORES
    ----------
    OS WAIT ARRAY INFO: reservation count 1510828, signal count 1927689
    Mutex spin waits 64256205, rounds 98465742, OS waits 1460531
    RW-shared spins 313695, rounds 1311507, OS waits 25333
    RW-excl spins 32153, rounds 1546598, OS waits 20362
    Spin rounds per wait: 1.53 mutex, 4.18 RW-shared, 48.10 RW-excl

    This is a full innodb monitor output:
    =====================================
    110314 13:25:32 INNODB MONITOR OUTPUT
    =====================================
    Per second averages calculated from the last 20 seconds
    -----------------
    BACKGROUND THREAD
    -----------------
    srv_master_thread loops: 11373 1_second, 11372 sleeps, 1124 10_second, 405 background, 405 flush
    srv_master_thread log flush and writes: 11464
    ----------
    SEMAPHORES
    ----------
    OS WAIT ARRAY INFO: reservation count 1508316, signal count 1925586
    Mutex spin waits 64229942, rounds 98364059, OS waits 1458040
    RW-shared spins 313502, rounds 1310927, OS waits 25321
    RW-excl spins 32136, rounds 1545701, OS waits 20355
    Spin rounds per wait: 1.53 mutex, 4.18 RW-shared, 48.10 RW-excl
    ------------
    TRANSACTIONS
    ------------
    Trx id counter 596A0C341
    Purge done for trx's n < 596A0B720 undo n < 0
    History list length 205
    LIST OF TRANSACTIONS FOR EACH SESSION:
    ---TRANSACTION 596A0C1C9, not started, OS thread id 208136
    MySQL thread id 17697, query id 8151093 localhost ::1 root
    ---TRANSACTION 596A0C333, not started, OS thread id 20760
    MySQL thread id 17610, query id 8151726 localhost ::1 root
    ---TRANSACTION 596A0B286, not started, OS thread id 285112
    MySQL thread id 17570, query id 8144961 localhost ::1 root
    ---TRANSACTION 596A0BE36, not started, OS thread id 55348
    MySQL thread id 17339, query id 8149503 localhost ::1 root
    ---TRANSACTION 0, not started, OS thread id 84980
    MySQL thread id 1791, query id 6569273 localhost ::1 root
    ---TRANSACTION 59647C428, not started, OS thread id 57584
    MySQL thread id 49, query id 1103345 localhost ::1 root
    ---TRANSACTION 596A0C340, ACTIVE 0 sec, OS thread id 30544 starting index read, thread declared inside InnoDB 500
    mysql tables in use 1, locked 0
    MySQL thread id 17670, query id 8151743 localhost ::1 root statistics
    Select DomainUID from DomainTable Where Domain='http://www.blawsom.com' Limit 1
    Trx read view will not see trx with id >= 596A0C341, sees < 596A0863E
    ---TRANSACTION 596A0863E, ACTIVE 37 sec, OS thread id 140664 fetching rows, thread declared inside InnoDB 395
    mysql tables in use 1, locked 1
    30867 lock struct(s), heap size 3996088, 8006426 row lock(s)
    MySQL thread id 893, query id 8126690 localhost ::1 root Sending data
    Replace Into Backlink.2011_10

    ( SELECT LinkDomainUID, DomainUID, PageUID, Position, DeepLink, Follow, Active, TextUID, Week, WeekRescan, YearRescan FROM Firma.`PagerelationsTable`

    WHERE Saved = 99 Limit 20300000, 100000 )
    --------
    FILE I/O
    --------
    I/O thread 0 state: wait Windows aio (insert buffer thread)
    I/O thread 1 state: wait Windows aio (log thread)
    I/O thread 2 state: wait Windows aio (read thread)
    I/O thread 3 state: wait Windows aio (read thread)
    I/O thread 4 state: wait Windows aio (read thread)
    I/O thread 5 state: wait Windows aio (read thread)
    I/O thread 6 state: wait Windows aio (read thread)
    I/O thread 7 state: wait Windows aio (read thread)
    I/O thread 8 state: wait Windows aio (read thread)
    I/O thread 9 state: wait Windows aio (read thread)
    I/O thread 10 state: wait Windows aio (write thread)
    I/O thread 11 state: wait Windows aio (write thread)
    I/O thread 12 state: wait Windows aio (write thread)
    I/O thread 13 state: wait Windows aio (write thread)
    I/O thread 14 state: wait Windows aio (write thread)
    I/O thread 15 state: wait Windows aio (write thread)
    I/O thread 16 state: wait Windows aio (write thread)
    I/O thread 17 state: wait Windows aio (write thread)
    Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0] ,
    ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
    Pending flushes (fsync) log: 0; buffer pool: 0
    2557122 OS file reads, 162752 OS file writes, 28198 OS fsyncs
    86.20 reads/s, 5248 avg bytes/read, 9.05 writes/s, 3.85 fsyncs/s
    -------------------------------------
    INSERT BUFFER AND ADAPTIVE HASH INDEX
    -------------------------------------
    Ibuf: size 1, free list len 261426, seg size 261428, 13571 merges
    merged operations:
    insert 83277, delete mark 459921, delete 58180
    discarded operations:
    insert 0, delete mark 0, delete 0
    Hash table size 144498583, node heap has 83577 buffer(s)
    94999.75 hash searches/s, 1993.50 non-hash searches/s
    ---
    LOG
    ---
    Log sequence number 9836204638037
    Log flushed up to 9836204595512
    Last checkpoint at 9835970245764
    0 pending log writes, 0 pending chkp writes
    11324 log i/o's done, 1.10 log i/o's/second
    ----------------------
    BUFFER POOL AND MEMORY
    ----------------------
    Total memory allocated 74725720064; in additional pool allocated 0
    Dictionary memory allocated 1012343
    Buffer pool size 4456448
    Free buffers 1246014
    Database pages 2587126
    Old database pages 955033
    Modified db pages 63332
    Pending reads 1
    Pending writes: LRU 0, flush list 0, single page 0
    Pages made young 10964, not young 0
    5.65 youngs/s, 0.00 non-youngs/s
    Pages read 2556935, created 32065, written 144994
    86.20 reads/s, 5.20 creates/s, 6.85 writes/s
    Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
    Pages read ahead 0.00/s, evicted without access 0.00/s
    LRU len: 2587126, unzip_LRU len: 1446750
    I/O sum[4719]:cur[6], unzip sum[5324]:cur[10]
    --------------
    ROW OPERATIONS
    --------------
    2 queries inside InnoDB, 0 queries in queue
    1 read views open inside InnoDB
    Main thread id 140360, state: sleeping
    Number of rows inserted 2259224, updated 1561336, deleted 1190, read 2729194687
    65.40 inserts/s, 10.85 updates/s, 0.00 deletes/s, 96350.43 reads/s
    ----------------------------
    END OF INNODB MONITOR OUTPUT
    ============================

  • #2
    Hi,

    There does not seems to be much load in the innodb sample you have provided. It shows there is one IO pending with only 80 reads/sec which is rather little for SSD.

    Also note:

    WHERE Saved = 99 Limit 20300000, 100000

    This is pretty bad for performance because MySQL has to skip 20300000 rows to get you 100000

    This can be real cause of your performance issues

    Comment


    • #3
      Hi Peter,

      thanks for your reply.
      Yes, there was little load and the query you mentioned is slow, but only a maintenance task run once a week - not our typical load.

      The server is runnig quite fast now even under heavier load.
      With 256 as innodb_thread_concurrency and 32 i/o thread the performance was a good deal worse for the same load.

      What do you say to my questions:
      Could innodb_thread_concurrency=32 still be to much?
      What is a good mutex spin wait/ os wait ratio?
      Is it normal to have all I/O threads in state: "wait Windows aio" (I never saw another state)?

      This is an automatic innodb monitor output in our error.log after a long semaphore wait with innodb_thread_concurrency=256:

      InnoDB: Warning: a long semaphore wait:
      --Thread 14316 has waited at ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 241.00 seconds the semaphore:
      S-lock on RW-latch at 0000000140758C08 created in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
      a writer (thread id 183672) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending preads 0, pwrites 0

      =====================================
      110309 12:02:06 INNODB MONITOR OUTPUT
      =====================================
      Per second averages calculated from the last 30 seconds
      -----------------
      BACKGROUND THREAD
      -----------------
      srv_master_thread loops: 17925 1_second, 17921 sleeps, 1701 10_second, 5612 background, 5606 flush
      srv_master_thread log flush and writes: 18214
      ----------
      SEMAPHORES
      ----------
      OS WAIT ARRAY INFO: reservation count 4529303, signal count 10234957
      --Thread 133740 has waited at ..\..\..\mysql-5.5.9\storage\innobase\row\row0ins.c line 2002 for 20.00 seconds the semaphore:
      X-lock on RW-latch at 00000003F13D8F40 created in file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 898
      a writer (thread id 240236) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0flu.c line 1292
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\row\row0ins.c line 2002
      --Thread 283240 has waited at ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293 for 160.00 seconds the semaphore:
      X-lock on RW-latch at 0000000140758C08 created in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
      a writer (thread id 183672) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
      --Thread 184808 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 215236 has waited at ..\..\..\mysql-5.5.9\storage\innobase\row\row0purge.c line 654 for 20.00 seconds the semaphore:
      S-lock on RW-latch at 00000001407CD940 created in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 710
      a writer (thread id 45764) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\row\row0purge.c line 654
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\row\row0mysql.c line 2781
      --Thread 211668 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 240236 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 135260 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 14316 has waited at ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 247.00 seconds the semaphore:
      S-lock on RW-latch at 0000000140758C08 created in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
      a writer (thread id 183672) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
      --Thread 218044 has waited at ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293 for 20.00 seconds the semaphore:
      X-lock on RW-latch at 0000000140758C08 created in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
      a writer (thread id 183672) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
      --Thread 91896 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 22664 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 7376 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 183672 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 180060 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 60552 has waited at ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 2755 for 19.00 seconds the semaphore:
      Mutex at 000000000A89F1C8 created file ..\..\..\mysql-5.5.9\storage\innobase\buf\buf0buf.c line 1208, lock var 1
      waiters flag 1
      --Thread 84312 has waited at G:\pb2\build\sb_0-2859905-1295578448.44\mysql-5.5.9\storage\ innobase\include\dict0boot.ic line 45 for 20.00 seconds the semaphore:
      Mutex at 0000000113990EA8 created file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 697, lock var 1
      waiters flag 1
      --Thread 225356 has waited at ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 740 for 20.00 seconds the semaphore:
      Mutex at 0000000113990EA8 created file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 697, lock var 1
      waiters flag 1
      Mutex spin waits 69375442, rounds 76371569, OS waits 940402
      RW-shared spins 6581324, rounds 134920002, OS waits 2488034
      RW-excl spins 2402458, rounds 62313034, OS waits 903876
      Spin rounds per wait: 1.10 mutex, 20.50 RW-shared, 25.94 RW-excl
      ------------
      TRANSACTIONS
      ------------
      Trx id counter 58278C705
      Purge done for trx's n < 58278C6A4 undo n < 3
      History list length 502
      LIST OF TRANSACTIONS FOR EACH SESSION:
      ---TRANSACTION 58278C6D1, not started, OS thread id 218044
      MySQL thread id 23995, query id 4150839 localhost ::1 root Opening tables
      SELECT MAX(DomainUID) FROM DomainTable
      ---TRANSACTION 58278C6E1, not started, OS thread id 283240
      MySQL thread id 23989, query id 4150730 localhost ::1 root Opening tables
      SELECT *

      FROM `userdomaintable`

      JOIN domaintable As Domain ON (`userdomaintable`.`DomainUID` = `domain`.`DomainUID`)

      Where `Domain`.`Domain` = 'http://www.my-art-print.de'
      ---TRANSACTION 58278C6FE, not started, OS thread id 225356
      MySQL thread id 23982, query id 4150933 localhost ::1 root Opening tables
      SELECT d.Domain, d.DomainUID, ud.*

      FROM UserdomainTable as ud JOIN DomainTable as d

      ON ud.DomainUID = d.DomainUID

      WHERE ud.UserUID = 739

      ORDER BY d.Domain
      ---TRANSACTION 0, not started, OS thread id 183672 updating table statistics
      MySQL thread id 23965, query id 4150554 localhost ::1 root
      SHOW TABLE STATUS FROM `firma`
      ---TRANSACTION 58278C6BB, not started, OS thread id 14316 returning various info to MySQL
      mysql tables in use 1, locked 0
      MySQL thread id 23923, query id 4150742 localhost ::1 root statistics
      Select Domain from DomainTable Where DomainUID = '9416'
      ---TRANSACTION 58278B0CE, not started, OS thread id 144088
      MySQL thread id 17020, query id 4150669 localhost 127.0.0.1 root
      ---TRANSACTION 58278644C, not started, OS thread id 39192
      MySQL thread id 8118, query id 4150894 localhost ::1 root
      ---TRANSACTION 58278C704, ACTIVE 20 sec, OS thread id 84312 inserting, thread declared inside InnoDB 500
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s)
      MySQL thread id 24032, query id 4150857 localhost ::1 root update
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (1, '', 0, '', 'visit', 0)
      ---TRANSACTION 58278C703, ACTIVE 20 sec, OS thread id 184808 inserting, thread declared inside InnoDB 500
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
      MySQL thread id 24042, query id 4150899 localhost ::1 root update
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (1, '', 0, '', 'visit', 0)
      ---TRANSACTION 58278C702, ACTIVE 20 sec, OS thread id 91896 estimating records in index range
      mysql tables in use 3, locked 0
      MySQL thread id 24022, query id 4150835 localhost ::1 root statistics
      SELECT `trefcode`.`area_code` as `ref_area_code`,`turlcode`.`area_code` as `url_area_code`,`turltitle`.`title` as `url_title`,`treftitle`.`title` as `ref_title`,`turldom`.`domain` as `url_dom`,`turlpath`.`path` as `url_path`,`trefdom`.`domain` as `ref_dom`,`trefpath`.`path` as `ref_path`,`entrance`,`params`,`untouched` FROM `visitor_browser_urls` INNER JOIN `visitor_data_pages` AS `turl` ON `visitor_browser_urls`.`url`=`turl`.`id` INNER JOIN `visitor_data_pages` AS `tref` ON `visitor_browser_urls`.`referrer`=`tref`.`id` INNER JOIN `visitor_data_domains` AS `trefdom` ON `tref`.`domain`=`trefdom
      Trx read view will not see trx with id >= 58278C703, sees < 58278C6EB
      ---TRANSACTION 58278C701, ACTIVE 20 sec, OS thread id 45764 truncating table
      mysql tables in use 32, locked 32
      MySQL thread id 23911, query id 4150243 localhost ::1 root
      TRUNCATE `pagecrcfinal`
      ---TRANSACTION 58278C6FD, ACTIVE 20 sec, OS thread id 22664 inserting, thread declared inside InnoDB 500
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s)
      MySQL thread id 24006, query id 4150931 localhost ::1 root update
      INSERT INTO UserActivityLog (UserUID, IP, ActionUID, Label, Value, Time) VALUES ('800', '1419124466', '2', '', '0', '0')
      ---TRANSACTION 58278C6FA, ACTIVE 20 sec, OS thread id 7376 preparing
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
      MySQL thread id 24031, query id 4150929 localhost ::1 root query end
      INSERT INTO TrackingTable (CookieId, Action) VALUES (87455, 'id allocation')
      ---TRANSACTION 58278C6F6, ACTIVE 160 sec, OS thread id 240236 inserting, thread declared inside InnoDB 500
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s)
      MySQL thread id 23966, query id 4150836 localhost ::1 root update
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (87454, '', 0, '', 'visit', 0)
      ---TRANSACTION 58278C6F5, ACTIVE 160 sec, OS thread id 135260 preparing
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
      MySQL thread id 24019, query id 4150794 localhost ::1 root query end
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (1, 'http://www.seo4wp.de/seo-extensions-google-chrome/', 796, '', 'visit', 0)
      ---TRANSACTION 58278C6F4, ACTIVE 160 sec, OS thread id 180060 preparing
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
      MySQL thread id 24027, query id 4150824 localhost ::1 root query end
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (1, ' http://www.maxiklicks.de/crons/ziel.php?uid=16&bid=mLRP9 wzQgkKF01QMbflH25F33kr3RZh4&sid=122&v1=e48c16da7c35c 8eb69d442081390f956&var1=e48c16da7c35c8eb69d442081390f95 6', 0, '', 'visit', 0)
      ---TRANSACTION 58278C6F3, ACTIVE 160 sec, OS thread id 133740 inserting, thread declared inside InnoDB 500
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s)
      MySQL thread id 24025, query id 4150815 localhost ::1 root update
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (1, '', 0, '', 'visit', 0)
      ---TRANSACTION 58278C6F2, ACTIVE (PREPARED) 160 sec, OS thread id 211668 committing
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
      MySQL thread id 24014, query id 4150769 localhost ::1 root query end
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (1, '', 0, '', 'visit', 0)
      ---TRANSACTION 58278C6EB, ACTIVE 242 sec, OS thread id 60552 preparing
      mysql tables in use 1, locked 1
      1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1
      MySQL thread id 24010, query id 4150760 localhost ::1 root query end
      INSERT INTO TrackingTable (CookieId, Referrer, PartnerId, AdId, Action, UserUID)

      VALUES (1, '', 0, '', 'visit', 0)
      --------
      FILE I/O
      --------
      I/O thread 0 state: wait Windows aio (insert buffer thread)
      I/O thread 1 state: wait Windows aio (log thread)
      I/O thread 2 state: wait Windows aio (read thread)
      I/O thread 3 state: wait Windows aio (read thread)
      I/O thread 4 state: wait Windows aio (read thread)
      I/O thread 5 state: wait Windows aio (read thread)
      I/O thread 6 state: wait Windows aio (read thread)
      I/O thread 7 state: wait Windows aio (read thread)
      I/O thread 8 state: wait Windows aio (read thread)
      I/O thread 9 state: wait Windows aio (read thread)
      I/O thread 10 state: wait Windows aio (read thread)
      I/O thread 11 state: wait Windows aio (read thread)
      I/O thread 12 state: wait Windows aio (read thread)
      I/O thread 13 state: wait Windows aio (read thread)
      I/O thread 14 state: wait Windows aio (read thread)
      I/O thread 15 state: wait Windows aio (read thread)
      I/O thread 16 state: wait Windows aio (read thread)
      I/O thread 17 state: wait Windows aio (read thread)
      I/O thread 18 state: wait Windows aio (write thread)
      I/O thread 19 state: wait Windows aio (write thread)
      I/O thread 20 state: wait Windows aio (write thread)
      I/O thread 21 state: wait Windows aio (write thread)
      I/O thread 22 state: wait Windows aio (write thread)
      I/O thread 23 state: wait Windows aio (write thread)
      I/O thread 24 state: wait Windows aio (write thread)
      I/O thread 25 state: wait Windows aio (write thread)
      I/O thread 26 state: wait Windows aio (write thread)
      I/O thread 27 state: wait Windows aio (write thread)
      I/O thread 28 state: wait Windows aio (write thread)
      I/O thread 29 state: wait Windows aio (write thread)
      I/O thread 30 state: wait Windows aio (write thread)
      I/O thread 31 state: wait Windows aio (write thread)
      I/O thread 32 state: wait Windows aio (write thread)
      I/O thread 33 state: wait Windows aio (write thread)
      Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] ,
      ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
      Pending flushes (fsync) log: 0; buffer pool: 0
      9036633 OS file reads, 1019489 OS file writes, 95688 OS fsyncs
      0.23 reads/s, 16384 avg bytes/read, 0.13 writes/s, 0.13 fsyncs/s
      -------------------------------------
      INSERT BUFFER AND ADAPTIVE HASH INDEX
      -------------------------------------
      Ibuf: size 1, free list len 100973, seg size 100975, 120916 merges
      merged operations:
      insert 1124658, delete mark 230351, delete 217314
      discarded operations:
      insert 0, delete mark 0, delete 0
      Hash table size 144498583, node heap has 264947 buffer(s)
      3.60 hash searches/s, 1.50 non-hash searches/s
      ---
      LOG
      ---
      Log sequence number 8870605216748
      Log flushed up to 8870605211717
      Last checkpoint at 8870605178275
      0 pending log writes, 0 pending chkp writes
      28023 log i/o's done, 0.03 log i/o's/second
      ----------------------
      BUFFER POOL AND MEMORY
      ----------------------
      Total memory allocated 74725720064; in additional pool allocated 0
      Dictionary memory allocated 998876
      InnoDB: ###### Diagnostic info printed to the standard error stream
      InnoDB: Warning: a long semaphore wait:
      --Thread 14316 has waited at ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 272.00 seconds the semaphore:
      S-lock on RW-latch at 0000000140758C08 created in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
      a writer (thread id 183672) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending preads 0, pwrites 0
      InnoDB: ###### Diagnostic info printed to the standard error stream
      InnoDB: Warning: a long semaphore wait:
      --Thread 14316 has waited at ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290 for 303.00 seconds the semaphore:
      S-lock on RW-latch at 0000000140758C08 created in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 720
      a writer (thread id 183672) has reserved it in mode exclusive
      number of readers 0, waiters flag 1, lock_word: 0
      Last time read locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 290
      Last time write locked in file ..\..\..\mysql-5.5.9\storage\innobase\dict\dict0dict.c line 293
      InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
      InnoDB: Pending preads 0, pwrites 0
      Buffer pool size 4456448
      Free buffers 193103
      Database pages 7113405
      Old database pages 2625866
      Modified db pages 86
      Pending reads 1
      Pending writes: LRU 0, flush list 0, single page 0
      Pages made young 13765440, not young 0
      0.13 youngs/s, 0.00 non-youngs/s
      Pages read 9033196, created 650087, written 947081
      0.09 reads/s, 0.04 creates/s, 0.00 writes/s
      Buffer pool hit rate 995 / 1000, young-making rate 8 / 1000 not 0 / 1000
      Pages read ahead 0.00/s, evicted without access 0.00/s
      LRU len: 7113405, unzip_LRU len: 1703840
      I/O sum[8]:cur[0], unzip sum[0]:cur[0]
      --------------
      ROW OPERATIONS
      --------------
      3 queries inside InnoDB, 0 queries in queue
      2 read views open inside InnoDB
      Main thread id 215236, state: flushing log
      Number of rows inserted 116357061, updated 777213, deleted 524, read 13818160521
      0.23 inserts/s, 0.00 updates/s, 0.00 deletes/s, 3.93 reads/s
      ----------------------------
      END OF INNODB MONITOR OUTPUT
      ============================

      Comment


      • #4
        Yup. Something is wrong. The dictionary semaphore is being held for 200+ seconds with very little progress in terms of thread operations. It would be good to see where all threads are stuck in this case. On linux/unix it can be done with GDB and or Poor Mans Profiler.

        Comment

        Working...
        X