I built a system using mysql innodb to archive SMS messages but the
innodb databases are not keeping up with the number of SMS messages
coming in. I'm looking for performance of 200 msgs/sec where 1 msg is
1 database row.
I'm running on Red Linux:
2.4.20-8bigmem #1 SMP Thu Mar 13 17:32:29 EST 2003 i686 i686 i386
GNU/Linux
The machine has dual CPU and 2G of RAM.
My sys admin built the box and installed mysql 4.0.14-standard. This
is the primary application on this box. The only other thing on this
box is Apache which drives a webpage I've created to help my users
query my database.
Here is the setup:
1. There is a Java app on another machine. It opens 4 threads to
mysql on my box. It does inserts into 3 tables. Each insert
statement inserts multiple row at once. Autocommit = 1. These 3
tables store transient data.
2. I have a Perl script that scrubs these 3 transient
tables---collecting info from the 3 tables (using left joins) and
archiving into an archive table.
All tables are innodb. All tables have around 10-13 indices to make
queries fast. Tables have BLOBs.
Perl scrubber script does the extended inserts -- multiple rows with 1
insert statement. I have tried varying the number of rows to scrub
from 250 - 3000 each time. For some reason, the performance level has
been disappointing: i.e.
2004-02-05 15:20:38 PERFORMANCE select_delta = 5 secs (21.74%),
insert_delta = 18 secs (78.26%), delete_delta = 0 secs (0.00%),
total_time = 23 secs, rows_selected = 250, msg_throughput = 10.87
msgs/sec
I've tried reading this newsgroup for ideas. I have tried tweaking
parameters in my.cnf with no significant improvement. I think "show
innodb status" is telling me something but I don't understand what it
is.
Any ideas? my.cnf and "show innodb status" is listed below.
************************************************** *****************************
Current my.cnf:
[mysqld]
datadir=/usr/local/pkg/mysql/data
socket=/tmp/mysql.sock
innodb_data_file_path=ibdata1:8G;ibdata2:8G;ibdata 3:8G;ibdata4:8G;ibdata5:8G;ibdata6:8G;ibdata7:8G;i bdata8:8G;ibdata9:8G
#innodb_data_file_path=ibdata1:10M:autoextend
set-variable=innodb_buffer_pool_size=512M
#set-variable=innodb_buffer_pool_size=750M
set-variable=max_allowed_packet=3M
set-variable=innodb_additional_mem_pool_size=4M
#set-variable=innodb_log_file_size=256M
#set-variable=innodb_log_buffer_size=5M
set-variable=read_buffer_size=3M
#set-variable=sort_buffer_size=5M
#set-variable=innodb_force_recovery=4
set-variable=innodb_flush_log_at_trx_commit=2
#set-variable=key_buffer_size=100M
set-variable=table_cache=1024
set-variable=bulk_insert_buffer_size=64M
[mysql.server]
user=mysql
basedir=/usr/local/pkg/mysql
set-variable=innodb_buffer_pool_size=512M
#set-variable=innodb_buffer_pool_size=750M
set-variable=max_allowed_packet=3M
set-variable=innodb_additional_mem_pool_size=4M
#set-variable=innodb_log_file_size=256M
#set-variable=innodb_log_buffer_size=5M
#set-variable=innodb_force_recovery=4
[mysql.client]
set-variable=max_allowed_packet=3M
[safe_mysqld]
err-log=/home/mysql/logs/mysqld.log
pid-file=/home/mysql/logs/mysqld.pid
************************************************** *****************************
top...
15:24:36 up 10 days, 7:27, 2 users, load average: 2.75, 4.19,
4.75
128 processes: 124 sleeping, 4 running, 0 zombie, 0 stopped
CPU0 states: 21.0% user 2.0% system 0.0% nice 0.0% iowait
75.1% idle
CPU1 states: 7.0% user 0.1% system 0.0% nice 0.0% iowait
91.0% idle
Mem: 2062380k av, 2040868k used, 21512k free, 0k shrd,
46016k buff
1658304k actv, 127272k in_d, 36016k in_c
Swap: 2096472k av, 868148k used, 1228324k free
1224928k cached
************************************************** *****************************
mysql> show innodb status\G
*************************** 1. row ***************************
Status:
=====================================
040205 15:22:27 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 4395247, signal count 4234540
Mutex spin waits 105338261, rounds 281779867, OS waits 1409845
RW-shared spins 5028456, OS waits 2363547; RW-excl spins 1596428, OS
waits 353425
------------------------
LATEST DETECTED DEADLOCK
------------------------
040205 8:13:46
*** (1) TRANSACTION:
TRANSACTION 0 13457607, ACTIVE 0 sec, process no 26805, OS thread id
1680609292 inserting
LOCK WAIT 4 lock struct(s), heap size 320, undo log entries 100
MySQL thread id 410297, query id 2608401 lab-ccbdev.mobilesys.net
172.16.72.26 qos_import update
INSERT INTO routerlog (prefixID, destination, originator,
clientMessageID, filterHistory, logTime, internalMessageID, hostname,
operatorID, filterResu
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 4302273 n bits 616 table
qosdb/routerlog index internalMessageID_hostname_IDX trx id 0 13457607
lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 396 RECORD: info bits 0 0: len 9; hex
313736303032373039; asc 176002709;; 1:
*** (2) TRANSACTION:
TRANSACTION 0 13457606, ACTIVE 0 sec, process no 18640, OS thread id
1938767886 starting index read, thread declared inside InnoDB 400
36 lock struct(s), heap size 5504, undo log entries 33
MySQL thread id 473324, query id 2608400 localhost deleter updating
delete from routerlog where (internalMessageID = '47650096' and
hostname = 'qos4') or (internalMessageID = '47650102' and hostname =
'qos4') or (inter
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 4302273 n bits 616 table
qosdb/routerlog index internalMessageID_hostname_IDX trx id 0 13457606
lock_mode X locks gap before rec
Record lock, heap no 147 RECORD: info bits 32 0: len 8; hex
3130343738373935; asc 10478795;; 1: len 4; hex 716f7337; asc qos7;;
Record lock, heap no 396 RECORD: info bits 0 0: len 9; hex
313736303032373039; asc 176002709;; 1:
Suppressing further record lock prints for this page
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 298411 n bits 416 table
qosdb/routerlog index internalMessageID_hostname_IDX trx id 0 13457606
lock_mode X waiting
Record lock, heap no 120 RECORD: info bits 0 0: len 9; hex
313736323137333331; asc 176217331;; 1:
*** WE ROLL BACK TRANSACTION (2)
------------
TRANSACTIONS
------------
Trx id counter 0 13510990
Purge done for trx's n:o < 0 13493204 undo n:o < 0 0
Total number of lock structs in row lock hash table 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 8950, OS thread id
2007830545
MySQL thread id 490185, query id 2761574 localhost act
show innodb status
---TRANSACTION 0 13510753, not started, process no 22822, OS thread id
1941118990
MySQL thread id 473898, query id 2760983 lab-ccbdev.mobilesys.net
172.16.72.26 qos_import
---TRANSACTION 0 13510677, not started, process no 4409, OS thread id
1767485453
MySQL thread id 431507, query id 2760742 lab-ccbdev.mobilesys.net
172.16.72.26 qos_import
---TRANSACTION 0 13510987, not started, process no 15897, OS thread id
1739890698
MySQL thread id 424770, query id 2761571 lab-ccbdev.mobilesys.net
172.16.72.26 qos_import
---TRANSACTION 0 13510888, not started, process no 26805, OS thread id
1680609292
MySQL thread id 410297, query id 2761355 lab-ccbdev.mobilesys.net
172.16.72.26 qos_import
---TRANSACTION 0 13510989, ACTIVE 1 sec, process no 9760, OS thread id
2008215567 inserting, thread declared inside InnoDB 486
1 lock struct(s), heap size 320, undo log entries 15
MySQL thread id 490279, query id 2761573 localhost scrubber update
INSERT ignore INTO archive13
(destination,routeHistory,stateDescription,statusR eportReq,hostname,uniqueReference,state,billingRef ,scrubberName,msgType
---TRANSACTION 0 13493202, ACTIVE 8932 sec, process no 24020, OS
thread id 1985998859 fetching rows, thread declared inside InnoDB 109
MySQL thread id 484855, query id 2712626 lab-rhcs1.mobilesys.net
172.16.24.23 qos_msg_lookup Sending data
select rid, logTime, hostname, clientName, clientID,
internalMessageID, destination, originator, state, stateDescription,
addl_state, addl_stateDescr
Trx read view will not see trx with id >= 0 13493203, sees < 0
13493117
--------
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
10742523 OS file reads, 19878784 OS file writes, 2382488 OS fsyncs
1 pending preads, 0 pending pwrites
84.23 reads/s, 20856 avg bytes/read, 5.50 writes/s, 2.75 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf for space 0: size 4667, free list len 15623, seg size 20291,
13080288 inserts, 14243160 merged recs, 1392916 merges
Hash table size 2212699, used cells 509823, node heap has 569
buffer(s)
22634.34 hash searches/s, 1645.34 non-hash searches/s
---
LOG
---
Log sequence number 106 1033350266
Log flushed up to 106 1033277188
Last checkpoint at 106 1024173651
0 pending log writes, 0 pending chkp writes
1389089 log i/o's done, 2.50 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 587116664; in additional pool allocated 2086912
Buffer pool size 32768
Free buffers 0
Database pages 32199
Modified db pages 7364
Pending reads 2
Pending writes: LRU 0, flush list 0, single page 0
Pages read 18706245, created 1021389, written 25330169
107.97 reads/s, 2.00 creates/s, 4.50 writes/s
Buffer pool hit rate 999 / 1000
--------------
ROW OPERATIONS
--------------
2 queries inside InnoDB, 0 queries in queue
Main thread process no. 25809, id 28680, state: sleeping
Number of rows inserted 18411172, updated 64102, deleted 14293534,
read 1107786361
19.75 inserts/s, 0.00 updates/s, 17.25 deletes/s, 695.58 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.06 sec)
