xtradb constant cpu load / mariadb 5.2.12

[Goetz T. Fischer]

machine specs:
---------------------

CPU: Intel(R) Core(TM)2 CPU E8400, 3.00GHz
ram: 8GB
OS: debian 6.0.5 64bit

basic server installation, no X, no special hardware. only default debian packages and fully updated.

mariadb 5.2.12 source package
compiler: gcc version 4.4.5 (Debian 4.4.5-8)
gcc options: '-mssse3 -O3'
configure options: --without-docs --without-ndb-debug

so i went ahead and tried a completely vanilla installation. used the my-medium.cnf and the following commands to get started from within the inst. dir:
# ./bin/mysql_install_db --user=mysql
# ./bin/mysqld_safe --defaults-file=./my-medium.cnf &

all fine so far. now to the actual

PROBLEM REPORT:
===============

as soon as i add the following to the cnf the db is constantly causing almost 50% cpu load on both cpus without me doing anything at all:
plugin-load = ha_xtradb.so

innodb doesn't work by default so i used that option. this is the only plugin i load in that cnf file. actually xtradb is the main reason why i picked mariadb. the second reason is i want to compile it with icc which i did after i encountered this very issue but just got the exact same problem. without xtradb everything seems fine.
following the processes and innodb status while the cpu load issue is present:

MariaDB [(none)]> SHOW PROCESSLIST;
+----+------+-----------+------+---------+------+-------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------+------+---------+------+-------+------------------+
| 1 | root | localhost | NULL | Query | 0 | NULL | SHOW PROCESSLIST |
+----+------+-----------+------+---------+------+-------+------------------+
1 row in set (0.00 sec)

MariaDB [(none)]> SHOW INNODB STATUS;
| InnoDB | |
=====================================
120810 5:08:52 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 51 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 1_second, 1 sleeps, 0 10_second, 1 background, 1 flush
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 14, signal count 14
Mutex spin waits 196, rounds 2878, OS waits 11
RW-shared spins 2, OS waits 2; RW-excl spins 0, OS waits 0
Spin rounds per wait: 14.68 mutex, 30.00 RW-shared, 0.00 RW-excl
--------
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 (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (write thread)
I/O thread 7 state: waiting for i/o request (write thread)
I/O thread 8 state: waiting for i/o request (write thread)
I/O thread 9 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
26 OS file reads, 3 OS file writes, 3 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 276671, node heap has 0 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 45356
Log flushed up to 45356
Last checkpoint at 45356
Max checkpoint age 7782360
Checkpoint age target 7539162
Modified age 0
Checkpoint age 0
0 pending log writes, 0 pending chkp writes
8 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137691136; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 2217584 (2213368 + 4216)
    Page hash 139112
    Dictionary cache 592524 (554768 + 37756)
    File system 83536 (82672 + 864)
    Lock system 333248 (332872 + 376)
    Recovery system 0 (0 + 0)
    Threads 83200 (82696 + 504)
Dictionary memory allocated 37756
Buffer pool size 8191
Buffer pool size, bytes 134201344
Free buffers 8176
Database pages 15
Old database pages 0
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 15, created 0, written 0
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 15, 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
Main thread process no. 17920, id 140389157238528, state: waiting for server activity
Number of rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 500
Purge done for trx's n:o < 0 undo n:o < 0
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started, process no 17920, OS thread id 140389631579904
MySQL thread id 1, query id 3 localhost root
SHOW INNODB STATUS
----------------------------
END OF INNODB MONITOR OUTPUT
============================

then i tried the latest mariadb 5.1.x and encountered the exact same problem. also tried a bunch of other things like a different config, different already existing db files ... all without any success, still the same cpu load issue.
there are no operational errors, the db works fine except xtradb hogging my cpus.

[Elena Stepanova (elenst)]

Hi,

You mentioned that "innodb doesn't work by default", but that's only because you didn't add it to your configure options, you should have run it with --with-plugins=xtradb .
Could you please try and see whether you are also having the same problem when xtradb is built in statically?

That said, I've built 5.2.12 with the same exact configure options as you mentioned, and started it presumably the same way, and didn't have a problem with CPU; but I have a different version of gcc and ubuntu instead of debian, so it's not a clean experiment of course.

Does the same happen if you run a binary distribution, e.g. from a binary tarball?

If it does, we can probably rule out the compiler version or options.

Thanks.

[Goetz T. Fischer (g-fischer)]

> Could you please try and see whether you are also having the same problem when
> xtradb is built in statically?
that's what i did in the first place; unfortunately with the same result. actually that very problem is the reason why i cut down on configure options.

> Does the same happen if you run a binary distribution, e.g. from a binary
> tarball?
i'll try that next but since i ran into that with both gcc and icc i'd be surprised. however if so it'd pretty much make this 'enterprise' of mine obsolete because the main reason was to have the db server built with icc.

anyhow thanks for the reply, will update this as soon as i finished the tries with a binary package ...

[Goetz T. Fischer (g-fischer)]

okay i used mariadb-5.2.12-Linux-x86_64.tar.gz and it's even worse than with my builds: cpus are at full throttle constantly.

[Elena Stepanova (elenst)]

Hi,

I've been wondering if there is any particular reason you are choosing 5.1/5.2 over higher versions? Not that it should not work, just maybe you would have had a better luck with 5.5, since XtraDB/InnoDB has gone long way from 5.1-based versions to 5.5?..

[Elena Stepanova (elenst)]

Axel,

Could you please take a look, if you've ever seen anything like this or happen to know what might cause this?

[Goetz T. Fischer (g-fischer)]

just to cover all options i tried mariadb-5.5.25-linux-x86_64.tar.gz as well and ran into the same problem. only this time compared to 5.2 the cpu load was a little lower at around 30% per core.

[Axel Schwenke (ahel)]

Hi Goetz,

how exactly are you setting the mentioned "compiler options"? I'll try to reproduce your problem with mariadb-5.2.12. Please see if you have the 'mysqlbug' script from that build of yours and attach it. It contains all options used during compiling.

[Goetz T. Fischer (g-fischer)]

well since it also happens with the binaries you provide it might not depend on my compiler. anyway i just use export to set the options in the shell before i start compiling. for example in this case for gcc:

export CFLAGS='-mtune=core2 -mssse3 -O3'
export CXXFLAGS='-mtune=core2 -mssse3 -O3'
export LDFLAGS='-mtune=core2 -mssse3 -O3'
export CPPFLAGS='-mtune=core2 -mssse3 -O3'

[Axel Schwenke (ahel)]

Hi Goetz,

I haven't been able to reproduce your problem, but would like to try investigate it further. I have two ideas so far:

1. is it possible that your system still suffers from the leap second problem? Try setting the system time like so:

date -s "`date`"

Background information: http://openquery.com/blog/2012-leap-second-linux

2. if the above does not change anything, please give us some more information. Start MariaDB so that it starts consuming cpu. Run:

top -b -n 1 >top1.txt
top -b -n 1 -H >top2.txt

The first top run will run in process mode and should show mysqld on top (as it consumes most cpu). The second top run is in thread mode and will show individual threads. I hope all cpu is consumed by a single mysqld thread.

Now create a full back trace of all threads in mysqld. For that lookup the mysqld PID (first top run) and run:

gdb -ex "set pagination 0" -ex "thread apply all bt" -batch -p <PID> >mysqld-all-bt.txt

(replace <PID> with the mysqld pid)

zip all 3 files and attach the zip to this report.

[Goetz T. Fischer (g-fischer)]

oh i'm very sorry, i didn't expect another reply so i moved on.
proprietary machine now and all is fine. never been a fan of linux and x86 anyway :-)

thanks for all the help!!