Assigning to marko by default Innodb guru. svoj, you can jump in, if you want to repeat, or have any idea how to fix. axel, same for you.

Given that log_sys.mutex appears to be one of the contention points, I think that we should keep track of the average volume of redo log written per write transaction. More redo log writes should lead to more contention.

There are two features in MariaDB 10.3 that could increase the writes: MDEV-12288 (resetting transaction identifiers after writes) and MDEV-11369 (instant ADD COLUMN). As far as I understand, neither of these changes should matter.

Also, some mini-transactions for writing undo log were changed in the hope of simplifying crash recovery; one of the changes was essentially reverted in MDEV-15914 due to a performance regression.

I would like to compare how these fields in SHOW ENGINE INNODB STATUS proceed:

…

------------

TRANSACTIONS

------------

Trx id counter 34

…

---

LOG

---

Log sequence number 1642672

…

We should record both counts at the start and end of the test, calculate the difference and the ratio. For example, if these counts were 50 and 2000000 at the end of the test, the ratio would be (2000000-1642672)/(50-34) = 22333 bytes per transaction.

If MariaDB 10.3 is generating significantly more redo log than 10.2, that could explain the increased log_sys.mutex contention.

If purge threads are using more CPU than earlier, that could be due to svoj’s work of removing trx_sys.mutex and employing some lock-free data structures. It could be useful to test a 10.3 version right before switching to lock-free data structures.

There was also this change to ut_delay() and some related discussion. On the Intel Skylake microarchitecture, the PAUSE instruction (REPZ NOP) takes more wall-clock time than on earlier ones. Maybe we are now burning more CPU on older microarchitectures?

ref ut_delay: I think I saw svoj test PTHREAD_MUTEX_ADAPTIVE_NP and it wasn't good.

Maybe some rethinking the adaptive delay in mariadb to a mean/std approach per mutex rather than a straight mean. We're wasting heaps of cycles in ut_delay so a little bit of maths extra isn't going to hurt too bad.
https://sourceware.org/git/?p=glibc.git;a=blob;f=nptl/pthread_mutex_lock.c;h=1519c142bd6ec5cc528c5921f28575d25c7fb664;hb=HEAD#l118

marko, I did some calculations of bytes per trx, guided by your hint, and this is what it is (surprisingly, to me maybe, the number of bytes is not integer

10.3.7
trxid1 = 193362180
LSN1 = 69634009621

trxid2 = 215344539
LSN2= 75578735333

bytes per trx = 270.43

10.2.14

trxid1 = 11388
LSN1= 13829598991
trxid2 = 22135718
LSN2= 19655598660

bytes per trx = 263.32

multiuser benchmarks was run between the point 1 and point 2.
Hope that helps

To reduce the redo log volume, it looks like we have to resume generating the redo log record types MLOG_UNDO_INIT and MLOG_UNDO_HDR_REUSE. The record MLOG_UNDO_INSERT was already restored in MDEV-15914.

MLOG_UNDO_HDR_REUSE was removed by MDEV-12288. That one we cannot restore. It should be equivalent to MLOG_UNDO_HDR_CREATE in the redo log volume. Similarly, reintroducing MLOG_UNDO_ERASE_END ought to increase the redo log volume written, so we’d better not restore that.

regarding "relax CPU" number of loops for "rep nop" being 200, https://github.com/MariaDB/server/commit/b3346c2f41d0f7bd0d919826592b37ae09fa41c8#diff-e877f572e9fd77c43d5e7af075f92e74R91 , this is something from me, I measured this as optimal back in 2008, on (probably) Core2 Duo. No idea if this still holds.

The MLOG_UNDO_INIT record should occupy 3..12 bytes while the lower-level records (MLOG_2BYTES, MLOG_4BYTES) could easily consume 7 more bytes.

I have now restored the MLOG_UNDO_INIT record, which I had removed in the hope that recovery would be simpler and faster. (But I failed to notice that a small increase on the number of redo log bytes written can hurt performance.)

I developed a simple test for measuring the volume of redo log written by an update. Note that transaction IDs are incremented both at start and at commit.

Due to MDEV-12288, it is clear that there will be more writes by the purge in 10.3. Before MDEV-12288, an UPDATE would not result in any purge activity, but after it, in 10.3, all DML will eventually result in the DB_TRX_ID column being zeroed out in the clustered index record. This will improve read performance at some cost of write performance.

--source include/have_innodb.inc

--source include/have_sequence.inc

let $n_updates=1;

let $n_rows=1;

create table t1 (id serial, c2 char(120) default 'foobar') engine=innodb;

#connect stop_purge, localhost, root;

#START TRANSACTION WITH CONSISTENT SNAPSHOT;

#connection default;

eval insert into t1(id) select * from seq_1_to_$n_rows;

--replace_regex /.*Log sequence number ([0-9]+).*/\1/

let $lsn= `SHOW ENGINE INNODB STATUS`;

let $lsn= `SELECT REGEXP_REPLACE('$lsn', 'InnoDB\\t*', '')`;

--replace_regex /.*Trx id counter ([0-9]+).*/\1/

let $trx= `SHOW ENGINE INNODB STATUS`;

let $trx= `SELECT REGEXP_REPLACE('$trx', 'InnoDB\\t*', '')`;

while ($n_updates) {

update t1 set c2='boofar';

update t1 set c2='foobar';

dec $n_updates;

}

--replace_regex /.*Log sequence number ([0-9]+).*/\1/

let $new_lsn= `SHOW ENGINE INNODB STATUS`;

let $new_lsn= `SELECT REGEXP_REPLACE('$new_lsn', 'InnoDB\\t*', '')`;

--replace_regex /.*Trx id counter ([0-9]+).*/\1/

let $new_trx= `SHOW ENGINE INNODB STATUS`;

let $new_trx= `SELECT REGEXP_REPLACE('$new_trx', 'InnoDB\\t*', '')`;

eval SELECT ($new_lsn-$lsn)/($new_trx-$trx) `bytes/(transaction*2)`;

drop table t1;

In the above test, you can disable purge to observe the effect to the number of redo log bytes written. The test should probably run a longer time for the purge to kick in.

The effect of MDEV-12288 can also be disabled by removing the body of the function row_purge_reset_trx_id(). After that change, read-only workloads should be somewhat slower due to performing lookups for DB_TRX_ID that have been purged.

I can confirm this in a memory-based benchmark:

sysbench oltp_update_index.lua --tables=20 --table_size=100000 --rand-type=uniform --time=60 --report-interval=10 --threads=40

and

numactl --interleave=all \

$MDIR/sql/mysqld --no-defaults --log-output=file --general-log=OFF --core-file --loose-debug-sync-timeout=300 --innodb \

  --datadir=$TDIR --lc-messages-dir=$MDIR/sql/share/ --socket=$MYSQL_SOCK \

  --loose-innodb_file_per_table=true \

  --loose-innodb-open-files=4000 \

  --loose-innodb_data_file_path=ibdata1:10M:autoextend \

  --loose-innodb_flush_log_at_trx_commit=0 \

  --loose-innodb_flush_method=O_DIRECT_NO_FSYNC \

  --loose-innodb-adaptive-hash-index-partitions=32 \

  --loose-innodb_log_buffer_size=256M \

  --loose-innodb_log_file_size=1900M \

  --loose-innodb_buffer_pool_size=50G \

  --loose-innodb-buffer-pool-instances=32 \

  --loose-innodb-thread-concurrency=0 \

  --loose-innodb_log_files_in_group=3 \

  --loose-innodb_read_io_threads=8 \

  --loose-innodb_write_io_threads=8 \

  --loose-innodb_io_capacity=8000 \

  --loose-innodb_flush_sync=0 \

  --table-open-cache=1400 \

  --table-open-cache-instances=64 \

  --max-connections=200 \

  --aria-checkpoint-interval=0 \

  --loose-performance-schema=off

The transactions/second number is:

Something has drastically changed between 10.3.4 and 10.3.5. Commit 5db9c6e490ea2c6b7997dff4cbee18274496dd2c is the biggest culprit. I still think that the idea of MDEV-15132 is good, but there must be something bad about this particular implementation.

I chose commit af566d8a63f908c76d43957e790e861d944486b0 because it is in the middle of some code changes by svoj. There is some visible regression between that and mariadb-10.3.5, and not much improvement since then.

The patch against the most recent 10.3 essentially disabled the resetting of the DB_TRX_ID (MDEV-12288). This resetting does create some purge activity and cause more writes, but it could also greatly help performance, as demonstrated above. (If DB_TRX_ID=0, we immediately know that there is no older version and the record is not implicitly locked.)

diff --git a/storage/innobase/row/row0purge.cc b/storage/innobase/row/row0purge.cc

index af8cd682288..8b22c90e0d1 100644

--- a/storage/innobase/row/row0purge.cc

+++ b/storage/innobase/row/row0purge.cc

@@ -671,6 +671,7 @@ static

 void

 row_purge_reset_trx_id(purge_node_t* node, mtr_t* mtr)

 {

+#if 0

 	ut_ad(rw_lock_own(dict_operation_lock, RW_LOCK_S));

 	/* Reset DB_TRX_ID, DB_ROLL_PTR for old records. */

 	mtr->start();

@@ -729,6 +730,7 @@ row_purge_reset_trx_id(purge_node_t* node, mtr_t* mtr)

 	}

 	mtr->commit();

+#endif

 }

 /***********************************************************//**

diff --git a/storage/innobase/row/row0umod.cc b/storage/innobase/row/row0umod.cc

index 47c515f70cf..3b5f37adf50 100644

--- a/storage/innobase/row/row0umod.cc

+++ b/storage/innobase/row/row0umod.cc

@@ -385,6 +385,7 @@ row_undo_mod_clust(

 					   false, &mtr);

 		ut_ad(err == DB_SUCCESS

 		      || err == DB_OUT_OF_FILE_SPACE);

+#if 0

 	} else if (!index->table->is_temporary() && node->new_trx_id) {

 		/* We rolled back a record so that it still exists.

 		We must reset the DB_TRX_ID if the history is no

@@ -430,6 +431,7 @@ row_undo_mod_clust(

 						  sizeof reset_trx_id, &mtr);

 			}

 		}

+#endif

 	} else {

 		goto func_exit;

 	}

Surprisingly, removing the following supposed optimization

diff --git a/storage/innobase/trx/trx0trx.cc b/storage/innobase/trx/trx0trx.cc

index 26b857a75f3..218e913d264 100644

--- a/storage/innobase/trx/trx0trx.cc

+++ b/storage/innobase/trx/trx0trx.cc

@@ -1341,11 +1341,6 @@ trx_write_serialisation_history(

 #endif

 	const bool update_binlog_pos = trx->mysql_log_file_name

 		&& *trx->mysql_log_file_name;

-	if (!update_binlog_pos

-#ifdef WITH_WSREP

-	    && !update_wsrep

-#endif

-	    ) return true;

 	buf_block_t* block = trx_sysf_get(mtr);

 #ifdef WITH_WSREP

fixes the performance regression of 5db9c6e490ea2c6b7997dff4cbee18274496dd2c. With this optimization removed, we are always acquiring and releasing the TRX_SYS page latch. Replication and Galera are disabled, after all.

This patch is not applicable to later versions, because MDEV-15158 later removed the write to the TRX_SYS page altogether. Maybe this page lock somehow served as useful throttling?

I applied a similar unnecessary acquisition of the TRX_SYS page lock to the latest 10.3, but it did reduce performance as expected:

diff --git a/storage/innobase/trx/trx0trx.cc b/storage/innobase/trx/trx0trx.cc

index 11d83c96a92..8ded9a03e3d 100644

--- a/storage/innobase/trx/trx0trx.cc

+++ b/storage/innobase/trx/trx0trx.cc

@@ -1120,6 +1120,7 @@ trx_write_serialisation_history(

 	mutex_exit(&rseg->mutex);

+	trx_sysf_get(mtr);

 	MONITOR_INC(MONITOR_TRX_COMMIT_UNDO);

 	trx->mysql_log_file_name = NULL;

I tried to remove a write that was added by MDEV-15158, but it did not help performance:

diff --git a/storage/innobase/trx/trx0purge.cc b/storage/innobase/trx/trx0purge.cc

index 32e050e9b91..3817ce8bcca 100644

--- a/storage/innobase/trx/trx0purge.cc

+++ b/storage/innobase/trx/trx0purge.cc

@@ -254,8 +254,10 @@ trx_purge_add_undo_to_history(const trx_t* trx, trx_undo_t*& undo, mtr_t* mtr)

 			rseg_header + TRX_RSEG_HISTORY_SIZE,

 			hist_size + undo->size, MLOG_4BYTES, mtr);

+#if 0

 		mlog_write_ull(rseg_header + TRX_RSEG_MAX_TRX_ID,

 			       trx_sys.get_max_trx_id(), mtr);

+#endif

 	}

 	/* Before any transaction-generating background threads or the

This write is performed while holding rseg->mutex, but there are 128 rollback segments, so I do not think it should matter with 40 concurrent users, if each transaction is assigned a different rollback segment.

My 10.3 (b2f56085d4249e2cf3ed9f80d284b3ce837e9e29 ) results don't go inline with what marko reported:

[ 10s ] thds: 40 tps: 246050.74 qps: 246050.94 (r/w/o: 0.00/246050.94/0.00) lat (ms,95%): 0.28 err/s: 0.00 reconn/s: 0.00

[ 20s ] thds: 40 tps: 266876.11 qps: 266876.11 (r/w/o: 0.00/266876.11/0.00) lat (ms,95%): 0.24 err/s: 0.00 reconn/s: 0.00

[ 30s ] thds: 40 tps: 265013.72 qps: 265013.52 (r/w/o: 0.00/265013.52/0.00) lat (ms,95%): 0.25 err/s: 0.00 reconn/s: 0.00

[ 40s ] thds: 40 tps: 267120.70 qps: 267120.70 (r/w/o: 0.00/267120.70/0.00) lat (ms,95%): 0.23 err/s: 0.00 reconn/s: 0.00

[ 50s ] thds: 40 tps: 267445.25 qps: 267445.25 (r/w/o: 0.00/267445.25/0.00) lat (ms,95%): 0.23 err/s: 0.00 reconn/s: 0.00

[ 60s ] thds: 40 tps: 265585.03 qps: 265585.03 (r/w/o: 0.00/265585.03/0.00) lat (ms,95%): 0.24 err/s: 0.00 reconn/s: 0.00

[ 70s ] thds: 40 tps: 262178.67 qps: 262178.67 (r/w/o: 0.00/262178.67/0.00) lat (ms,95%): 0.25 err/s: 0.00 reconn/s: 0.00

[ 80s ] thds: 40 tps: 265030.96 qps: 265030.96 (r/w/o: 0.00/265030.96/0.00) lat (ms,95%): 0.23 err/s: 0.00 reconn/s: 0.00

[ 90s ] thds: 40 tps: 263325.84 qps: 263325.94 (r/w/o: 0.00/263325.94/0.00) lat (ms,95%): 0.23 err/s: 0.00 reconn/s: 0.00

[ 100s ] thds: 40 tps: 249319.73 qps: 249319.63 (r/w/o: 0.00/249319.63/0.00) lat (ms,95%): 0.28 err/s: 0.00 reconn/s: 0.00

[ 110s ] thds: 40 tps: 263994.66 qps: 263994.66 (r/w/o: 0.00/263994.66/0.00) lat (ms,95%): 0.23 err/s: 0.00 reconn/s: 0.00

[ 120s ] thds: 40 tps: 263167.54 qps: 263167.54 (r/w/o: 0.00/263167.54/0.00) lat (ms,95%): 0.23 err/s: 0.00 reconn/s: 0.00

    transactions:                        31452722 (262087.56 per sec.)

    queries:                             31452722 (262087.56 per sec.)

However 10.2 results are perfectly inline:

[ 10s ] thds: 40 tps: 189485.74 qps: 189485.84 (r/w/o: 0.00/189485.84/0.00) lat (ms,95%): 0.34 err/s: 0.00 reconn/s: 0.00

[ 20s ] thds: 40 tps: 198558.47 qps: 198558.37 (r/w/o: 0.00/198558.37/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 30s ] thds: 40 tps: 195900.53 qps: 195900.53 (r/w/o: 0.00/195900.53/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 40s ] thds: 40 tps: 196844.47 qps: 196844.47 (r/w/o: 0.00/196844.47/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 50s ] thds: 40 tps: 198759.66 qps: 198759.66 (r/w/o: 0.00/198759.66/0.00) lat (ms,95%): 0.32 err/s: 0.00 reconn/s: 0.00

[ 60s ] thds: 40 tps: 197423.50 qps: 197423.50 (r/w/o: 0.00/197423.50/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 70s ] thds: 40 tps: 196168.50 qps: 196168.50 (r/w/o: 0.00/196168.50/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 80s ] thds: 40 tps: 196777.38 qps: 196777.38 (r/w/o: 0.00/196777.38/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 90s ] thds: 40 tps: 198326.91 qps: 198326.91 (r/w/o: 0.00/198326.91/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 100s ] thds: 40 tps: 196600.91 qps: 196600.91 (r/w/o: 0.00/196600.91/0.00) lat (ms,95%): 0.32 err/s: 0.00 reconn/s: 0.00

[ 110s ] thds: 40 tps: 198558.49 qps: 198558.49 (r/w/o: 0.00/198558.49/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

[ 120s ] thds: 40 tps: 197079.29 qps: 197079.29 (r/w/o: 0.00/197079.29/0.00) lat (ms,95%): 0.31 err/s: 0.00 reconn/s: 0.00

    transactions:                        23605935 (196703.44 per sec.)

    queries:                             23605935 (196703.44 per sec.)

maybe you need to run just a little bit longer, like marko and I did

OTOH, marko ran for 2 minutes as well. I reported on 300 seconds

I used the following build configuration for both 10.2 and 10.3:

cmake -DCONC_WITH_{UNITTEST,SSL}=OFF -DWITH_EMBEDDED_SERVER=OFF -DWITH_UNIT_TESTS=OFF -DCMAKE_BUILD_TYPE=RelWithDebInfo -DPLUGIN_{TOKUDB,MROONGA,OQGRAPH,ROCKSDB,CONNECT}=NO -DPLUGIN_PERFSCHEMA=ON -DWITH_SAFEMALLOC=OFF -DWITH_SSL=bundled ..

svoj used the following:

cmake -DBUILD_CONFIG=mysql_release -DPLUGIN_PERFSCHEMA=NO -DPLUGIN_CONNECT=NO -DPLUGIN_MROONGA=NO -DPLUGIN_TOKUDB=NO -DPLUGIN_SPIDER=NO -DPLUGIN_OQGRAPH=NO -DWITH_JEMALLOC=system ..

I retested commit 5db9c6e490ea2c6b7997dff4cbee18274496dd2c with the latter config:

I applied the patch to remove the optimization from trx_write_serialisation_history() (which counter-intuitively improved performance from about 100ktps to 178ktps using my config):

So, removing the optimization does help in both cases, but much more with my build configuration. This change is not relevant for solving the regression, because the code has been seriously rewritten since then, but it shows that performance is hard. Perhaps the explanation could be that the TRX_SYS page lock serves as some kind of useful throttle that reduces contention on the rseg->mutex? It would seem best to acquire and release rseg->mutex only once during commit, and to try to ensure that the transactions running in different threads do not get assigned the same rseg (of course, this is only possible for up to 128 concurrent threads).

I tried modifying svoj’s config by removing -DWITH_JEMALLOC=system. Performance remained roughly the same:

So, jemalloc does help multi-client performance a little compared to GNU libc 2.27, but not that much, and the relative performance difference remains.

A major difference between our build configurations could be that cmake/build_configurations/mysql_release.cmake uses -O3 while -DCMAKE_BUILD_TYPE=RelWithDebInfo only uses -O2. After replacing -O2 with -O3 in my configuration, I got the following:

This suggests that there could be a clear regression from 10.2 to 10.3 when compiling with -O2. I hope that most distributed packages use -O3.

distributed packages are compiled with -DBUILD_CONFIGURATION=mysql_release

Still, I suggest to look more than just threads=1, and thread=40. 40 threads might be a sweet spot on svoj's machine. I tried 1,..,4096, that's more comprehensive. I suggest to vary durability settings as well (innodb_flush_log_at_trx_commit = 1). innodb_flush_method=O_DIRECT_NO_FSYNC is also a trick that pretends your box has battery backed disk. And it does not probably. dataset size, AHI vs no AHI, threadpool vs no threadpool., etc.

Seeing a full picture after running 2 tests. 2 minutes each , is not easy. I'd really start full comparison for different levels on concurrency, and then vary other parameters, if that does not show regression

I had a systematic error, caused by not rebuilding from the scratch. It looks like -DBUILD_CONFIG=mysql_release does use -O2 after all.

My observations about 5db9c6e490ea2c6b7997dff4cbee18274496dd2c and its predecessor are repeatable. And I still see a significant performance regression with 10.3.5 or the latest 10.3 Here are some rough results from 3-minute runs:

There is some fluctuation in these numbers, so 10% variance could be ignored.

Surprisingly, 53cc9aa5be63b4dd03aba804aebaa3bd470dab9c (MDEV-15104 - Remove trx_sys_t::rw_trx_ids) reduces performance compared to its parent af566d8a63f908c76d43957e790e861d944486b0. The next InnoDB commit c0d5d7c0efb6d2b9961da7fb813ff000a5d3e4c5 (MDEV-15104 - Remove trx_sys_t::serialisation_list) is better again. This is what I see with GCC 7.3.0; @svoj sees a steady improvement for these commits with GCC 5.4.0.

Another interesting pair is bc7a1dc1fbd27e6064d3b40443fe242397668af7 and b782971c58b5656820429b8ef3fae5fd82f5a0f7. The latter commit fixed a correctness bug that was introduced by the former. There are quite a few changes in between, and there appears to be some regression already in the parent of the fix (ba125eca551e3f5faee9f6d7ebed290f04cfc8fd).

Next I will try to find the regression between bc7a1dc1fbd27e6064d3b40443fe242397668af7 and ba125eca551e3f5faee9f6d7ebed290f04cfc8fd.

Commit 217fc122c8e893aa48fa5dcfb3dbfcc99a2aa299 is a merge from bb-10.2-ext, most notably adding st_mem_root::name. That is clearly costing some performance compared to its parent d6ed077fc82c2f4d20895db9a6b16ca295f23c33. I tried reverting the patch:

git show d69642deddf4f8d51f8c6807361576451334f1f9|patch -Rp1

# note: in 10.3, sql/rpl_handler.h was renamed to sql/rpl_rli.h

# note: adjust a few init_alloc_root() calls that did not exist in bb-10.2-ext

It seems that we must define st_mem_root::name in debug builds only.

Still, the additional regression between 217fc122c8e893aa48fa5dcfb3dbfcc99a2aa299 and eda142590f385b3d79e7b6a6e0cc13ba8fd25961 has to be narrowed down. It is outside InnoDB; the InnoDB differences in that range are trivial integer type mismatch warning fixes and fixes of source code comments. The only other commits in this range are CTE fixes (MDEV-15162 and MDEV-15119).

It is surprising that the performance improved in the middle, even though the st_mem_root::name is still present. The CTE fixes seem innocent to the performance.

It is also surprising that the MDEV-15091 size_t fix (commit 6c279ad6a71c63cb595fde7c951aadb31c3dbebc) is hurting so much. That seems to be the main source of regression (for my RAM-based toy benchmark).

I would suggest introducing a compile-time option for enabling st_mem_root::name (disabled by default), and revisiting MDEV-15091.

Here's what I get on 6c279ad6a71c63cb595fde7c951aadb31c3dbebc:

[ 10s ] thds: 40 tps: 245242.59 qps: 245242.69 (r/w/o: 0.00/245242.69/0.00) lat (ms,95%): 0.27 err/s: 0.00 reconn/s: 0.00

[ 20s ] thds: 40 tps: 254569.26 qps: 254569.16 (r/w/o: 0.00/254569.16/0.00) lat (ms,95%): 0.25 err/s: 0.00 reconn/s: 0.00

[ 30s ] thds: 40 tps: 254972.73 qps: 254972.73 (r/w/o: 0.00/254972.73/0.00) lat (ms,95%): 0.26 err/s: 0.00 reconn/s: 0.00

[ 40s ] thds: 40 tps: 252851.43 qps: 252851.53 (r/w/o: 0.00/252851.53/0.00) lat (ms,95%): 0.25 err/s: 0.00 reconn/s: 0.00

[ 50s ] thds: 40 tps: 251944.58 qps: 251944.48 (r/w/o: 0.00/251944.48/0.00) lat (ms,95%): 0.25 err/s: 0.00 reconn/s: 0.00

[ 60s ] thds: 40 tps: 253112.17 qps: 253112.17 (r/w/o: 0.00/253112.17/0.00) lat (ms,95%): 0.25 err/s: 0.00 reconn/s: 0.00

[ 70s ] thds: 40 tps: 250768.06 qps: 250768.06 (r/w/o: 0.00/250768.06/0.00) lat (ms,95%): 0.27 err/s: 0.00 reconn/s: 0.00

[ 80s ] thds: 40 tps: 246130.98 qps: 246130.98 (r/w/o: 0.00/246130.98/0.00) lat (ms,95%): 0.26 err/s: 0.00 reconn/s: 0.00

[ 90s ] thds: 40 tps: 243231.00 qps: 243231.00 (r/w/o: 0.00/243231.00/0.00) lat (ms,95%): 0.26 err/s: 0.00 reconn/s: 0.00

[ 100s ] thds: 40 tps: 245256.26 qps: 245256.26 (r/w/o: 0.00/245256.26/0.00) lat (ms,95%): 0.26 err/s: 0.00 reconn/s: 0.00

[ 110s ] thds: 40 tps: 246891.01 qps: 246891.01 (r/w/o: 0.00/246891.01/0.00) lat (ms,95%): 0.26 err/s: 0.00 reconn/s: 0.00

[ 120s ] thds: 40 tps: 246429.67 qps: 246429.87 (r/w/o: 0.00/246429.87/0.00) lat (ms,95%): 0.25 err/s: 0.00 reconn/s: 0.00

SQL statistics:

    queries performed:

        read:                            0

        write:                           29916061

        other:                           0

        total:                           29916061

    transactions:                        29916061 (249278.75 per sec.)

    queries:                             29916061 (249278.75 per sec.)

Sometimes I experience similar turbulence in benchmarks, which I couldn't explain so far. It is usually gone by itself and I can't reliably analyse it.
I guess if marko would re-run benchmark against 6c279ad6a71c63cb595fde7c951aadb31c3dbebc e.g. tomorrow he would see totally different picture.

I get a feeling like original report is completely ignored, and everyone is running ramdisk benchmarks now, testing CPU caches, and compiler optimizations, on 40 threads, on 40 core machines, for 2 minutes

You're right, we need to concentrate on original report. Which I couldn't reproduce locally, most probably due to some known issues with Samsung SSD being slow on heavy fsync.

I will try to look into ramdisk performance more closely, with longer run and more concurrent connections (like 1000).

I agree that we must address the I/O issue, but at the same time it could be worth looking for CPU regressions, that is, approach repeatable regressions from multiple angles. For what it is worth, I repeated some 180-second ramdisk benchmarks today:

The baseline was 123927.89tps before the weekend, and now it is 130213.08tps, so there indeed is some turbulence in the figures even after I switched to always do a full rebuild.

Patch 1 reverts some struct or class member variables from size_t to a narrower type, such as uint or uint32. A minimal version of the patch (1m) is below:

diff --git a/sql/sql_cache.h b/sql/sql_cache.h

index 0ed45a9ed81..ca2c3a59ee7 100644

--- a/sql/sql_cache.h

+++ b/sql/sql_cache.h

@@ -350,7 +350,7 @@ class Query_cache

   size_t min_allocation_unit, min_result_data_size;

   uint def_query_hash_size, def_table_hash_size;

-  size_t mem_bin_num, mem_bin_steps;		// See at init_cache & find_bin

+  uint mem_bin_num, mem_bin_steps;		// See at init_cache & find_bin

   bool initialized;

In my test resuls above, this minimal patch appeared to cause a slight performance regression, but I think that we can explain it by saying that it falls within the 5% or 10% of fluctuation.

Patch 2 removes st_mem_root::name and the name parameter of init_alloc_root():

diff --git a/include/my_alloc.h b/include/my_alloc.h

index 3ba8a02fc48..c9879125d96 100644

--- a/include/my_alloc.h

+++ b/include/my_alloc.h

@@ -52,7 +52,9 @@ typedef struct st_mem_root

   unsigned int first_block_usage;

   void (*error_handler)(void);

+#ifndef DBUG_OFF

   const char *name;

+#endif

 } MEM_ROOT;

 #ifdef  __cplusplus

diff --git a/include/my_sys.h b/include/my_sys.h

index 13ab7b12320..fb18cd92e8a 100644

--- a/include/my_sys.h

+++ b/include/my_sys.h

@@ -888,9 +888,16 @@ extern void my_free_lock(void *ptr);

 #define alloc_root_inited(A) ((A)->min_malloc != 0)

 #define ALLOC_ROOT_MIN_BLOCK_SIZE (MALLOC_OVERHEAD + sizeof(USED_MEM) + 8)

 #define clear_alloc_root(A) do { (A)->free= (A)->used= (A)->pre_alloc= 0; (A)->min_malloc=0;} while(0)

+#ifndef DBUG_OFF

 extern void init_alloc_root(MEM_ROOT *mem_root, const char *name,

                             size_t block_size, size_t pre_alloc_size,

                             myf my_flags);

+#else

+extern void init_alloc_Root(MEM_ROOT *mem_root,

+                            size_t block_size, size_t pre_alloc_size,

+                            myf my_flags);

+# define init_alloc_root(m,n,b,p,f) init_alloc_Root(m,b,p,f)

+#endif

 extern void *alloc_root(MEM_ROOT *mem_root, size_t Size);

 extern void *multi_alloc_root(MEM_ROOT *mem_root, ...);

 extern void free_root(MEM_ROOT *root, myf MyFLAGS);

diff --git a/mysys/my_alloc.c b/mysys/my_alloc.c

index 7139466be17..fddc9118312 100644

--- a/mysys/my_alloc.c

+++ b/mysys/my_alloc.c

@@ -54,9 +54,15 @@

     Because of this, we store in MY_THREAD_SPECIFIC as bit 1 in block_size

 */

+#ifndef DBUG_OFF

 void init_alloc_root(MEM_ROOT *mem_root, const char *name, size_t block_size,

 		     size_t pre_alloc_size __attribute__((unused)),

                      myf my_flags)

+#else

+void init_alloc_Root(MEM_ROOT *mem_root, size_t block_size,

+		     size_t pre_alloc_size __attribute__((unused)),

+                     myf my_flags)

+#endif

 {

   DBUG_ENTER("init_alloc_root");

   DBUG_PRINT("enter",("root: %p  name: %s  prealloc: %zu", mem_root,

@@ -72,7 +78,9 @@ void init_alloc_root(MEM_ROOT *mem_root, const char *name, size_t block_size,

   mem_root->block_num= 4;			/* We shift this with >>2 */

   mem_root->first_block_usage= 0;

   mem_root->total_alloc= 0;

+#ifndef DBUG_OFF

   mem_root->name= name;

+#endif

 #if !(defined(HAVE_valgrind) && defined(EXTRA_DEBUG))

   if (pre_alloc_size)

I would suggest to include this patch in 10.3 in some form.

With GCC 7.3.0 and the 3-minute CPU-bound ramdisk benchmark, we still appear to have a significant regression somewhere between 10.3.4 and 10.3.5. I will keep trying to trace it down while Svoj can concentrate on the originally reported regression.

I can still repeat the huge drop caused by commit 6c279ad6a71c63cb595fde7c951aadb31c3dbebc: dropping from 207119.69tps to 130029.74tps. I narrowed it down to the sql_class.h and sql_class.cc changes in that commit, but when I reverted that part of the patch in the latest 10.3, I did not see any improvement.

In my benchmark, I would see contention in lock_sys.mutex and log_sys.mutex. The situation should be improved by MDEV-16232 and MDEV-14425.

Also, at low concurrency, it seems that purge is wasting resources and creating unnecessary contention. Perhaps the amount of purge threads should be automatically scaled based on the amount of purgeable records?

A bad merge of MDEV-14705 to MariaDB 10.3.6 causes frequent calls to service_manager_extend_timeout() from all purge threads. These calls were supposed to only occur during a slow shutdown. This will be fixed in MDEV-17003.

Given that the performance regression reported in this ticket was reported on Windows, where the systemd interface is not present, this probably does not explain much of the regression. Also, I probably did not have libsystemd-dev installed when compiling code for running benchmarks.

By now, we are all educated that MDEV-12288 caused that issue. It just came not really announced back then