MySQL Bugs: #38207: Row-based Replication (RBR) is CPU bound (invalidating query cache)

Bug #38207	Row-based Replication (RBR) is CPU bound (invalidating query cache)
Submitted:	17 Jul 2008 16:56	Modified:	7 Aug 2008 6:24
Reporter:	Eric Jensen	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Row Based Replication ( RBR )	Severity:	S5 (Performance)
Version:	5.1.25	OS:	Linux (x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	performance, RBR, replication

Description:
RBR is heinously slow for me because it seems to be CPU bound.
It's constantly in the "invalidating query cache entries (table)"
thread state even though I have query_cache_type = 0 (i.e., OFF). I
see mysql cranking away with 99% CPU usage, whereas when I use
statement-based replication it is decidedly IO bound, with barely any
CPU usage that isn't IO wait. I had hoped for the opposite, and this
seems like buggy behavior... 

I realize this is not a well-encapsulated bug report.  I originally inquired about it a couple places:

http://lists.mysql.com/replication/1335 
http://forums.mysql.com/read.php?26,216227,216227

but received no response.  It is preventing me from upgrading to 5.1.  Shouldn't the lists and forums be merged?

How to repeat:
The bottleneck in my application is bulk inserts (insert into ... values ... with 1500 or so values) into a one-to-many relation, i.e. a table that is only two integers:  a_id, b_id and has a single primary key on (a_id, b_id).  This bottleneck doesn't change between statement based vs. RBR, but the speed of RBR is much worse seemingly due to this cpu usage.

Thank you for a problem report. Please, try to repeat with a newer version, 5.1.26, and, in case of the same problem, send your entire my.cnf and SHOW FULL PROCESSLIST results at the moment when you see the problem.

It's fairly time-consuming for me to recreate my test environment with 5.1.26 instead of 5.1.25.  Are there some specific fixes you think would have influenced this?  You can find my full environment (my.cnf, etc.) in http://bugs.mysql.com/?id=38205

Anyway, we need SHOW FULL PROCESSLIST output here for a deeper analysation.

Here is a reconstruction:

|  786 | system user |           | NULL               | Connect | 180017 | Waiting for master to send event | NULL                                              
|  787 | system user |           | problem_database | Connect |      4 | invalidating query cache entries (table)                           | insert delayed into problem_table (a_id, b_id) values (1088244,878272223),(1114251,878272288),(1114272,878272288),... [about 1500 of these values]
| 5140 | user     | localhost | problem_database | Sleep   |     27 |                                  | NULL                                              
| 5143 | user     | localhost | problem_database | Sleep   |      6 |                                  | NULL                                              
... [about 50 connections open sleeping]

For me this still don't look like a bug. But for get a deeper analysation I need to know the following:

a) which storage engine do you use?
b) output of SHOW VARIABLES
c) your my.cnf files
d) which scheduler is your Linux system using? We recommend to use deadline.

I'm using MyISAM, variables set by the my.cnf in http://bugs.mysql.com/bug.php?id=38205, and using the default cfq scheduler.  This bug is twofold:

1.  RBR is slower than statement-based replication, because it's taking a lot of CPU time (while statement-based was i/o-bound instead).

2.  The replication thread constantly says "invalidating query cache" even though I have the query cache disabled.

I think here is a relation to bug #38551

I will set this bug as duplicate of bug #38551 because the main problem is explained at the other bug. This seems to be a side effect from bug #38551.

Please, when bug #38551 is fixed and your problem still isn't gone feel free to open this bug report again.

I don't agree it's a duplicate. 
Bugfix for 38551 solves the problem only when the Query Cache is OFF. If you have QC enabled, you still get a huge performance hit and huge slave lag.
I vote to reopen this bug. 
If there's no fix in 5.1, I think RBR in 5.1 is pointless, because it brings more performance issues than it solves.

Here is SHOW ENGINE INNODB STATUS example from our slave, which cannot keep up because of this bug:

---TRANSACTION 22AB5694, ACTIVE 20 sec, process no 10807, OS thread id 1380317504 updating or deleting
mysql tables in use 33, locked 33
2 lock struct(s), heap size 368, 1 row lock(s), undo log entries 1
MySQL thread id 13510657, query id 19455898390 invalidating query cache entries (table)
TABLE LOCK table `mydb`.`mytable` trx id 22AB5694 lock mode IX
RECORD LOCKS space id 114 page no 1446530 n bits 168 index `PRIMARY` of table `mydb`.`mytable` trx id 22AB5694 lock_mode X locks rec but not gap

Hello,

i have the same problem with RBR. Normaly my querycache is on.
But after read this bug report, i set it off. But i can see any change after that.

PROCESSLIST show first 'invalidating query cache'.

The actually output from the processlist is:

*************************** 1. row ***************************
     Id: 1
   User: system user
   Host:
     db: NULL
Command: Connect
   Time: 37361
  State: Reading event from the relay log
   Info: NULL
*************************** 2. row ***************************
     Id: 2
   User: system user
   Host:
     db: NULL
Command: Connect
   Time: 2962
  State: Waiting for master to send event
   Info: NULL
*************************** 3. row ***************************
     Id: 61
   User: root
   Host: localhost
     db: NULL
Command: Query
   Time: 0
  State: NULL
   Info: show processlist
3 rows in set (0.00 sec)

Output of 'show innodb status':
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
100715 11:48:28 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 40 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 96185, signal count 96039
Mutex spin waits 0, rounds 3470309, OS waits 21884
RW-shared spins 131733, OS waits 63315; RW-excl spins 31664, OS waits 5923
------------
TRANSACTIONS
------------
Trx id counter 0 118550
Purge done for trx's n:o < 0 118549 undo n:o < 0 0
History list length 5
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 17536, OS thread id 1150077264
MySQL thread id 61, query id 12166 localhost root
show innodb status
---TRANSACTION 0 118549, ACTIVE 524 sec, process no 17536, OS thread id 1149876560 starting index read
mysql tables in use 1, locked 1
3558 lock struct(s), heap size 473072, 473203 row lock(s), undo log entries 236374
MySQL thread id 1, query id 12110 Reading event from the relay log
--------
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
504118 OS file reads, 21353 OS file writes, 4608 OS fsyncs
0.82 reads/s, 35250 avg bytes/read, 5.17 writes/s, 2.57 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 1338, seg size 1340,
10414 inserts, 10414 merged recs, 560 merges
Hash table size 553253, node heap has 1368 buffer(s)
250388.22 hash searches/s, 1568.39 non-hash searches/s
---
LOG
---
Log sequence number 29 3424709053
Log flushed up to   29 3424707337
Last checkpoint at  29 3384970630
0 pending log writes, 0 pending chkp writes
2951 log i/o's done, 2.15 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 439351112; in additional pool allocated 1048576
Dictionary memory allocated 313872
Buffer pool size   16384
Free buffers       0
Database pages     14988
Modified db pages  8551
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 3313409, created 2076, written 39857
1.77 reads/s, 1.07 creates/s, 12.80 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 17536, id 1149274448, state: sleeping
Number of rows inserted 5115, updated 5104, deleted 291588, read 523426904
0.00 inserts/s, 0.00 updates/s, 252.32 deletes/s, 252.32 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set, 1 warning (0.00 sec)