0

I am encountering what I'm pretty sure is a low-level (OS?) resource contention in MariaDB.

I'm using MariaDB 10.0.29 on a machine with two cores and 8GB of RAM.

The situation is as follows - I have an application written in Java, which uses JDBC to access a MariaDB database. The application starts two separate threads, each with its own connection to a different schema (call them Schema_1 and Schema_2). I have verified that each thread does indeed only access its own connection, and its own schema. I've also double-checked there are no cross-schema foreign keys. As far as I can tell, there should be no DB-level resource contention between the two threads.

When running one such thread, I see my Java process using ~65% CPU, with the MariaDB thread using ~35% CPU. However, when running both threads, each MariaDB thread only uses 25% CPU, with the Java threads using ~55% CPU, which to me means there is some resources being locked by each of the MariaDB threads in turn, so only one can run at a time.

Running the exact same code on a different machine with MariaDB 5.5.50 confirms there may be something wrong, as it scales almost perfectly to 2 threads, using ~100% of the CPU at all times.

Trying to get to the bottom of it, I've ran show status like '%wait%' which yields:

show status like '%wait%';
+---------------------------------------+----------+
| Variable_name                         | Value    |
+---------------------------------------+----------+
| Binlog_group_commit_trigger_lock_wait | 0        |
| Innodb_buffer_pool_wait_free          | 0        |
| Innodb_log_waits                      | 0        |
| Innodb_mutex_os_waits                 | 38108364 |
| Innodb_mutex_spin_waits               | 46717276 |
| Innodb_row_lock_current_waits         | 0        |
| Innodb_row_lock_waits                 | 0        |
| Innodb_s_lock_os_waits                | 1527996  |
| Innodb_s_lock_spin_waits              | 2079031  |
| Innodb_x_lock_os_waits                | 710738   |
| Innodb_x_lock_spin_waits              | 1211905  |
| Table_locks_waited                    | 0        |
| Tc_log_page_waits                     | 0        |
+---------------------------------------+----------+
13 rows in set (0.00 sec)

which, if I understand correctly, means there were no table or row lock waits, but there were an awful lot of os waits. But what are they? How can I tell which resource is being locked, and by whom?

The InnoDB buffer pool is set to 6GB, the thread concurrency is set to 10 (setting to 0 doesn't seem to have any noticeable effect), and just to be 100% certain this isn't I/O related, the log files are saved to a RAM disk.

What else can I do to find the source of the locks? Is this a reasonable number for OS locks? Why does MariaDB 5.5 seem to perform much better than 10.0.29 in this regard?

Following is the output of show engine innodb status. If there are any other helpful diagnostic outputs please let me know and I'll post them:

| InnoDB |      | 
=====================================
2017-03-27 13:11:44 7f8c55020700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 39 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 98077 srv_active, 0 srv_shutdown, 682949 srv_idle
srv_master_thread log flush and writes: 780936
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 40364775
OS WAIT ARRAY INFO: signal count 42775103
Mutex spin waits 46717276, rounds 1174586500, OS waits 38108364
RW-shared spins 2079031, rounds 47480157, OS waits 1527996
RW-excl spins 1211905, rounds 25553878, OS waits 710738
Spin rounds per wait: 25.14 mutex, 22.84 RW-shared, 21.09 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 886179328
Purge done for trx's n:o < 886179327 undo n:o < 0 state: running but idle
History list length 3404
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 93, OS thread handle 0x7f8c55020700, query id 366742871 localhost root init
show engine innodb status
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (read thread)
I/O thread 7 state: waiting for completed aio requests (read thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
I/O thread 10 state: waiting for completed aio requests (write thread)
I/O thread 11 state: waiting for completed aio requests (write thread)
I/O thread 12 state: waiting for completed aio requests (write thread)
I/O thread 13 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
5124 OS file reads, 187867510 OS file writes, 480141 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 18411, seg size 18413, 874 merges
merged operations:
 insert 0, delete mark 789821, delete 754
discarded operations:
 insert 0, delete mark 0, delete 0
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 104106175746
Log flushed up to   104106175746
Pages flushed up to 104106175746
Last checkpoint at  104106175746
Max checkpoint age    169158206
Checkpoint age target 163872013
Modified age          0
Checkpoint age        0
0 pending log writes, 0 pending chkp writes
181317888 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 6706692096; in additional pool allocated 0
Total memory allocated by read views 216
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 137096336   (101997608 + 35098728)
    Page hash           797656 (buffer pool 0 only)
    Dictionary cache    25944722    (25501136 + 443586)
    File system         965152  (812272 + 152880)
    Lock system         15938512    (15938152 + 360)
    Recovery system     0   (0 + 0)
Dictionary memory allocated 443586
Buffer pool size        393208
Buffer pool size, bytes 6442319872
Free buffers            325107
Database pages          65959
Old database pages      24185
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 11425, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 5078, created 60881, written 6549515
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 65959, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40785
Database pages          8117
Old database pages      2976
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1271, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 970, created 7147, written 917449
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8117, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40909
Database pages          7972
Old database pages      2922
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 2025, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 632, created 7340, written 533992
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 7972, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40569
Database pages          8318
Old database pages      3050
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1066, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 604, created 7714, written 464495
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8318, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40359
Database pages          8508
Old database pages      3120
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1417, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 643, created 7865, written 1655991
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8508, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40784
Database pages          8084
Old database pages      2964
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1243, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 660, created 7424, written 1061540
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8084, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40612
Database pages          8268
Old database pages      3032
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1579, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 646, created 7622, written 776527
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8268, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40457
Database pages          8429
Old database pages      3091
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1554, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 291, created 8138, written 585268
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8429, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size        49151
Buffer pool size, bytes 805289984
Free buffers            40632
Database pages          8263
Old database pages      3030
Modified db pages       0
Percent of dirty pages(LRU & free pages): 0.000
Max dirty pages percent: 75.000
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 1270, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 632, created 7631, written 554253
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 8263, 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
0 read views open inside InnoDB
0 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
0 out of 1000 descriptors used
Main thread process no. 12006, id 140233249109760, state: sleeping
Number of rows inserted 25540074, updated 163314856, deleted 23278039, read 11939702187
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system 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
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Output of show status like '%tmp%':

+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 0     |
| Created_tmp_files       | 6     |
| Created_tmp_tables      | 0     |
| Handler_tmp_update      | 0     |
| Handler_tmp_write       | 0     |
| Rows_tmp_read           | 0     |
+-------------------------+-------+
  • Where is located your temporary tables? – Alexander Tolkachev Mar 27 '17 at 21:01
  • @AlexanderT - how do I find out? Added output of show status like '%tmp%', and it seems no temporary files are created on disk. – Itai Mar 28 '17 at 7:16
  • it's located in my.cnf or could be checked by command show variables like "%tmp%"; in mysql cli. – Alexander Tolkachev Mar 28 '17 at 8:02
  • the variables tmpdir has the value /tmp/. There is no temporary directory/file definition in the configuration file (for me it's in /etc/mysql/mariadb.conf.d/50-server.cnf). There are no mysql-related or mysql-owned files in /tmp that I can see. – Itai Mar 28 '17 at 8:08

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.