unexplained extremely low performance

[Mati]

Hello,

I have a WAN Galera cluster, 4 nodes, 2 per data center, 60ms between data centers and 20MB/s connection between nodes. Each machine is with SSD, and 16GB ram.

Generally, the execution time of updates/inserts is around 60ms, as expected. However, in some cases the execution time is ~300ms. I did some digging and narrowed it down to the simplest case ever - a table with a single record, no indexes, simple structure and an update that takes 300ms. This is all while there is no use whatsoever in the cluster, no queries executed in parallel. All because I am updating with REPEAT('a',64*1024), rather than REPEAT('a',1). 64KB brings down the cluster performance.

Please help me analyze and resolve this situation. Thank you.

The 64KB case

Query:

# reset
START TRANSACTION;
UPDATE test SET html=REPEAT('q',64*1024) WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;

SET profiling=1;

# first update, set 64KB of data
START TRANSACTION;
UPDATE test SET html=REPEAT('e',64*1024) WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;

# second update, reset the data
START TRANSACTION;
UPDATE test SET html='' WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;

SHOW PROFILES;

The result is as follows (they are the same even without the transactions, also when table row format is not compressed):

1	0.00005439	START TRANSACTION
2	0.00185255	UPDATE test SET html=REPEAT('e',64*1024) WHERE use...
3	0.24935809	COMMIT
4	0.00005166	START TRANSACTION
5	0.00083209	UPDATE test SET html='' WHERE users_xsite_id=24138...
6	0.12672389	COMMIT

The 1 byte case

Query:

# reset
START TRANSACTION;
UPDATE test SET html=REPEAT('q',1) WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;

SET profiling=1;

# first update, set 64KB of data
START TRANSACTION;
UPDATE test SET html=REPEAT('e',1) WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;

# second update, reset the data
START TRANSACTION;
UPDATE test SET html='' WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;

SHOW PROFILES;

The profiling, expected performance:

1	0.00004916	# first update, set 64KB of data START TRANSACTIO...
2	0.00021921	UPDATE test SET html=REPEAT('e',1) WHERE users_xsi...
3	0.06215270	COMMIT
4	0.00004508	# second update, reset the data START TRANSACTION
5	0.00025207	UPDATE test SET html='' WHERE users_xsite_id=24138...
6	0.06292883	COMMIT

Configurations and structure

The table structure is:

CREATE TABLE `test` (  `users_xsite_id` int(10) unsigned NOT NULL,  `xsite_templates_prototypes_id` int(10) unsigned NOT NULL,  `html` longtext,  `type` enum('smartphone','facebook_fangate','facebook','desktop') NOT NULL ) ENGINE=InnoDB DEFAULT CHARSET=utf8 ROW_FORMAT=COMPRESSED

The node configurations are:

innodb_buffer_pool_size = 10G

innodb_log_file_size = 100M

wsrep_retry_autocommit = 0

wsrep_sst_method = rsync

wsrep_provider_options=\"gcache.size = 512M; gcache.name = /tmp/galera.cache; gcache.page_size = 100M\"

wsrep_slave_threads = 16

binlog_format=ROW

innodb_autoinc_lock_mode=2

innodb_flush_log_at_trx_commit=2

innodb_locks_unsafe_for_binlog = 1

gtid-domain-id=1

gtid_strict_mode=1

binlog-format=ROW

log-slave-updates=1

[Philip Stoev]

Hello,

This presentation

http://www.slideshare.net/philip_stoev/using-galera-cluster-to-power-geodistributed-applications-on-the-wan

has some settings you may wish to try.

Philip Stoev

--
You received this message because you are subscribed to the Google Groups
"codership" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to codership-tea...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Mati]

Thank you for the reference. It improved some matters, but not all.

I applied the following settings:

innodb_flush_log_at_trx_commit = 0

binlog_row_event_max_size = 1048576

wsrep_provider_options="gcache.size = 512M; gcache.name = /tmp/galera.cache; gcache.page_size = 100M; gcs.max_packet_size=1048576; evs.send_window=512; evs.user_send_window=256; gmcast.segment=1;"

(each data center got its own gmcast.segment)

And the TCP configurations:

echo 'net.core.wmem_max=12582912' >> /etc/sysctl.conf

echo 'net.core.rmem_max=12582912' >> /etc/sysctl.conf

echo 'net.ipv4.tcp_rmem= 10240 87380 12582912' >> /etc/sysctl.conf

echo 'net.ipv4.tcp_wmem= 10240 87380 12582912' >> /etc/sysctl.conf

echo 'net.ipv4.tcp_window_scaling = 1' >> /etc/sysctl.conf

echo 'net.ipv4.tcp_timestamps = 1' >> /etc/sysctl.conf

echo 'net.ipv4.tcp_sack = 1' >> /etc/sysctl.conf

echo 'net.ipv4.tcp_no_metrics_save = 1' >> /etc/sysctl.conf

echo 'net.core.netdev_max_backlog = 5000' >> /etc/sysctl.conf

sysctl -p

The profiling now yields:

Query_ID	Duration	Query
1	0.00004905

# first update, set 64KB of data START TRANSACTIO...

2	0.00124282

UPDATE test SET html=REPEAT('e',64*1024) WHERE use...

3	0.12855567	COMMIT
4	0.00005271

# second update, reset the data START TRANSACTION

5	0.00052889

UPDATE test SET html='' WHERE users_xsite_id=24138...

6	0.06527989	COMMIT

The first commit is still twice as slow as should be. It seems to me, that only the size of the commit (64KB) creates the issue (the second commit, has an expected performance). Any ideas?

Kind regards,

Mati Skiba

[Philip Stoev]

Hello,

Please try to double the second number in the net.ipv4.tcp_wmem and
net.ipv4.tcp_rmem values. Also please make sure all settings are applied to
all nodes in the cluster.

When running tests you may find it useful to run each test multiple times in
rapid succession in order to allow the TCP buffers and windows in the kernel
to settle into their proper sizes.

Thank you.

[Mati]

I will try that.

The steps I am taking are (for each nodes, in order):

* update the configuration files.

* cat the files, see that changes are in place.

* restart node

To be double sure, after all of that, I also reboot each node.

And then perform the test about 5 times in a row.

Is that sufficient?

Mati

[Philip Stoev]

Yes, that should be sufficient.

[Mati]

I went even further and applied the following:

echo 'net.ipv4.tcp_rmem= 1048576 1048576 12582912' >> /etc/sysctl.conf

echo 'net.ipv4.tcp_wmem= 1048576 1048576 12582912' >> /etc/sysctl.conf

sysctl -p

Sadly, I am still getting the 125ms for the commit:

Query_ID	Duration	Query
1	0.00005239

# first update, set 64KB of data START TRANSACTIO...

2	0.00119961

UPDATE test SET html=REPEAT('e',64*1024) WHERE use...

3	0.12520868	COMMIT
4	0.00004421

# second update, reset the data START TRANSACTION

5	0.00042427

UPDATE test SET html='' WHERE users_xsite_id=24138...

6	0.06514427	COMMIT

Any ideas?

Kind regards,

Mati Skiba

[Jörg Brühe]

Hi!

On 20.10.2015 17:16, Mati wrote:
> I went even further and applied the following:
> |
> echo 'net.ipv4.tcp_rmem= 1048576 1048576 12582912' >> /etc/sysctl.conf
> echo 'net.ipv4.tcp_wmem= 1048576 1048576 12582912' >> /etc/sysctl.conf
> sysctl -p
> |
>
> Sadly, I am still getting the 125ms for the commit:
> Query_ID Duration Query
> 1 0.00005239 # first update, set 64KB of data
> START TRANSACTIO...
> 2 0.00119961 UPDATE test SET html=REPEAT('e',64*1024) WHERE use...
> 3 0.12520868 COMMIT
> 4 0.00004421 # second update, reset the data
> START TRANSACTION
> 5 0.00042427 UPDATE test SET html='' WHERE users_xsite_id=24138...
> 6 0.06514427 COMMIT
>
>
> Any ideas?

If I got you right, your setup contains these points:

1) You are ensuring a clean system (by reboot) before you are running
your test.
2) The table contains one row only, and field "html" is empty.
3) Your table does not have a primary key.
4) Your test expands field "html" to 64 kB.

I suspect this expansion forces disk space allocation, most probably for
'test.ibd' (file-per-table is now default), and this might be slow.

Also, accessing the row by a primary key should be faster than a search
by a non-indexed field.
IMNSHO, every table should have a primary key, and performance will
benefit if that is used to access the data.

Did you measure the same transaction in a purely local system, without
Galera? This will show you how much time a stock MySQL already needs
(without communication latency).


HTH,
Joerg

--
Joerg Bruehe, Senior MySQL Support Engineer, joerg....@fromdual.com
FromDual GmbH, Rebenweg 6, CH - 8610 Uster
Geschäftsführer: Oliver Sennhauser
Handelsregister-Eintrag: CH-020.4.044.539-3

[Mati]

Hello Jorg,

I tested it on a local setup. The same operation takes a fraction of the time (0.00014200s). The system has a lot of ram, fast disks (SSD) and no one is using it at the moment. 

I deleted the keys to prevent slow-downs by INDEX updates. But I now added a primary key (on the users_xsite_id field). The results are still the same.

Since its a rather clean multiply of 60ms, I am rather sure its because of a double round trip to one of the remote servers, or a single trip to each.

Regards,

Mati

[James Wang]

what is your DC to DC RTT please?

just ping from one  DC to another will find out RTT

[alexey.y...@galeracluster.com]

On 2015-10-20 17:00, Mati wrote:
> Hello Jorg,
>
> I tested it on a local setup. The same operation takes a fraction of
> the
> time (0.00014200s). The system has a lot of ram, fast disks (SSD) and
> no
> one is using it at the moment.
> I deleted the keys to prevent slow-downs by INDEX updates. But I now
> added
> a primary key (on the users_xsite_id field). The results are still the
> same.
>
> Since its a rather clean multiply of 60ms, I am rather sure its because
> of
> a double round trip to one of the remote servers, or a single trip to
> each.

I suspect that "clean" multiple is just a coincidence.
gcs.max_packet_size is not respected above 32K (you should see it in the
error log) so there should be at least 3 packets sent, but
gcomm.*send_window should take care of that (unless there is a bug). You
can infer the actual size of a writeset replicated from the wsrep_%
status variables. Of interest are the number of bytes and number of keys
replicated per each trx. If you could get the difference in the writeset
size and the number of keys between 64K and '' cases, it could shed some
light.

> Regards,
> Mati
>

[Mati]

Hello,

It is 60ms

Kind regards,
Mati Skiba

[Mati]

Hello Alexey,

Thank you for your reply.
I did "cat /var/log/syslog | grep max_packet_size" but saw no error message.

Here are the delta's in the relevant wsrep_% statuses you reffered to.

wsrep_% delta in server where update is execute:

wsrep_last_committed	3
wsrep_replicated	3
wsrep_replicated_bytes	262879
wsrep_repl_keys	9
wsrep_repl_keys_bytes	141
wsrep_repl_data_bytes	262546
wsrep_repl_other_bytes	0
wsrep_received	0
wsrep_received_bytes	0

wsrep_% delta in local DB server (compared to previous):

wsrep_last_committed	3
wsrep_replicated	0
wsrep_replicated_bytes	0
wsrep_repl_keys	0
wsrep_repl_keys_bytes	0
wsrep_repl_data_bytes	0
wsrep_repl_other_bytes	0
wsrep_received	3
wsrep_received_bytes	262879

wsrep_% delta in remote DC server:

wsrep_last_committed	3
wsrep_replicated	0
wsrep_replicated_bytes	0
wsrep_repl_keys	0
wsrep_repl_keys_bytes	0
wsrep_repl_data_bytes	0
wsrep_repl_other_bytes	0
wsrep_received	3
wsrep_received_bytes	262879

I reduced the number of nodes from 4 to 3, 2 "local" DB, 1 "remote" DB, to narrow down the issue, still the same behavior:

Query_ID	Duration	Query
1	0.00005133

# first update, set 64KB of data START TRANSACTIO...

2	0.00111972

UPDATE test SET html=REPEAT('e',64*1024) WHERE use...

3	0.12098766	COMMIT
4	0.00004771

# second update, reset the data START TRANSACTION

5	0.00041681

UPDATE test SET html='' WHERE users_xsite_id=24138...

6	0.06256374	COMMIT

Kind regards,
Mati Skiba

[alexey.y...@galeracluster.com]

Hi Mati,

1) Do I understand it correctly that the difference 3 for
wsrep_last_committed is for 64K and reset transactions together? Or just
for the 64K transaction?

2) Do you still have primary keys on the table?

3) Does the table contents after 64K update look as expected - i.e. only
one row is changed?

4) Can you repeat the experiment after setting wsrep_retry_autocommit=0?

> [1]
>
> QUERY_ID
> DURATION
> QUERY

[Mati]

Hello Alexey.

I reinstalled all of the servers, narrowed it down to only 2 servers (different data centers) and added the wsrep_retry_autocommit=0 configuration.
Also made sure it is 64KB, as you suggestion (the stats I provided were for the 3 actions)
The poor performance is still there. I don't know what else I could do.

I can allow root access to the servers, if you or anything else would like to investigate the matter.

Kind regards,
Mati

[alexey.y...@galeracluster.com]

On 2015-10-29 18:55, Mati wrote:
> Hello Alexey.
>
> I reinstalled all of the servers, narrowed it down to only 2 servers
> (different data centers) and added the wsrep_retry_autocommit=0
> configuration.
> Also made sure it is 64KB, as you suggestion (the stats I provided were
> for
> the 3 actions)

3 actions? I thought it was just two: 64K update and empty string
update. What gives? What is the 3rd action?
Can you just do a single 64K update and check by how much
wsrep_last_committed is incremented?

> The poor performance is still there. I don't know what else I could do.

Is there anything in the mysql error log?

[Mati]

Hello Alexey.

I perform the experiment. The initial state before capturing the status was of:

START TRANSACTION;
UPDATE test SET html=REPEAT('q',64*1024) WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;


Then I captured the status and executed:

# first update, set 64KB of data


START TRANSACTION;
UPDATE test SET html=REPEAT('e',64*1024) WHERE users_xsite_id=241383 and xsite_templates_prototypes_id=5 and type='desktop';
COMMIT;


The diffed status on the remote server was:

wsrep_last_committed

1

wsrep_replicated	0
wsrep_replicated_bytes	0
wsrep_repl_keys	0
wsrep_repl_keys_bytes	0
wsrep_repl_data_bytes	0
wsrep_repl_other_bytes	0

wsrep_received	1
wsrep_received_bytes	262425

The diffed status on the local server (where the statement was executed) was:

wsrep_last_committed	1
wsrep_replicated	1
wsrep_replicated_bytes	262425
wsrep_repl_keys	4
wsrep_repl_keys_bytes	55
wsrep_repl_data_bytes	262306

wsrep_repl_other_bytes	0
wsrep_received	0
wsrep_received_bytes	0

Is there anything there to show was the issue is?

Kind regards,
Mati

[alexey.y...@galeracluster.com]

Unfortunately no. This all looks like it should look. And gives
absolutely no hint about why the latency is twice as high. Perhaps there
is an hidden internal limit on how much data can be in flight
simultaneously, not just a number of packets.

One interesting experiment would be to vary the size of update and plot
replicated bytes against commit latency. Will it jump discretely at
certain intervals or will it increase gradually? Will the jumps be
exactly 1RTT?

> --
> You received this message because you are subscribed to the Google
> Groups "codership" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to codership-tea...@googlegroups.com.

> For more options, visit https://groups.google.com/d/optout [1].
>
>
> Links:
> ------
> [1] https://groups.google.com/d/optout

[Mati]

Hello,

Sorry for the late reply - I reinstalled the entire cluster, and performed many tests.
I created a script which performs the update statement, with varying payload from 32KB to 127KB, for each payload, performing 50 iterations and capturing the time taken and reporting the number of iterations exceeding 2TTL.
The script can be found here (run from machine with local connection where Galera server is at. update connection settings).

I run the test in such a way:

# on all nodes
service mysql stop ; rm /var/log/mysql/* ; rm /var/lib/mysql/mysqld-bin.*

# on node where test script will be running
service mysql start --wsrep_new_cluster
service mysql start --wsrep-cluster-address="gcomm://"

# on other nodes
service mysql start

# on node where test script will be running
php testCluster.php

The results are troubling, as can be seen from the following graph (y - number of iterations exceeding 2TTL, x - payload size in KB):

Even more troubling is the fact that I managed to have a good performing cluster, consistently, as can be seen by the following graph.
For some reason, at some point it stopped with this good performance. I don't know why.

Notes:
* I shut down all nodes except one, the execution time was <5ms - means, the execution times are resulted by Galera.
* Besides the test run, there is no use of the cluster. No queries are run.
* My cluster size is 4. 2 servers 16GB with 8 vCores in data center A, 2 servers 16GB with 4 vCores in data center B. All have dedicated SSD disks.
* My Galera configurations are:

[mysqld]
default_storage_engine=innodb
bind-address = 0.0.0.0

innodb_buffer_pool_size = 10G
innodb_log_file_size = 100M

innodb_file_per_table
innodb_file_format      = Barracuda

server-id=....
gtid-domain-id=1
gtid_strict_mode=1
binlog-format=ROW
log-slave-updates=1
bin-log

wsrep_provider = /usr/lib/galera/libgalera_smm.so
wsrep_cluster_name = cluster
wsrep_node_name = ...
wsrep_node_address = ...

wsrep_retry_autocommit = 0
wsrep_sst_method =

rsync
binlog_row_event_max_size = 1048576

wsrep_slave_threads = 16

binlog_format=ROW
innodb_autoinc_lock_mode=2

innodb_flush_log_at_trx_commit=0
innodb_locks_unsafe_for_binlog = 1

For data center A also

wsrep_provider_options=\"gcache.size = 512M; gcache.name = /tmp/galera.cache; gcache.page_size = 100M; gcs.max_packet_size=1048576; evs.send_window=512; evs.user_send_window=256; gmcast.segment=0;\"

For data center B also

wsrep_provider_options=\"gcache.size = 512M; gcache.name = /tmp/galera.cache; gcache.page_size = 100M; gcs.max_packet_size=1048576; evs.send_window=512; evs.user_send_window=256; gmcast.segment=1;\"

* My TCP configurations are:

net.core.wmem_max=12582912
net.core.rmem_max=12582912
net.core.wmem_default=12582912
net.core.rmem_default=12582912
net.ipv4.tcp_rmem= 12582912 12582912 12582912
net.ipv4.tcp_wmem= 12582912 12582912 12582912
net.ipv4.tcp_slow_start_after_idle = 0
net.ipv4.tcp_window_scaling = 1
net.ipv4.tcp_timestamps = 1
net.ipv4.tcp_sack = 1
net.ipv4.tcp_no_metrics_save = 1
net.core.netdev_max_backlog = 5000

I do not know how to debug this issue further. Please assist.

Kind regards,
Mati Skiba

[alexey.y...@galeracluster.com]

On 2015-11-09 12:19, Mati wrote:
> Hello,
>
> Sorry for the late reply - I reinstalled the entire cluster, and
> performed many tests.
> I created a script which performs the update statement, with varying
> payload from 32KB to 127KB, for each payload, performing 50 iterations
> and capturing the time taken and reporting the number of iterations
> exceeding 2TTL.

I take it you mean 2RTT?

Too bad we don't have the actual latencies: are they multiples of RTT or
not. And too bad we don't see how it jumps from small updates to bigger
updates. I'd use a geometric progression, something like

for ( $i = 0 ; $i < 16 ; $i++ )
performTest(1 << $i);

But anyway, the way how chaotic it looks suggests that there is some
noise in play, probably packet loss. I would suggest checking for it.

And setting gcs.max_packet_size to something small, like 16K or 8K might
help.

> The script can be found here [2] (run from machine with local

> connection where Galera server is at. update connection settings).
>
> I run the test in such a way:
>
> # on all nodes
> service mysql stop ; rm /var/log/mysql/* ; rm
> /var/lib/mysql/mysqld-bin.*
>
> # on node where test script will be running
> service mysql start --wsrep_new_cluster
> service mysql start --wsrep-cluster-address="gcomm://"
>
> # on other nodes
> service mysql start
>
> # on node where test script will be running
> php testCluster.php
>
> The results are troubling, as can be seen from the following graph (y
> - number of iterations exceeding 2TTL, x - payload size in KB):
>

> Even more troubling is the fact that I managed to have a good
> performing cluster, consistently, as can be seen by the following
> graph.
> For some reason, at some point it stopped with this good performance.
> I don't know why.
>

>>> [1] https://groups.google.com/d/optout [1]

>
> --
> You received this message because you are subscribed to the Google
> Groups "codership" group.
> To unsubscribe from this group and stop receiving emails from it, send
> an email to codership-tea...@googlegroups.com.

> For more options, visit https://groups.google.com/d/optout.

>
>
> Links:
> ------
> [1] https://groups.google.com/d/optout

> [2] http://codepad.org/rOVRCQQc

[Mati]

Hello Alexey and all,

Thank you very much for all your assistance. Everything is working perfectly now.
It was a combination of the configurations, plus some network issue that was resolved.

I don't know how exactly to offer it, but if anyone encounters similar issues, I'd be more than happy to assist.

Kind regards,
Mati Skiba

[hunter86bg]

Could you be more specific? I might be in a similar situation.

[Mati]

Hello,

I believe I was very specific. What would you like to know?

Kind regards,

Mati

[hunter86bg]

Could you share your current my.cnf and short description of the causes of the issue and how did you resolved it.

I'm asking ,because we have a cluster of 4 VMs on 4 Blade Servers in the same enclosure. It seems we have issues as we keep getting flow control messages but IO and CPU utilization are very low. We are testing with simple INSERTs in several tables.

[Gart Nilis]

If you still have this problem on a standalone database with galera enabled then try disable autocommit on each transaction.  That solved my problem in addition to innodb_flush_log_at_trx_commit=0 or 2 which also manifested itself on standalone.

First test on standalone with Galera enabled to verify if it's Galera or because of the WAN.