GET 24/7 LIVE HELP NOW

Announcement

Announcement Module
Collapse
No announcement yet.

What is "history list" exactly?

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

  • What is "history list" exactly?

    Yesterday night I've updated my Percona Server from 5.1.54-rel12.5 to 5.5.17-rel22.1.
    Update was done via SQL dump-restore, so all xtradb files were created from scratch.
    The problem (or not) is in the attached picture, "history list" is times higher than it was before the update.
    The question is what is exactly the "history list" and is that behavior any bad?

    related information:
    There are no permanent connections or long-running queries on that db.
    "history list" goes directly to ~2k immediately after restart, while there is no load at all and "show processlist" is empty.
    Server is 8-core, 24GB RAM, SAS RAID1 with BBU, running FreeBSD 8.1.
    DB size is ~12GB.
    Log write rate is ~5-20MB/sec, day-night sine wave.
    my.cnf:

    [mysqld]character-set-server = cp1251skip-character-set-client-handshakeuser = mysqlmax-allowed-packet = 4Mtable-cache = 512thread-cache = 32bind-address = 192.168.1.13port = 3306query_cache_size = 32Mquery_cache_limit = 32Msort_buffer_size = 8Mjoin_buffer_size = 8Mtmp_table_size = 64Mmax_heap_table_size = 64Mdatadir = /var/db/mysqlinnodb_data_home_dir = /var/db/mysqlinnodb_data_file_path = ibdata1:10M:autoextendinnodb_log_group_home_dir = /var/db/mysqlinnodb_log_files_in_group = 2innodb_buffer_pool_size = 16Ginnodb_log_file_size = 256Minnodb_log_buffer_size = 16Minnodb_flush_log_at_trx_commit = 0innodb_thread_concurrency = 16innodb_flush_method = ALL_O_DIRECTinnodb_file_per_table = 1innodb_max_dirty_pages_pct = 90innodb_io_capacity = 200innodb_write_io_threads = 2innodb_adaptive_flushing_method = estimateinnodb_buffer_pool_restore_at_startup = 86400transaction-isolation = READ-COMMITTEDskip-name-resolve

    Server ran the same configuration before the update with the exception of "innodb_buffer_pool_restore_at_startup", which was not used.

    PS:
    "history list" nightly spikes were happening because of innobackup (from innobase oy) was running. Now it is disabled and will be replaced with xtrabackup.

  • #2
    Please read http://code.google.com/p/mysql-cacti-templates/wiki/MySQLTem plates#InnoDB_Transactions

    Do you have the output of show innodb status?

    Comment


    • #3
      Thank you, now things are a bit clearer.
      However, I still don't get why this value was so low with 5.1 and now is that high with 5.5, while cnf and usage pattern stayed the same.
      show engine innodb status:

      =====================================111121 18:01:45 INNODB MONITOR OUTPUT=====================================Per second averages calculated from the last 46 seconds-----------------BACKGROUND THREAD-----------------srv_master_thread loops: 54945 1_second, 54863 sleeps, 5494 10_second, 8 background, 8 flushsrv_master_thread log flush and writes: 56549----------SEMAPHORES----------OS WAIT ARRAY INFO: reservation count 308313, signal count 13060409Mutex spin waits 13008467, rounds 8624042, OS waits 38534RW-shared spins 6962077, rounds 19702011, OS waits 150539RW-excl spins 471256, rounds 17979523, OS waits 91824Spin rounds per wait: 0.66 mutex, 2.83 RW-shared, 38.15 RW-excl--------FILE I/O--------I/O thread 0 state: waiting for i/o request (insert buffer thread)I/O thread 1 state: waiting for i/o request (log thread)I/O thread 2 state: waiting for i/o request (read thread)I/O thread 3 state: waiting for i/o request (read thread)I/O thread 4 state: waiting for i/o request (read thread)I/O thread 5 state: waiting for i/o request (read thread)I/O thread 6 state: waiting for i/o request (write thread)I/O thread 7 state: waiting for i/o request (write thread)Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0] , ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0Pending flushes (fsync) log: 0; buffer pool: 0250215 OS file reads, 1493019 OS file writes, 148468 OS fsyncs0.00 reads/s, 0 avg bytes/read, 37.28 writes/s, 2.89 fsyncs/s-------------------------------------INSERT BUFFER AND ADAPTIVE HASH INDEX-------------------------------------Ibuf: size 1, free list len 0, seg size 2, 149 mergesmerged operations: insert 138, delete mark 78, delete 3discarded operations: insert 0, delete mark 0, delete 0Hash table size 35401589, node heap has 32899 buffer(s)248082.22 hash searches/s, 7043.24 non-hash searches/s---LOG---Log sequence number 42394723533Log flushed up to 42393001652Last checkpoint at 42065746622Max checkpoint age 433210615Checkpoint age target 419672784Modified age 328976699Checkpoint age 3289769110 pending log writes, 0 pending chkp writes62727 log i/o's done, 1.11 log i/o's/second----------------------BUFFER POOL AND MEMORY----------------------Total memory allocated 17649631232; in additional pool allocated 0Internal hash tables (constant factor + variable factor) Adaptive hash index 822234144 (283212712 + 539021432) Page hash 17701592 (buffer pool 0 only) Dictionary cache 71349054 (70804688 + 544366) File system 129752 (82672 + 47080) Lock system 42505720 (42500456 + 5264) Recovery system 0 (0 + 0)Dictionary memory allocated 544366Buffer pool size 1048575Buffer pool size, bytes 17179852800Free buffers 295953Database pages 719723Old database pages 265658Modified db pages 58994Pending reads 0Pending writes: LRU 0, flush list 0, single page 0Pages made young 484, not young 00.02 youngs/s, 0.00 non-youngs/sPages read 709875, created 9848, written 22418380.00 reads/s, 0.15 creates/s, 62.13 writes/sBuffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/sLRU len: 719723, unzip_LRU len: 0I/O sum[0]:cur[0], unzip sum[0]:cur[0]--------------ROW OPERATIONS--------------6 queries inside InnoDB, 0 queries in queue7 read views open inside InnoDB---OLDEST VIEW---Normal read viewRead view low limit trx n 39C5CF2Read view up limit trx id 39C5C77Read view low limit trx id 39C5CF2Read view individually stored trx ids:Read view trx id 39C5CF1Read view trx id 39C5CE1Read view trx id 39C5C7FRead view trx id 39C5C77-----------------Main thread id 53130254144, state: sleepingNumber of rows inserted 141596, updated 6422037, deleted 194294, read 1093783039784.15 inserts/s, 72.50 updates/s, 0.78 deletes/s, 3178914.89 reads/s------------TRANSACTIONS------------Trx id counter 39C60BAPurge done for trx's n < 39C5CF4 undo n < 0History list length 3366LIST OF TRANSACTIONS FOR EACH SESSION:---TRANSACTION 0, not startedMySQL thread id 2954097, OS thread handle 0xc5ecf22c0, query id 43453474 192.168.1.11 dcishow engine innodb status---TRANSACTION 0, not startedMySQL thread id 2954079, OS thread handle 0xc5ecf37c0, query id 43453465 192.168.1.12 pda_main_ipb---TRANSACTION 0, not startedMySQL thread id 2954084, OS thread handle 0xc5ecf30c0, query id 43453463 192.168.1.12 pda_main_ipb---TRANSACTION 39C60B7, not startedMySQL thread id 2954095, OS thread handle 0xc5ecf4240, query id 43453462 192.168.1.12 pda_main_ipb---TRANSACTION 39C60A9, not startedMySQL thread id 2954092, OS thread handle 0xc5ecf2800, query id 43453428 192.168.1.12 pda_main_ipb---TRANSACTION 39C6095, not startedMySQL thread id 2954087, OS thread handle 0xc5ecf4780, query id 43453394 192.168.1.12 pda_main_ipb---TRANSACTION 39C6022, not startedMySQL thread id 2954064, OS thread handle 0xc5ecf2d40, query id 43453200 192.168.1.12 pda_main_ipb---TRANSACTION 39C6063, not startedMySQL thread id 2954004, OS thread handle 0xc5ecf3d00, query id 43453331 192.168.1.12 pda_main_ipb---TRANSACTION 39C60B9, ACTIVE 0 sec, thread declared inside InnoDB 177mysql tables in use 1, locked 0MySQL thread id 2954098, OS thread handle 0xc5ecf2f00, query id 43453473 192.168.1.12 pda_main_ipb Sending dataSELECT COUNT(*) AS `cnt` FROM `ibf_posts` p WHERE p.`topic_id`=5832 AND p.`pid`<5786509 AND p.`pid`!=1580037 AND p.`queued`=0Trx read view will not see trx with id >= 39C60BA, sees < 39C5F61---TRANSACTION 39C60A0, ACTIVE 1 sec fetching rows, thread declared inside InnoDB 172mysql tables in use 4, locked 0MySQL thread id 2954090, OS thread handle 0xc5ecf4400, query id 43453416 192.168.1.12 pda_main_ipb Sending dataSELECT p.`pid`, p.`append_edit`, p.`edit_time`, p.`use_sig`, p.`ip_address`, p.`post_date`, p.`icon_id`, p.`post`, p.`queued`, p.`edit_name`, p.`post_attach`, p.`post_edit_reason`, p.`post_karma`, m.`id`, m.`name`, m.`mgroup`, m.`joined`, m.`posts`, m.`title`, m.`warn_level`, m.`last_activity`, m.`temp_ban`, m.`restrict_post`, m.`login_anonymous`, m.`reputation`, me.`signature`, me.`avatar_location`, me.`avatar_size`, me.`avatar_type`, pf.`field_5` FROM `ibf_posts` p LEFT JOIN `ibf_members` m ON ( m.`id`=p.`author_id` ) LEFT JOIN `ibf_member_extra` me ON ( me.`id`=p.`author_id` ) LEFT JOIN `ibTrx read view will not see trx with id >= 39C60A2, sees < 39C5F61---TRANSACTION 39C6068, ACTIVE 1 sec starting index read, thread declared inside InnoDB 131mysql tables in use 4, locked 0MySQL thread id 2954086, OS thread handle 0xc5ecf4cc0, query id 43453336 192.168.1.12 pda_main_ipb Sending dataSELECT p.`pid`, p.`append_edit`, p.`edit_time`, p.`use_sig`, p.`ip_address`, p.`post_date`, p.`icon_id`, p.`post`, p.`queued`, p.`edit_name`, p.`post_attach`, p.`post_edit_reason`, p.`post_karma`, m.`id`, m.`name`, m.`mgroup`, m.`joined`, m.`posts`, m.`title`, m.`warn_level`, m.`last_activity`, m.`temp_ban`, m.`restrict_post`, m.`login_anonymous`, m.`reputation`, me.`signature`, me.`avatar_location`, me.`avatar_size`, me.`avatar_type`, pf.`field_5` FROM `ibf_posts` p LEFT JOIN `ibf_members` m ON ( m.`id`=p.`author_id` ) LEFT JOIN `ibf_member_extra` me ON ( me.`id`=p.`author_id` ) LEFT JOIN `ibTrx read view will not see trx with id >= 39C6069, sees < 39C5F61---TRANSACTION 39C603D, ACTIVE 1 sec fetching rows, thread declared inside InnoDB 312mysql tables in use 3, locked 0MySQL thread id 2954065, OS thread handle 0xc5ecf2480, query id 43453256 192.168.1.12 pda_main_ipb Copying to tmp tableSELECT s.topic_track_type, s.trid, s.member_id, s.topic_id, s.last_sent, s.start_date as track_started, t.*, f.id as forum_id, f.name as forum_name FROM ibf_tracker s LEFT JOIN ibf_topics t ON (t.tid=s.topic_id) LEFT JOIN ibf_forums f ON (f.id=t.forum_id) WHERE s.member_id=144064 AND t.last_post > '1319292102' ORDER BY f.id, t.last_post DESCTrx read view will not see trx with id >= 39C603E, sees < 39C5CF1---TRANSACTION 39C6013, ACTIVE 1 sec, thread declared inside InnoDB 452mysql tables in use 1, locked 0MySQL thread id 2954069, OS thread handle 0xc5ecf3280, query id 43453167 192.168.1.12 pda_main_ipb Sending dataSELECT email,id FROM ibf_members WHERE LOWER(email)='######@mail.ru' LIMIT 0,1Trx read view will not see trx with id >= 39C6014, sees < 39C5CF1---TRANSACTION 39C5F61, ACTIVE 1 sec, thread declared inside InnoDB 1mysql tables in use 3, locked 0MySQL thread id 2954037, OS thread handle 0xc5ecf4e80, query id 43452861 192.168.1.12 pda_main_ipb Sorting resultSELECT r.*, m.members_display_name, t.title, t.forum_id FROM ibf_reputation r LEFT JOIN ibf_members m on m.id=r.from_user LEFT JOIN ibf_topics t ON t.tid=r.topic WHERE to_user = 817524 ORDER BY created DESC LIMIT 0,30Trx read view will not see trx with id >= 39C5F62, sees < 39C5CF1----------------------------END OF INNODB MONITOR OUTPUT============================

      Comment


      • #4
        The value in the graph is confirmed by your output: History list length 3366

        Now that I read more, I don't think the explanation on the cacti wiki is correct. The number increases after a transaction is completed, so long running transaction (which you don't have) are not important.

        http://www.mysqlperformanceblog.com/2006/07/17/show-innodb-s tatus-walk-through/
        http://mysqlha.blogspot.com/2008/07/how-do-you-know-when-inn odb-gets-behind.html

        It is strange that the value is so high even if you have no load at all.

        Comment


        • #5
          The history list length is the number of pages in the undo log. It just means that purge is delayed for some reason -- which could be due to the very high insert rate of reloading the data. This can happen due to a long-running transaction, but it can also happen if purge simply can't keep up.

          Comment


          • #6
            Well yes, but
            1. it was ok with 5.1.
            2. it's a web workload with typical page generation time about 0.1 sec, so there is no long-running queries.
            3. it goes to about 2000 immediately after start, when no clients are connected and no queries are executed, and stays sharp at the same value while the buffer pool is loaded.
            4. and the most frustrating, it shows REVERSE correlation with the load, lower at daytime, while insert/update rate is high, and a bit higher at night, while insert/update rate is times (seven times) lower. It can be seen in the picture from the first post.

            Comment

            Working...
            X