History list length never goes to zero

[Swany]

I ran a 1000 warehouse TPCC with various buffer pool sizes (1GB,6GB,10GB) to test IO load workload against PCI express SSD.

I experienced apparent leak of UNDO. The history list length never goes to zero, even after database restart.

=====================================
110314 9:52:09 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 5 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 21105 1_second, 21105 sleeps, 2036 10_second, 750 background, 750 flush
srv_master_thread log flush and writes: 21897
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4947287, signal count 3459129
Mutex spin waits 4205407, rounds 5731181, OS waits 68666
RW-shared spins 1733095, rounds 46365452, OS waits 1089890
RW-excl spins 5320582, rounds 168091383, OS waits 3634873
Spin rounds per wait: 1.36 mutex, 26.75 RW-shared, 31.59 RW-excl
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (read thread)
I/O thread 7 state: waiting for completed aio requests (read thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
I/O thread 10 state: waiting for completed aio requests (write thread)
I/O thread 11 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0] , aio writes: 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
17282549 OS file reads, 8839576 OS file writes, 1993560 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 1155, seg size 1157, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 21249841, node heap has 3 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 379862309251
Log flushed up to 379862309251
Last checkpoint at 379862309251
Max checkpoint age 869019772
Checkpoint age target 841862905
Modified age 0
Checkpoint age 0
0 pending log writes, 0 pending chkp writes
722551 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 11025776640; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 170052096 (169998728 + 53368)
    Page hash 10625704 (buffer pool 0 only)
    Dictionary cache 42777682 (42501104 + 276578)
    File system 86632 (82672 + 3960)
    Lock system 26563392 (26563016 + 376)
    Recovery system 0 (0 + 0)
    Threads 407440 (406936 + 504)
Dictionary memory allocated 276578
Buffer pool size 655359
Buffer pool size, bytes 10737401856
Free buffers 428145
Database pages 227211
Old database pages 83892
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2677471, not young 850215625
0.00 youngs/s, 0.00 non-youngs/s
Pages read 17282535, created 6119051, written 7420242
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s
LRU len: 227211, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 6DB9999
Read view up limit trx id 6DB9999
Read view low limit trx id 6DB9999
Read view individually stored trx ids:
-----------------
Main thread process no. 13247, id 140341878757120, state: waiting for server activity
Number of rows inserted 290448958, updated 75684, deleted 35227, read 1054863466
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 6DB9999
Purge done for trx's n:o < 6DB9998 undo n:o < 0
History list length 637
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started, process no 13247, OS thread id 140341857511168
MySQL thread id 33390, query id 251992 localhost root
show engine innodb status
----------------------------
END OF INNODB MONITOR OUTPUT
============================

mysql> select * from INNODB_RSEG;
+---------+----------+----------+---------+------------+-----------+
| rseg_id | space_id | zip_size | page_no | max_size | curr_size |
+---------+----------+----------+---------+------------+-----------+
| 0 | 0 | 0 | 6 | 4294967294 | 1 |
| 1 | 0 | 0 | 46 | 4294967294 | 3 |
| 2 | 0 | 0 | 47 | 4294967294 | 3 |
| 3 | 0 | 0 | 48 | 4294967294 | 3 |
| 4 | 0 | 0 | 49 | 4294967294 | 3 |
| 5 | 0 | 0 | 50 | 4294967294 | 3 |
| 6 | 0 | 0 | 51 | 4294967294 | 3 |
| 7 | 0 | 0 | 52 | 4294967294 | 3 |
| 8 | 0 | 0 | 53 | 4294967294 | 3 |
| 9 | 0 | 0 | 54 | 4294967294 | 3 |
| 10 | 0 | 0 | 55 | 4294967294 | 3 |
| 11 | 0 | 0 | 56 | 4294967294 | 3 |
| 12 | 0 | 0 | 57 | 4294967294 | 3 |
| 13 | 0 | 0 | 58 | 4294967294 | 3 |
| 14 | 0 | 0 | 59 | 4294967294 | 3 |
| 15 | 0 | 0 | 60 | 4294967294 | 3 |
| 16 | 0 | 0 | 61 | 4294967294 | 3 |
| 17 | 0 | 0 | 62 | 4294967294 | 3 |
| 18 | 0 | 0 | 63 | 4294967294 | 3 |
| 19 | 0 | 0 | 192 | 4294967294 | 3 |
| 20 | 0 | 0 | 193 | 4294967294 | 3 |
| 21 | 0 | 0 | 194 | 4294967294 | 3 |
| 22 | 0 | 0 | 195 | 4294967294 | 3 |
| 23 | 0 | 0 | 196 | 4294967294 | 3 |
| 24 | 0 | 0 | 197 | 4294967294 | 3 |
| 25 | 0 | 0 | 198 | 4294967294 | 3 |
| 26 | 0 | 0 | 199 | 4294967294 | 3 |
| 27 | 0 | 0 | 200 | 4294967294 | 2 |
| 28 | 0 | 0 | 201 | 4294967294 | 3 |
| 29 | 0 | 0 | 202 | 4294967294 | 3 |
| 30 | 0 | 0 | 203 | 4294967294 | 3 |
| 31 | 0 | 0 | 204 | 4294967294 | 3 |
| 32 | 0 | 0 | 205 | 4294967294 | 4 |
| 33 | 0 | 0 | 206 | 4294967294 | 4 |
| 34 | 0 | 0 | 207 | 4294967294 | 4 |
| 35 | 0 | 0 | 208 | 4294967294 | 3 |
| 36 | 0 | 0 | 209 | 4294967294 | 3 |
| 37 | 0 | 0 | 210 | 4294967294 | 3 |
| 38 | 0 | 0 | 211 | 4294967294 | 3 |
| 39 | 0 | 0 | 212 | 4294967294 | 3 |
| 40 | 0 | 0 | 213 | 4294967294 | 3 |
| 41 | 0 | 0 | 214 | 4294967294 | 3 |
| 42 | 0 | 0 | 215 | 4294967294 | 3 |
| 43 | 0 | 0 | 216 | 4294967294 | 3 |
| 44 | 0 | 0 | 217 | 4294967294 | 3 |
| 45 | 0 | 0 | 218 | 4294967294 | 3 |
| 46 | 0 | 0 | 219 | 4294967294 | 3 |
| 47 | 0 | 0 | 220 | 4294967294 | 3 |
| 48 | 0 | 0 | 221 | 4294967294 | 3 |
| 49 | 0 | 0 | 222 | 4294967294 | 3 |
| 50 | 0 | 0 | 223 | 4294967294 | 3 |
| 51 | 0 | 0 | 224 | 4294967294 | 4 |
| 52 | 0 | 0 | 225 | 4294967294 | 3 |
| 53 | 0 | 0 | 226 | 4294967294 | 3 |
| 54 | 0 | 0 | 227 | 4294967294 | 3 |
| 55 | 0 | 0 | 228 | 4294967294 | 3 |
| 56 | 0 | 0 | 229 | 4294967294 | 3 |
| 57 | 0 | 0 | 230 | 4294967294 | 3 |
| 58 | 0 | 0 | 231 | 4294967294 | 3 |
| 59 | 0 | 0 | 232 | 4294967294 | 4 |
| 60 | 0 | 0 | 233 | 4294967294 | 3 |
| 61 | 0 | 0 | 234 | 4294967294 | 4 |
| 62 | 0 | 0 | 235 | 4294967294 | 3 |
| 63 | 0 | 0 | 236 | 4294967294 | 4 |
| 64 | 0 | 0 | 237 | 4294967294 | 3 |
| 65 | 0 | 0 | 238 | 4294967294 | 3 |
| 66 | 0 | 0 | 239 | 4294967294 | 3 |
| 67 | 0 | 0 | 240 | 4294967294 | 3 |
| 68 | 0 | 0 | 241 | 4294967294 | 3 |
| 69 | 0 | 0 | 243 | 4294967294 | 3 |
| 70 | 0 | 0 | 244 | 4294967294 | 4 |
| 71 | 0 | 0 | 245 | 4294967294 | 3 |
| 72 | 0 | 0 | 246 | 4294967294 | 3 |
| 73 | 0 | 0 | 247 | 4294967294 | 4 |
| 74 | 0 | 0 | 248 | 4294967294 | 3 |
| 75 | 0 | 0 | 249 | 4294967294 | 3 |
| 76 | 0 | 0 | 250 | 4294967294 | 4 |
| 77 | 0 | 0 | 251 | 4294967294 | 3 |
| 78 | 0 | 0 | 252 | 4294967294 | 3 |
| 79 | 0 | 0 | 253 | 4294967294 | 3 |
| 80 | 0 | 0 | 254 | 4294967294 | 3 |
| 81 | 0 | 0 | 255 | 4294967294 | 3 |
| 82 | 0 | 0 | 256 | 4294967294 | 3 |
| 83 | 0 | 0 | 257 | 4294967294 | 3 |
| 84 | 0 | 0 | 258 | 4294967294 | 4 |
| 85 | 0 | 0 | 259 | 4294967294 | 4 |
| 86 | 0 | 0 | 260 | 4294967294 | 3 |
| 87 | 0 | 0 | 261 | 4294967294 | 3 |
| 88 | 0 | 0 | 262 | 4294967294 | 3 |
| 89 | 0 | 0 | 263 | 4294967294 | 3 |
| 90 | 0 | 0 | 264 | 4294967294 | 3 |
| 91 | 0 | 0 | 265 | 4294967294 | 3 |
| 92 | 0 | 0 | 266 | 4294967294 | 3 |
| 93 | 0 | 0 | 267 | 4294967294 | 3 |
| 94 | 0 | 0 | 268 | 4294967294 | 3 |
| 95 | 0 | 0 | 269 | 4294967294 | 3 |
| 96 | 0 | 0 | 270 | 4294967294 | 3 |
| 97 | 0 | 0 | 271 | 4294967294 | 3 |
| 98 | 0 | 0 | 272 | 4294967294 | 3 |
| 99 | 0 | 0 | 273 | 4294967294 | 3 |
| 100 | 0 | 0 | 274 | 4294967294 | 3 |
| 101 | 0 | 0 | 275 | 4294967294 | 4 |
| 102 | 0 | 0 | 276 | 4294967294 | 2 |
| 103 | 0 | 0 | 277 | 4294967294 | 3 |
| 104 | 0 | 0 | 278 | 4294967294 | 3 |
| 105 | 0 | 0 | 279 | 4294967294 | 3 |
| 106 | 0 | 0 | 280 | 4294967294 | 3 |
| 107 | 0 | 0 | 281 | 4294967294 | 3 |
| 108 | 0 | 0 | 282 | 4294967294 | 3 |
| 109 | 0 | 0 | 283 | 4294967294 | 4 |
| 110 | 0 | 0 | 284 | 4294967294 | 3 |
| 111 | 0 | 0 | 285 | 4294967294 | 3 |
| 112 | 0 | 0 | 286 | 4294967294 | 3 |
| 113 | 0 | 0 | 287 | 4294967294 | 3 |
| 114 | 0 | 0 | 288 | 4294967294 | 3 |
| 115 | 0 | 0 | 289 | 4294967294 | 2 |
| 116 | 0 | 0 | 290 | 4294967294 | 4 |
| 117 | 0 | 0 | 291 | 4294967294 | 3 |
| 118 | 0 | 0 | 292 | 4294967294 | 3 |
| 119 | 0 | 0 | 293 | 4294967294 | 3 |
| 120 | 0 | 0 | 294 | 4294967294 | 3 |
| 121 | 0 | 0 | 295 | 4294967294 | 3 |
| 122 | 0 | 0 | 296 | 4294967294 | 3 |
| 123 | 0 | 0 | 297 | 4294967294 | 3 |
| 124 | 0 | 0 | 298 | 4294967294 | 3 |
| 125 | 0 | 0 | 299 | 4294967294 | 3 |
| 126 | 0 | 0 | 300 | 4294967294 | 3 |
| 127 | 0 | 0 | 301 | 4294967294 | 3 |
+---------+----------+----------+---------+------------+-----------+
128 rows in set (0.00 sec)

mysql> select sum(curr_size) from INNODB_RSEG;
+----------------+
| sum(curr_size) |
+----------------+
| 394 |
+----------------+
1 row in set (0.00 sec)

mysql> select page_type, count(*) pages, 16384 * count(*) as pages_as_bytes from innodb_buffer_pool_pages group by page_type order by pages desc;
+-----------+--------+----------------+
| page_type | pages | pages_as_bytes |
+-----------+--------+----------------+
| index | 646868 | 10598285312 |
| undo_log | 8079 | 132366336 |
| bitmap | 211 | 3457024 |
| sys | 130 | 2129920 |
| xdes | 54 | 884736 |
| inode | 12 | 196608 |
| fsp_hdr | 3 | 49152 |
| allocated | 1 | 16384 |
| trx_sys | 1 | 16384 |
+-----------+--------+----------------+
9 rows in set (0.95 sec)

[Vadim Tkachenko (vadim-tk)]

I correspond this problem to
http://bugs.mysql.com/bug.php?id=59291

[Swany (greenlion)]

My database has been idle for days at a time and the undo length never
goes to zero. It never spiked into the tens of thousands and it
doesn't grow unbounded.

The server has no activity (innodb is 'waiting for server activity')
but the history list length is not zero.

I am not sure how this is related to 59291. Can you please explain?

--Justin

On Mon, Mar 14, 2011 at 10:19 AM, Vadim Tkachenko <email address hidden> wrote:
> I correspond this problem to
> http://bugs.mysql.com/bug.php?id=59291
>
> ** Bug watch added: MySQL Bug System #59291
>   http://bugs.mysql.com/bug.php?id=59291
>
> --
> You received this bug notification because you are a direct subscriber
> of the bug.
> https://bugs.launchpad.net/bugs/734956
>
> Title:
>  History list length never goes to zero
>
> To unsubscribe from this bug, go to:
> https://bugs.launchpad.net/percona-server/+bug/734956/+subscribe
>

[Stewart Smith (stewart)]

We may just wait for upstream bug fix to hit releases unless there is customer request to backport..

[Yasufumi Kinoshita (yasufumi-kinoshita)]

I think it was already fixed at XtraDB.
Did you test at current version?

[Yasufumi Kinoshita (yasufumi-kinoshita)]

I mean it should be duplicate of
https://bugs.launchpad.net/percona-projects-qa/+bug/756387