Hi
I'm experiencing very strange innodb behavior. I'm testing the following DB
structure: stn|dt|par1|par2|par3 , where stn is 1 to N, dt 1 to M, par1,
par2, par3, par4, par5, par6 are any values and stn+dt is a primary key.
So create statement looks like
CREATE TABLE t3 (stn SMALLINT UNSIGNED NOT NULL,
dt BIGINT UNSIGNED NOT NULL,
par1 TINYINT,
par2 TINYINT,
par3 TINYINT,
par4 TINYINT,
par5 TINYINT,
par6 TINYINT,
PRIMARY KEY (stn, dt)) TYPE=INNODB
The table looks like that:
1 1 9 9 9 9 9 9
1 2 9 9 9 9 9 9
.
2 1 9 9 9 9 9 9
2 2 9 9 9 9 9 9
.
N M-1 9 9 9 9 9 9
N M 9 9 9 9 9 9
I'm testing it for N=(4000, 8000) and
M=(1500, 3000, 6000, 12000, 24000).
Test consits of writing down the file for current N and M,
loading it in table via 'LOAD DATA INFILE', commiting changes and then
testing speed of 500 random selects from the table.
For N=4000 all is loking good, but when N=8000 loading time is droping down
drastically when M reaches 3000 or so. I'm talking about 50 times slower
insertion here.
So I simplified the test, lefting just the loading data in table and run it
for N=4000, M=12000 and then for N=8000, M=6000. Notice the data and index
length for this cases are the same.
The first test was finished in a hour, the second was terminated by
me after 12 hour work and it did not even inserted half the rows.
If this helps the following are outputs of innodb monitor for this tests.
Typical output for N=4000, M=12000:
=
020923 3:44:12 INNODB MONITOR OUTPUT
=
--
SEMAPHORES
--
OS WAIT ARRAY INFO: reservation count 1858, signal count 1858
Mutex spin waits 1868, rounds 19710, OS waits 132
RW-shared spins 248, OS waits 124; RW-excl spins 9149, OS waits 1602
TRANSACTIONS
Trx id counter 0 1287
Purge done for trx's n:o 0 0 undo n:o 0 0
Total number of lock structs in row lock hash table 0
---TRANSACTION 0 1286, OS thread id 441071616 inserting, active, runs or
sleeps, has 1 lock struct(s), undo log entries 11479793
MySQL thread id 1, query id 16 localhost admin
LOAD DATA INFILE '/db/tmp/df.dat' INTO TABLE t3 FIELDS TERMINATED BY ',' LINES
TERMINATED BY '
'
FILE I/O
I/O thread 0 state: waiting for i/o request
I/O thread 1 state: waiting for i/o request
I/O thread 2 state: waiting for i/o request
I/O thread 3 state: waiting for i/o request
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
42975 OS file reads, 18554 OS file writes, 3895 OS fsyncs
0.00 reads/s, 5.88 writes/s, 2.06 fsyncs/s
-
INSERT BUFFER
-
Ibuf for space 0: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
---
LOG
---
Log sequence number 0 671108249
Log flushed up to 0 670978039
Last checkpoint at 0 54962
0 pending log writes, 0 pending chkp writes
1360 log i/o's done, 1.56 log i/o's/second
--
BUFFER POOL AND MEMORY
--
Total memory allocated 246403343; in additional pool allocated 205696
Free list length 0
LRU list length 8187
Flush list length 8001
Buffer pool size 8192
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 61069, created 55116, written 108019
0.00 reads/s, 23.81 creates/s, 16.56 writes/s
Buffer pool hit rate 1000 / 1000
--
ROW OPERATIONS
--
1 queries inside InnoDB, 0 queries in queue; main thread: sleeping
Number of rows inserted 11879792, updated 0, deleted 0, read 0
17659.81 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
END OF INNODB MONITOR OUTPUT
17659.81 inserts/s. Pretty good I guess.
While for N=8000, M=6000 at the beginning monitor output looks the same,
after ~260 rows insert speed begins falling down, and very fast.
And the typical output of monitor becomes like this
=
020923 5:04:24 INNODB MONITOR OUTPUT
=
--
SEMAPHORES
--
OS WAIT ARRAY INFO: reservation count 1671, signal count 1670
--Thread 441090048 has waited at btr0cur.c line 357 for 0.00 seconds the
semaphore:
X-lock on RW-latch at 12bcee78 created in file buf0buf.c line 348
a writer (thread id 441090048) has reserved it in mode exclusive
number of readers 0, waiters flag 1
Last time read locked in file buf0flu.c line 466
Last time write locked in file buf0buf.c line 1246
Mutex spin waits 416, rounds 4470, OS waits 42
RW-shared spins 60, OS waits 30; RW-excl spins 4163, OS waits 1599
TRANSACTIONS
