Bug #31774 | purge stall cause ibdata growing | ||
---|---|---|---|
Submitted: | 23 Oct 2007 3:31 | Modified: | 24 Oct 2007 15:10 |
Reporter: | li david | Email Updates: | |
Status: | Closed | Impact on me: | |
Category: | MySQL Server: InnoDB storage engine | Severity: | S2 (Serious) |
Version: | 5.0.27 | OS: | Linux (2.6.9-42.ELsmp) |
Assigned to: | Heikki Tuuri | CPU Architecture: | Any |
[23 Oct 2007 3:31]
li david
[23 Oct 2007 4:51]
Valeriy Kravchuk
Thank you for a problem report. Please, send the entire SHOW INNODB STATUS and steps to reproduce a problem, if any.
[23 Oct 2007 5:01]
li david
mysql> show engine innodb status \G; *************************** 1. row *************************** Status: ===================================== 071023 12:57:02 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 42 seconds ---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 381252209, signal count 366228324 Mutex spin waits 974865083, rounds 2260332540, OS waits 284391714 RW-shared spins 165192304, OS waits 20048488; RW-excl spins 463371699, OS waits 10995091 ------------------------ LATEST DETECTED DEADLOCK ------------------------ 071023 12:05:24 *** (1) TRANSACTION: TRANSACTION 3 720818925, ACTIVE 0 sec, process no 26724, OS thread id 620096432 starting index read mysql tables in use 1, locked 1 LOCK WAIT 5 lock struct(s), heap size 1024, undo log entries 1 MySQL thread id 83994, query id 2977002525 192.168.113.151 tlbb Searching rows for update update t_iteminfo set charguid = pcharguid, guid = pguid, world = pworld, server = pserver, itemtype = pitemtype, pos = ppos, visualid = pvisualid, maxgemid = pmaxgemid, fixattr = pfixattr, p1 = pp1, p2 = pp2, p3 = pp3, p4 = pp4, p5 = pp5, p6 = pp6, p7 = pp7, p8 = pp8, p9 = pp9, p10 = pp10, p11 = pp11, p12 = pp12, p13 = pp13, p14 = pp14, p15 = pp15, p16 = pp16, p17 = pp17, isvalid = pisvalid, dbversion = pdbversion, creator = pcreator, var = pvar where charguid=pcharguid and pos=ppos and rdbversion<=pdbversion *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 53 page no 130641 n bits 1000 index `Index_it_charguid` of table `tlbbdb/t_iteminfo` trx id 3 720818925 lock_mode X waiting Record lock, heap no 329 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 957b5e8c; asc {^ ;; 1: len 8; hex 8000000000aac7cf; asc ;; *** (2) TRANSACTION: TRANSACTION 3 720818924, ACTIVE 0 sec, process no 26724, OS thread id 620297136 fetching rows, thread declared inside InnoDB 427 mysql tables in use 1, locked 1 22 lock struct(s), heap size 2496 MySQL thread id 83997, query id 2977002523 192.168.113.152 tlbb Searching rows for update update t_iteminfo set charguid = pcharguid, guid = pguid, world = pworld, server = pserver, itemtype = pitemtype, pos = ppos, visualid = pvisualid, maxgemid = pmaxgemid, fixattr = pfixattr, p1 = pp1, p2 = pp2, p3 = pp3, p4 = pp4, p5 = pp5, p6 = pp6, p7 = pp7, p8 = pp8, p9 = pp9, p10 = pp10, p11 = pp11, p12 = pp12, p13 = pp13, p14 = pp14, p15 = pp15, p16 = pp16, p17 = pp17, isvalid = pisvalid, dbversion = pdbversion, creator = pcreator, var = pvar where charguid=pcharguid and pos=ppos and rdbversion<=pdbversion *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 53 page no 130641 n bits 1000 index `Index_it_charguid` of table `tlbbdb/t_iteminfo` trx id 3 720818924 lock_mode X Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0 0: len 8; hex 73757072656d756d; asc supremum;; Record lock, heap no 329 PHYSICAL RECORD: n_fields 2; compact format; info bits 0 0: len 4; hex 957b5e8c; asc {^ ;; 1: len 8; hex 8000000000aac7cf; asc ;; *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 53 page no 160077 n bits 184 index `PRIMARY` of table `tlbbdb/t_iteminfo` trx id 3 720818924 lock_mode X locks rec but not gap waiting Record lock, heap no 112 PHYSICAL RECORD: n_fields 33; compact format; info bits 0 0: len 8; hex 8000000000aec3a5; asc ;; 1: len 6; hex 00032af6d2ed; asc * ;; 2: len 7; hex 00001870042fe4; asc p / ;; 3: len 4; hex 957b5e8c; asc {^ ;; 4: len 4; hex 856b5d03; asc k] ;; 5: len 4; hex 80000024; asc $;; 6: len 4; hex 80000001; asc ;; 7: len 4; hex 81d1689b; asc h ;; 8: len 2; hex 807d; asc };; 9: len 4; hex 80010010; asc ;; 10: len 4; hex 93880000; asc ;; 11: len 4; hex 8a010000; asc ;; 12: len 4; hex 80000027; asc ';; 13: len 4; hex 851bfe01; asc ;; 14: len 4; hex 80003f00; asc ? ;; 15: len 4; hex 81000400; asc ;; 16: len 4; hex 8308000a; asc ;; 17: len 4; hex 80a00002; asc ;; 18: len 4; hex 80000105; asc ;; 19: len 4; hex 80000000; asc ;; 20: len 4; hex 80000000; asc ;; 21: len 4; hex 80000000; asc ;; 22: len 4; hex 80000000; asc ;; 23: len 4; hex 80000000; asc ;; 24: len 4; hex 80000000; asc ;; 25: len 4; hex 80000000; asc ;; 26: len 0; hex ; asc ;; 27: len 2; hex 8000; asc ;; 28: len 4; hex 8000041e; asc ;; 29: len 0; hex ; asc ;; 30: len 0; hex ; asc ;; 31: len 4; hex 80000000; asc ;; 32: len 4; hex 7fffffff; asc ;; *** WE ROLL BACK TRANSACTION (2)
[23 Oct 2007 5:03]
li david
....continue ------------ TRANSACTIONS ------------ Trx id counter 3 723129795 Purge done for trx's n:o < 3 524791548 undo n:o < 0 0 History list length 62765841 Total number of lock structs in row lock hash table 24 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0 0, not started, process no 26724, OS thread id 608656304 MySQL thread id 84000, query id 2986263014 localhost root show engine innodb status ---TRANSACTION 3 723129794, not started, process no 26724, OS thread id 616483760 MySQL thread id 83876, query id 2986263013 192.168.113.154 tlbb ---TRANSACTION 3 721925119, not started, process no 26724, OS thread id 607853488 MySQL thread id 83737, query id 2981465355 192.168.113.154 tlbb ---TRANSACTION 3 717141919, not started, process no 26724, OS thread id 609459120 MySQL thread id 83738, query id 2962123894 192.168.113.154 tlbb ---TRANSACTION 3 710501214, not started, process no 26724, OS thread id 622705584 MySQL thread id 83739, query id 2935344787 192.168.113.154 tlbb ---TRANSACTION 3 722373391, not started, process no 26724, OS thread id 607652784 MySQL thread id 83736, query id 2983244682 192.168.113.154 tlbb ---TRANSACTION 3 722374977, not started, process no 26724, OS thread id 613874608 MySQL thread id 83734, query id 2983251153 192.168.113.154 tlbb ---TRANSACTION 3 722374882, not started, process no 26724, OS thread id 607452080 MySQL thread id 83735, query id 2983250816 192.168.113.154 tlbb ---TRANSACTION 3 722677559, not started, process no 26724, OS thread id 619092912 MySQL thread id 83733, query id 2984451877 192.168.113.154 tlbb ---TRANSACTION 3 723128983, not started, process no 26724, OS thread id 612268976 MySQL thread id 83732, query id 2986262016 192.168.113.154 tlbb ---TRANSACTION 3 723129730, not started, process no 26724, OS thread id 610864048 MySQL thread id 83731, query id 2986262888 192.168.113.154 tlbb ---TRANSACTION 3 722863059, not started, process no 26724, OS thread id 612871088 MySQL thread id 83729, query id 2986263003 192.168.113.154 tlbb ---TRANSACTION 3 723129259, ACTIVE 83 sec, process no 26724, OS thread id 620096432 updating or deleting, thread declared inside InnoDB 473 mysql tables in use 1, locked 1 5 lock struct(s), heap size 1024, undo log entries 13 MySQL thread id 83994, query id 2986262289 192.168.113.151 tlbb Updating update t_iteminfo set isvalid = 0 where charguid = 360473095 and dbversion<=22 ---TRANSACTION 3 723129101, ACTIVE 96 sec, process no 26724, OS thread id 614677424 updating or deleting, thread declared inside InnoDB 466 mysql tables in use 1, locked 1 5 lock struct(s), heap size 1024, undo log entries 15 MySQL thread id 83998, query id 2986262126 192.168.113.152 tlbb Updating update t_iteminfo set isvalid = 0 where charguid = 360159726 and dbversion<=7184 ---TRANSACTION 3 723129022, ACTIVE 96 sec, process no 26724, OS thread id 609659824 updating or deleting, thread declared inside InnoDB 469 mysql tables in use 1, locked 1 17 lock struct(s), heap size 5504, undo log entries 15 MySQL thread id 83996, query id 2986262025 192.168.113.153 tlbb updating delete from t_skill where charguid = 360314842 and dbversion<=6322 -------- 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 (write thread) Pending normal aio reads: 0, aio writes: 0, ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 Pending flushes (fsync) log: 0; buffer pool: 0 344408211 OS file reads, 140483994 OS file writes, 4213833000 OS fsyncs 9.36 reads/s, 17426 avg bytes/read, 133.95 writes/s, 11.09 fsyncs/s ------------------------------------- INSERT BUFFER AND ADAPTIVE HASH INDEX ------------------------------------- Ibuf: size 1, free list len 0, seg size 2, 176 inserts, 176 merged recs, 176 merges Hash table size 8850487, used cells 3524880, node heap has 4405 buffer(s) 26.95 hash searches/s, 38.07 non-hash searches/s --- LOG --- Log sequence number 879 204287128 Log flushed up to 879 204287128 Last checkpoint at 879 35057221 0 pending log writes, 0 pending chkp writes 4193450202 log i/o's done, 1.90 log i/o's/second ---------------------- BUFFER POOL AND MEMORY ---------------------- Total memory allocated 2310640878; in additional pool allocated 6862208 Buffer pool size 131072 Free buffers 0 Database pages 126667 Modified db pages 30797 Pending reads 0 Pending writes: LRU 0, flush list 0, single page 0 Pages read 530207357, created 21537434, written 407272262 9.95 reads/s, 0.00 creates/s, 191.16 writes/s Buffer pool hit rate 960 / 1000 -------------- ROW OPERATIONS -------------- 3 queries inside InnoDB, 0 queries in queue 1 read views open inside InnoDB Main thread process no. 26724, id 667855792, state: sleeping Number of rows inserted 4148528574, updated 3377807624, deleted 4121441753, read 1927383990 0.00 inserts/s, 0.33 updates/s, 0.17 deletes/s, 54.64 reads/s ---------------------------- END OF INNODB MONITOR OUTPUT ============================ 1 row in set (0.05 sec) ERROR: No query specified
[23 Oct 2007 5:13]
li david
As for "How to reproduct step", there is detail step. There are similar state in lots of product db where lots of delete and update sqls were run simultaneously. found that if history list length reach large, purge will be purged. is it true in fact?
[23 Oct 2007 13:09]
Heikki Tuuri
Did you run a big workload so that the purge could not keep up? I see that InnoDB is writing quite a number of buffer pages per second.
[23 Oct 2007 15:40]
Heikki Tuuri
9.36 reads/s, 17426 avg bytes/read, 133.95 writes/s, 11.09 fsyncs/s The status shows so many file writes per second that you might have exhausted the capacity of your disk drive. Your ibdata1 file size is 26 GB, while the buffer pool is only 2 GB. The workload may be disk-bound. When the size of the ibdata1 file grows, it becomes even more severely disk-bound.
[24 Oct 2007 1:10]
li david
Thks a lot!
[24 Oct 2007 1:15]
li david
Yes , there is big workload. if purge can't keep up, would it cause ibdata growing?
[24 Oct 2007 1:22]
li david
Heikki, I guess that if history list length reach certain length, purge will stop work. is it true?
[24 Oct 2007 11:42]
Heikki Tuuri
David, you need to change your application so that causes less write load. Or, if you have lots of RAM and the computer is 64-bit, you can make your buffer pool much bigger. I am closing this bug report because this probably is not a bug. Regards, Heikki
[24 Oct 2007 15:10]
li david
try to upgrade to 64 bit! Thks again!