MySQL Bugs: #23335: InnoDB hangs if BLOBS and BINLOG are used during new performance test

Bug #23335	InnoDB hangs if BLOBS and BINLOG are used during new performance test
Submitted:	16 Oct 2006 14:16	Modified:	5 Sep 2007 20:45
Reporter:	Jonathan Miller	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	5.1.12	OS:	Linux (Linux 32 Bit)
Assigned to:	Andrei Elkin	CPU Architecture:	Any

Description:
Hi,

I have created a new performance perl script that does the following:

Begin Loop
- Create Simple Table
- Drop Simple Table
End Loop

Begin Loop
- Create Simple Table
- Load Table
- Drop Simple Fully Loaded Table
End Loop

Begin Loop
- Create Complex Table (Text, Varchar, BLOB, etc..)
- Drop Complex Table (Text, Varchar, BLOB, etc..)
End Loop

Begin Loop
- Create Complex Table (Text, Varchar, BLOB, etc..)
- Load Table
- Drop Complex Fully Loaded Table (Text, Varchar, BLOB, etc..)
End Loop

The test loops 6 times through each (loops can be increased or decreased). The load is currently set to 10,000 rows. I have tried the test with Cluster, MyISAM and InnoDB.

During the run with InnoDB, the test hung during the second load of the complex table. I have repeated this many times and the hang always seems to happen around 6300+ rows on the second load. If I comment out the blob column the test will complete. Also if I remove the binlog usage from MySQLD the test completes. This leads me to believe that we have a BLOB/Binlog issues using InnoDB.

The Perl script actually uses one of the MySQL executable files as the BLOB and loads it into the Database.

How to repeat:
1) Download the 5.1 main tree and build the MAX build.
2) Download the Perl script and the executable file that I will attach to this report
3) Make sure that:
a) Binlog is turned on
b) That the executable file is in the same directory as the script.
4) Start the script running using the following command:
perl load_perf.pl -ho localhost --so -e InnoDB

The test should make it through the first past. Then during the second pass it should hang a little past 6300 rows.

Perl Script

Attachment: load_perf.pl (application/x-perl, text), 19.34 KiB.

I am not able to upload the executable do to size. I am using ndb_cpcd as the blob.

Jonathan,

what do SHOW INNODB STATUS and SHOW PROCESSLIST report during the hang?

Regards,

Heikki

mysql> SHOW INNODB STATUS\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
061019 16:30:24 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 5 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 351, signal count 351
Mutex spin waits 729, rounds 6597, OS waits 231
RW-shared spins 182, OS waits 91; RW-excl spins 23, OS waits 21
------------
TRANSACTIONS
------------
Trx id counter 0 197681
Purge done for trx's n:o < 0 191440 undo n:o < 0 0
History list length 21
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 197680, not started, process no 24591, OS thread id 2975857584
MySQL thread id 3, query id 76289 localhost root
SHOW INNODB STATUS
---TRANSACTION 0 197678, not started, process no 24591, OS thread id 2978368432
mysql tables in use 1, locked 1
MySQL thread id 2, query id 76285 localhost root update
INSERT into t2 values('6227', '3',
                                               'G', 'GGGGGGGGGGGGGGGGGGGGGGGGGGGGGGGG\n
GGGGGGGGG\n                         _G_G_G_G_G',
                                               '⌂ELF☺☺☺\0\0\0\0\0\0\0\0\0☻\0♥\0☺\0\0\0??\0\0\0
--------
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
898 OS file reads, 158058 OS file writes, 155148 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 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 34679, used cells 1, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1 939508351
Log flushed up to   1 939508351
Last checkpoint at  1 939508351
0 pending log writes, 0 pending chkp writes
153509 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 18347782; in additional pool allocated 885504
Dictionary memory allocated 24616
Buffer pool size   512
Free buffers       0
Database pages     511
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 901, created 65993, written 67321
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 24591, id 2996284336, state: waiting for server activity
Number of rows inserted 76227, updated 0, deleted 0, read 33730
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set, 1 warning (0.01 sec)

mysql>
mysql> show warnings;
+---------+------+---------------------------------------------------------------------------------------------------------------------
-----------+
| Level   | Code | Message
           |
+---------+------+---------------------------------------------------------------------------------------------------------------------
-----------+
| Warning | 1541 | The syntax 'SHOW INNODB STATUS' is deprecated and will be removed in MySQL 5.2. Please use 'SHOW ENGINE INNODB STATU
S' instead |
+---------+------+---------------------------------------------------------------------------------------------------------------------
-----------+
1 row in set (0.00 sec)

mysql>

mysql> SHOW PROCESSLIST\G
*************************** 1. row ***************************
     Id: 1
   User: system user
   Host:
     db:
Command: Daemon
   Time: 0
  State: Waiting for event from ndbcluster
   Info: NULL
*************************** 2. row ***************************
     Id: 2
   User: root
   Host: localhost
     db: perf
Command: Query
   Time: 1050
  State: update
   Info: INSERT into t2 values('6227', '3',
                                               'G', 'GGGGGGGGGGG
*************************** 3. row ***************************
     Id: 3
   User: root
   Host: localhost
     db: perf
Command: Query
   Time: 0
  State: NULL
   Info: SHOW PROCESSLIST
3 rows in set (0.00 sec)

mysql>

Hi,

I did not change the default for replication, so it should have been mixed.

Cheers,
/jeb

This is no longer an issue with the current mysql-5.1-rpl-new clone:

Total Average t2 load time = (669.166666666667)