[DOC] wsrep_flow_control_paused does not really seem to ever become 0

Bug #1338523 reported by Kenny Gryp
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
Status tracked in 5.6
5.5
Invalid
Undecided
Unassigned
5.6
Confirmed
Undecided
Alexey Zhebel

Bug Description

the documentation says:
"The fraction of time since the last status query that replication was paused due to flow control.
In other words, how much the slave lag is slowing down the cluster."

However, I do not see such behavior. with an idle cluster, the wsrep_flow_control_paused seem to drop bit by bit, it seems to not reset anymore when 'show global status' is ran.

pxc3 mysql> show global status like 'wsrep_received%';
+----------------------+----------+
| Variable_name | Value |
+----------------------+----------+
| wsrep_received | 140 |
| wsrep_received_bytes | 32769939 |
+----------------------+----------+
2 rows in set (0.00 sec)

pxc3 mysql> show global status like 'wsrep_f%';
+------------------------------+-------------+
| Variable_name | Value |
+------------------------------+-------------+
| wsrep_flow_control_paused_ns | 27913832854 |
| wsrep_flow_control_paused | 0.026364 |
| wsrep_flow_control_sent | 12 |
| wsrep_flow_control_recv | 12 |
+------------------------------+-------------+
4 rows in set (0.00 sec)

pxc3 mysql> select sleep(60);
+-----------+
| sleep(60) |
+-----------+
| 0 |
+-----------+
1 row in set (1 min 0.03 sec)

pxc3 mysql> show global status like 'wsrep_received%';
+----------------------+----------+
| Variable_name | Value |
+----------------------+----------+
| wsrep_received | 140 |
| wsrep_received_bytes | 32769939 |
+----------------------+----------+
2 rows in set (0.01 sec)

pxc3 mysql> show global status like 'wsrep_f%';
+------------------------------+-------------+
| Variable_name | Value |
+------------------------------+-------------+
| wsrep_flow_control_paused_ns | 27913832854 |
| wsrep_flow_control_paused | 0.024874 |
| wsrep_flow_control_sent | 12 |
| wsrep_flow_control_recv | 12 |
+------------------------------+-------------+
4 rows in set (0.00 sec)

Tags: doc
Revision history for this message
Kenny Gryp (gryp) wrote :

- 5.6.15-56 Percona XtraDB Cluster (GPL), Release 25.5, Revision 759, wsrep_25.5.r4061
- | wsrep_provider_vendor | Codership Oy <email address hidden> |
| wsrep_provider_version | 3.5(r178) |

Revision history for this message
Alex Yurchenko (ayurchen) wrote :

ahh, do you guys ever get content? ;) It is a fix for https://bugs.launchpad.net/galera/+bug/1180792 . Reading status no longer resets it. Use flush status.

Revision history for this message
Kenny Gryp (gryp) wrote :

Alex, I do not mind the change to not longer reset it, but either the code or the documentation was wrong. :)

So let's make it a documentation bug:
- http://www.percona.com/doc/percona-xtradb-cluster/5.6/wsrep-status-index.html#wsrep_flow_control_sent
- http://galeracluster.com/documentation-webpages/galerastatusvariables.html#wsrep-flow-control-paused

Actually, why not just remove wsrep_flow_control_paused completely where wsrep_flow_control_paused_ns exists.
 wsrep_flow_control_paused doesn't really show us anything interesting anymore except how much % of total server time was flow control active (or FLUSH STATUS, which is not commonly used). It will just keep on confusing people.

summary: - wsrep_flow_control_paused does not really seem to ever become 0
+ [DOC] wsrep_flow_control_paused does not really seem to ever become 0
tags: added: doc
Revision history for this message
Alex Yurchenko (ayurchen) wrote :

well, wsrep_flow_control_paused and wsrep_flow_control_paused_ns show exactly the same information, but in different form. And IMO the % of time is far more readable and understandable than nanoseconds. At least when you see that it is 90% you know that something is wrong. When you see 98702358642 - what does it tell you? - first you need to figure out when the last FLUSH STATUS happened.

Revision history for this message
Kenny Gryp (gryp) wrote :

I agree that if you use FLUSH STATUS with wsrep_flow_control_paused you have a good indication on what is going on.

Monitoring/trending tools however do not do FLUSH STATUS, so wsrep_flow_control_paused is not useful for monitoring it.
So that makes the nanosecond wsrep_flow_control_paused_ns more interesting (possibly by converting it to milliseconds :)) to me as I usually use tools to look at data.

Revision history for this message
Przemek (pmalkowski) wrote :
Download full text (3.5 KiB)

I think it should be made clear in the documentation that this change happened only in Galera 3.x.

percona1 mysql> select @@version; show status like 'wsrep_provider_version';
+----------------+
| @@version |
+----------------+
| 5.5.39-36.0-55 |
+----------------+
1 row in set (0.00 sec)

+------------------------+----------------+
| Variable_name | Value |
+------------------------+----------------+
| wsrep_provider_version | 2.11(r318911d) |
+------------------------+----------------+
1 row in set (0.00 sec)

percona1 mysql> flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)

percona1 mysql> show status like 'ws%flow%';
+---------------------------+----------+
| Variable_name | Value |
+---------------------------+----------+
| wsrep_flow_control_paused | 0.278969 |
| wsrep_flow_control_sent | 1 |
| wsrep_flow_control_recv | 1 |
+---------------------------+----------+
3 rows in set (0.00 sec)

percona1 mysql> show status like 'ws%flow%';
+---------------------------+----------+
| Variable_name | Value |
+---------------------------+----------+
| wsrep_flow_control_paused | 1.000000 |
| wsrep_flow_control_sent | 0 |
| wsrep_flow_control_recv | 0 |
+---------------------------+----------+
3 rows in set (0.00 sec)

percona1 mysql> unlock tables;
Query OK, 0 rows affected (0.00 sec)

percona1 mysql> show status like 'ws%flow%';
+---------------------------+----------+
| Variable_name | Value |
+---------------------------+----------+
| wsrep_flow_control_paused | 0.982063 |
| wsrep_flow_control_sent | 0 |
| wsrep_flow_control_recv | 0 |
+---------------------------+----------+
3 rows in set (0.00 sec)

percona1 mysql> show status like 'ws%flow%';
+---------------------------+----------+
| Variable_name | Value |
+---------------------------+----------+
| wsrep_flow_control_paused | 0.000000 |
| wsrep_flow_control_sent | 0 |
| wsrep_flow_control_recv | 0 |
+---------------------------+----------+
3 rows in set (0.00 sec)

The same PXC version but with Galera 3.x:

percona2 mysql> select @@version; show status like 'wsrep_provider_version';
+----------------+
| @@version |
+----------------+
| 5.5.39-36.0-55 |
+----------------+
1 row in set (0.00 sec)

+------------------------+---------------+
| Variable_name | Value |
+------------------------+---------------+
| wsrep_provider_version | 3.7(r7f44a18) |
+------------------------+---------------+
1 row in set (0.00 sec)

percona2 mysql> show status like 'ws%flow%';
+------------------------------+----------------+
| Variable_name | Value |
+------------------------------+----------------+
| wsrep_flow_control_paused_ns | 39192035930593 |
| wsrep_flow_control_paused | 0.385263 |
| wsrep_flow_control_sent | 2 |
| wsrep_flow_control_recv | 5 |
+------------------------------+----------------+
4 rows in set (0.00 sec)

percona2 mysql> show status like 'ws%flow%';
+------------------------------+----------------+
| Variable_name ...

Read more...

Revision history for this message
Alexey Zhebel (alexey-zhebel) wrote :

Will be tracked as part of https://jira.percona.com/browse/DOC-563

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXC-1696

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.