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:
None 
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
Description:
we enable innodb_file_per_table. 
ibdata1  file keep growing.But we have confirmed that there is no any active transaction .
via "show innodb status", we found that purge  stop at n:0 <3 524791548 wich mean that it seem stall and History list length is increasing. as the following snippets:
Trx id counter 3 681909926
Purge done for trx's n:o < 3 524791548 undo n:o < 0 0
History list length 49701538
#ls -l  ibdata1
-rw-rw----  1 mysql mysql 18166165880 10月 22 17:28 ibdata1
ls -l ibdata1
-rw-rw----  1 mysql mysql 26166165504 10月 23 11:28 ibdata1

How to repeat:
none
[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!