[MDEV-31089] Connections counter increases with replication Created: 2023-04-19  Updated: 2023-06-27  Resolved: 2023-06-27

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.5.18, 10.5.19
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Nicolas Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: 10.5, connection, replication, thread
Environment:

debian 11

Attachments: PNG File Capture d’écran 2023-04-19 à 18.37.33.png     PNG File Capture d’écran 2023-04-19 à 18.41.54.png     PNG File Capture d’écran 2023-04-19 à 18.42.31.png     PNG File Capture d’écran 2023-04-19 à 18.46.38.png     Text File variables.log    

 Description   

Hello everyone,

I and my team spent a lot of time before posting this bug, and maybe it's not really a bug, but we can't figure out why our server has this behaviour.

We had 5 servers with debian 10 + mariaDB 10.3.38, everything was fine. We recently upgraded to debian 11 + mariaDB 10.5.18 and we started to have a high connect rate.

we upgraded on 23th march (week 12). We can see clearly on the chart below that connect_rate increased by about 4 times.

connect_rate is a probe from CheckMK monitoring, which reads Connections variable from SHOW GLOBAL STATUS.

When showing this variable every 10 seconds, counter increases a lot:

MariaDB [(none)]> show global status like 'Connections';
 
+---------------+----------+
 
| Variable_name | Value    |
 
+---------------+----------+
 
| Connections   | 33742168 |
 
+---------------+----------+
 
1 row in set (0,002 sec)
 
 
 
MariaDB [(none)]> show global status like 'Connections';
 
+---------------+----------+
 
| Variable_name | Value    |
 
+---------------+----------+
 
| Connections   | 33742651 |
 
+---------------+----------+
 
1 row in set (0,001 sec)

483 new connections in about 10 seconds.

But when listing processlist, there aren't so many running sessions.

And our trafic hasn't increased neither.

All our servers are in ring replication, so all are master-master, and slave from previous one.

sql1 <=> sql2 <=> sql3 <=> sql4 <=> sql5 =>

So we tried with another slave connected to sql1, with only replication as client (no read from any application or other client): same problem.

sql1 <=> sql2 <=> sql3 <=> sql4 <=> sql5 =>

sql8

But when we stop replication (STOP SLAVE), new connections don't increase no more! I checked in the source code, "Connections" global status variable seems to be increased every new connection, and should have created a new thread.

We tried to enable audit plugin, but we can't see all intermediate connection_id.

We also tried to enable the general_log for a few minutes, we can see replication queries, with connection_id = the same in the processlist, but we can't find other one.

Connection rate increases when there are many queries in the replication.

So our main problems are:

  • connect_rate that triggers our monitoring alerts
  • the result is that performance has decreased a lot, because server seems to be on heavyload permanently, with some peaks when there are many queries replication.

We searched a lot on Internet, but we can't find any post or any bug in this tracker speaking about this behaviour.

What it seems to be weird, is that we can't find in the general_log nor in the audit log queries or connections with new IDs. All queries made by replication have the same connection_id. But when there are many queries, connection rate increases, which seems to be a link between the two.

I assume that queries replication shouldn't create new connections or increase Connections counter?

Binlog format from master sql1 is in MIXED format.

thread_handling one-thread-per-connection

Is this behaviour normal?

Thanks a lot!

 Comments   
Comment by Nicolas [ 2023-04-19 ]

here is an example:

21:19:55

MariaDB [(none)]> show global status like 'Connections';
 
+---------------+--------+
 
| Variable_name | Value  |
 
+---------------+--------+
 
| Connections   | 145201 |
 
+---------------+--------+
 
1 row in set (0.002 sec)
 
 
 
 
 
MariaDB [(none)]> start slave;
 
Query OK, 0 rows affected (0.002 sec)
 
 
 
MariaDB [(none)]> show global status like 'Connections';
 
+---------------+--------+
 
| Variable_name | Value  |
 
+---------------+--------+
 
| Connections   | 145220 |
 
+---------------+--------+
 
1 row in set (0.003 sec)

21:19:58

MariaDB [(none)]> show global status like 'Connections';
 
+---------------+--------+
 
| Variable_name | Value  |
 
+---------------+--------+
 
| Connections   | 145235 |
 
+---------------+--------+
 
1 row in set (0.003 sec)

from audit log:

20230419 21:19:51,sql8,root,localhost,145193,25130827,QUERY,,'show global status like \'Connections\'',0
 
20230419 21:19:53,sql8,root,localhost,145193,25130828,QUERY,,'show global status like \'Connections\'',0
 
20230419 21:19:55,sql8,root,localhost,145193,25130829,QUERY,,'start slave',0
 
20230419 21:19:57,sql8,root,localhost,145193,25132845,QUERY,,'show global status like \'Connections\'',0
 
20230419 21:19:59,sql8,root,localhost,145193,25134907,QUERY,,'show global status like \'Connections\'',0
 
20230419 21:20:17,sql8,root,localhost,145250,0,CONNECT,,,0
 
20230419 21:20:17,sql8,root,localhost,145250,0,DISCONNECT,,,0
 
20230419 21:20:17,sql8,root,localhost,145251,0,CONNECT,,,0
 
20230419 21:20:17,sql8,root,localhost,145251,25136747,QUERY,,'show global status',0
 
20230419 21:20:17,sql8,root,localhost,145251,25136748,QUERY,,'show global variables',0
 
20230419 21:20:17,sql8,root,localhost,145251,0,DISCONNECT,,,0
 
20230419 21:20:17,sql8,root,localhost,145252,0,CONNECT,,,0
 
20230419 21:20:17,sql8,root,localhost,145252,25136750,QUERY,,'SELECT table_schema, sum(data_length + index_length), sum(data_free)\n           FROM information_schema.TABLES GROUP BY table_schema',0
 
20230419 21:20:17,sql8,root,localhost,145252,0,DISCONNECT,,,0
 
20230419 21:20:17,sql8,root,localhost,145254,0,CONNECT,,,0
 
20230419 21:20:17,sql8,root,localhost,145254,25136776,QUERY,,'show slave status',0
 
20230419 21:20:17,sql8,root,localhost,145254,0,DISCONNECT,,,0


MariaDB [(none)]> show processlist;
 
+--------+-----------------+-----------+------+--------------+-------+--------------------------------------------------------+------------------+----------+
 
| Id     | User            | Host      | db   | Command      | Time  | State                                                  | Info             | Progress |
 
+--------+-----------------+-----------+------+--------------+-------+--------------------------------------------------------+------------------+----------+
 
|  22124 | event_scheduler | localhost | NULL | Daemon       | 19789 | Waiting on empty queue                                 | NULL             |    0.000 |
 
|  47247 | root            | localhost | NULL | Sleep        | 16137 |                                                        | NULL             |    0.000 |
 
| 145193 | root            | localhost | NULL | Query        |     0 | starting                                               | show processlist |    0.000 |
 
| 145202 | system user     |           | NULL | Slave_IO     |   102 | Waiting for master to send event                       | NULL             |    0.000 |
 
| 145204 | system user     |           | NULL | Slave_worker |     1 | Waiting for work from SQL thread                       | NULL             |    0.000 |
 
| 145205 | system user     |           | NULL | Slave_worker |     0 | Waiting for work from SQL thread                       | NULL             |    0.000 |
 
| 145203 | system user     |           | NULL | Slave_SQL    |   102 | Slave has read all relay log; waiting for more updates | NULL             |    0.000 |
 
+--------+-----------------+-----------+------+--------------+-------+--------------------------------------------------------+------------------+----------+

Comment by Sergei Golubchik [ 2023-05-26 ]

Replication connections are still connections and they are counted as such, this is normal. But, of course, replication slave should not reconnect 50 times a second, so it cannot explain why you got 483 new connections in 10 seconds.

Queries from the audit log looks like monitoring queries. Could you have some kind of a monitoring tool (e.g. your CheckMK) that starts doing a lot more work when replication is enabled? For example — just a guess — may be it tries to walk the replication topology from the master to slaves and collect some stats, but because you have a ring, it just runs forever in circles? Try to break the ring and see if Connections stops increasing. Or disable your monitoring and see if Connections stops increasing.

Either way, it's likely not the replication itself.

Generated at Thu Feb 08 10:21:12 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.