search

signal18 / replication-manager

Signal 18 repman - Replication Manager for MySQL / MariaDB / Percona Server
https://signal18.io/products/srm
GNU General Public License v3.0
648 stars 167 forks source link

Monitor connections to the backend servers not closing with PFS #273

Closed 0x6d617474 closed 5 years ago

0x6d617474 commented 5 years ago

We have recently started using RM to manage our simple master/slave cluster running MariaDB 10.3. 

[root@engr-dbprxy-201 ~]# replication-manager-cli version
Replication Manager 2.0.1 for MariaDB 10.x and MySQL 5.7 Series
Full Version:  2.0.1-18-gb4ffd27f
Build Time:  2018-11-25T09:58:56+0000

We have run into an issue where the RM process (run from another server) is opening connections to the backend servers to check state, but it is not closing the connections. The connection pool quickly fills up, and clients are unable to connect to the servers. Additionally, since RM itself is no longer able to connect, it assumes the backend servers have failed, and so attempts to initiate failover.

Here are the configs for RM:

config.toml

```toml [Default] include = "/etc/replication-manager/cluster.d" failover-mode = "automatic" failover-at-sync = true failover-readonly = true failover-pre-script = "" failover-post-script = "" autorejoin = true autorejoin-backup-binlog = true autorejoin-mysqldump = true autorejoin-script = false autorejoin-flashback-on-sync = true autorejoin-slave-positional-hearbeat = true switchover-at-equal-gtid = false # This causes problems during switchover switchover-at-sync = true switchover-slave-wait-catch = true switchover-wait-kill = 10000 switchover-wait-trx = 5 switchover-wait-write-query = 10 check-binlog-filters = true check-replication-filters = true check-replication-state = true force-slave-readonly = true force-sync-binlog = true force-sync-innodb = true force-slave-semisync = true force-binlog-annotate-embedded = false force-binlog-checksum = false force-binlog-compress = true force-binlog-row = true force-binlog-slowqueries = false force-slave-gtid-mode = true force-slave-no-gtid-mode = false force-slave-heartbeat = true force-noslave-behind = true log-file = "/var/log/replication-manager.log" log-rotate = true verbose = 1 log-level = 3 monitoring-ticker = 2 monitoring-scheduler = false # Automatically runs cleanup scripts. Don't # Changing this requires the password to be used at the command-line # Safe to leave defaults so long as the firewall denys access # api-credential = "admin:repman" graphite-embedded = true graphite-metrics = true graphite-carbon-api-port = "10002" http-server = true http-bind-address = "0.0.0.0" http-port = "10001" ```

cluster.d/cluster01.toml

```toml [cluster01] title = "Main Cluster" db-servers-hosts = "152.1.0.150,152.1.0.151,152.1.0.152" db-servers-prefered-master = "152.1.0.150" db-servers-ignored-hosts = "152.1.0.152" db-servers-connect-timeout = 5 db-servers-read-timeout = 15 db-servers-credential = "sys_monitor:[REDACTED]" db-servers-tls-ca-cert = "" db-servers-tls-client-cert = "" db-servers-tls-client-key = "" replication-credential = "sys_replication:[REDACTED]" replication-use-ssl = false replication-master-slave = true proxy-servers-read-on-master = "true" proxysql = "true" proxysql-servers = "152.1.0.155" proxysql-port = "3306" proxysql-admin-port = "6032" proxysql-user = "prxyadmin" proxysql-password = "[REDACTED]" proxysql-bootstrap = false # Servers are configured into ProxySQL via puppet proxysql-copy-grants = true # Copy users into proxysql when they are created at runtime proxysql-writer-hostgroup = "0" proxysql-reader-hostgroup = "1" ```

/var/log/replication-manager.log

``` 2019/03/08 09:47:10 [cluster01] INFO - New server monitored: 152.1.0.150 2019/03/08 09:47:10 [cluster01] INFO - New server monitored: 152.1.0.151 2019/03/08 09:47:10 [cluster01] INFO - New server monitored: 152.1.0.152 2019/03/08 09:47:10 [cluster01] INFO - Failover in automatic mode 2019/03/08 09:47:10 [cluster01] INFO - Loading 1 proxies 2019/03/08 09:47:10 [cluster01] INFO - Loading ProxySQL... 2019/03/08 09:47:10 [cluster01] ERROR - No master found from replication 2019/03/08 09:47:10 [cluster01] INFO - Set stateSlave from rejoin slave 152.1.0.151 2019/03/08 09:47:10 [cluster01] INFO - Init Proxy Type: proxysql Host: 152.1.0.155 Port: 6032 2019/03/08 09:47:10 [cluster01] STATE - OPENED ERR00021 : All cluster db servers down 2019/03/08 09:47:10 [cluster01] STATE - OPENED WARN0058 : No GTID strict mode on slave 152.1.0.151 2019/03/08 09:47:10 [cluster01] STATE - OPENED WARN0070 : No GTID strict mode on master 152.1.0.150 2019/03/08 09:47:12 [cluster01] STATE - RESOLV ERR00021 : All cluster db servers down ```


Here's a screenshot of the backend servers without replication-manager running:

image

And here is the same but with replication-manager running for about 20-30 seconds: image

As you can see, a lot of connections remain open. Interestingly, the master node (the top panel) correctly closes the connections; however, yesterday afternoon the situation was reversed, and only the master node was accumulating connections.

Any thoughts on why this is happening, or how to fix it? I'm happy to provide more information if needed.

svaroqui commented 5 years ago

Hi Matt ,

Could it be that the network is super buzzy, indeed go drivers do process database request with a pool , so if many concurrent request are trigger at the same time than you may get multiple connections.

Are you not connecting to db via a proxy like ProxySQL ? Did you change the default TCP IP stack via sysctl.conf ?

/svar Thanks for the report !

svaroqui commented 5 years ago

Regarding the conf,

autorejoin-slave-positional-hearbeat = true Is for pseudo GTID this is not usefull for MariaDB or MySQL using GTID i guess tis trigger insert on the master that may consume connections

Can you check without it ?

0x6d617474 commented 5 years ago

svar,

A few extra connections is no issue, but it will quickly reach the maximum connection limit as it is creating a new connection every 2 seconds (the monitor ticker interval), and does not every close them.

I have disabled autorejoin-slave-positional-hearbeat, along with all of the force- options, and the issue remains.

I will also add that in testing this setup a few months ago, I never ran into this issue. The configuration for everything is the same (managed by Puppet), and basically the only difference is that we loaded our production data into the cluster and connected clients to it. I'm not sure why this would do anything to cause this issue though.

Are you not connecting to db via a proxy like ProxySQL ?

All the end-users connect through ProxySQL, but replication manager connects directly to the backends.

Did you change the default TCP IP stack via sysctl.conf ?

The system is a stock minimal RHEL 7 install, with very little changes.

/etc/sysctl.conf + /usr/lib/sysctl.d/*

``` # sysctl settings are defined through files in # /usr/lib/sysctl.d/, /run/sysctl.d/, and /etc/sysctl.d/. # # Vendors settings live in /usr/lib/sysctl.d/. # To override a whole file, create a new file with the same in # /etc/sysctl.d/ and put new settings there. To override # only specific settings, add a file with a lexically later # name in /etc/sysctl.d/ and put new settings there. # # For more information, see sysctl.conf(5) and sysctl.d(5). # Kernel sysctl configuration file # # For binary values, 0 is disabled, 1 is enabled. See sysctl(8) and # sysctl.conf(5) for more details. # Disable netfilter on bridges. net.bridge.bridge-nf-call-ip6tables = 0 net.bridge.bridge-nf-call-iptables = 0 net.bridge.bridge-nf-call-arptables = 0 # When yama is enabled in the kernel it might be used to filter any user # space access which requires PTRACE_MODE_ATTACH like ptrace attach, access # to /proc/PID/{mem,personality,stack,syscall}, and the syscalls # process_vm_readv and process_vm_writev which are used for interprocess # services, communication and introspection (like synchronisation, signaling, # debugging, tracing and profiling) of processes. # # Usage of ptrace attach is restricted by normal user permissions. Normal # unprivileged processes cannot interact through ptrace with processes # that they cannot send signals to or processes that are running set-uid # or set-gid. # # yama ptrace scope can be used to reduce these permissions even more. # This should normally not be done because it will break various programs # relying on the default ptrace security restrictions. But can be used # if you don't have any other way to separate processes in their own # domains. A different way to restrict ptrace is to set the selinux # deny_ptrace boolean. Both mechanisms will break some programs relying # on the ptrace system call and might force users to elevate their # priviliges to root to do their work. # # For more information see Documentation/security/Yama.txt in the kernel # sources. Which also describes the defaults when CONFIG_SECURITY_YAMA # is enabled in a kernel build (currently 1 for ptrace_scope). # # This runtime kernel parameter can be set to the following options: # (Note that setting this to anything except zero will break programs!) # # 0 - Default attach security permissions. # 1 - Restricted attach. Only child processes plus normal permissions. # 2 - Admin-only attach. Only executables with CAP_SYS_PTRACE. # 3 - No attach. No process may call ptrace at all. Irrevocable. # kernel.yama.ptrace_scope = 0 # This file is part of systemd. # # systemd is free software; you can redistribute it and/or modify it # under the terms of the GNU Lesser General Public License as published by # the Free Software Foundation; either version 2.1 of the License, or # (at your option) any later version. # See sysctl.d(5) and core(5) for for documentation. # To override settings in this file, create a local file in /etc # (e.g. /etc/sysctl.d/90-override.conf), and put any assignments # there. # System Request functionality of the kernel (SYNC) # # Use kernel.sysrq = 1 to allow all keys. # See http://fedoraproject.org/wiki/QA/Sysrq for a list of values and keys. kernel.sysrq = 16 # Append the PID to the core filename kernel.core_uses_pid = 1 # Source route verification net.ipv4.conf.default.rp_filter = 1 net.ipv4.conf.all.rp_filter = 1 # Do not accept source routing net.ipv4.conf.default.accept_source_route = 0 net.ipv4.conf.all.accept_source_route = 0 # Promote secondary addresses when the primary address is removed net.ipv4.conf.default.promote_secondaries = 1 net.ipv4.conf.all.promote_secondaries = 1 # Enable hard and soft link protection fs.protected_hardlinks = 1 fs.protected_symlinks = 1 ```

0x6d617474 commented 5 years ago

So, an interesting anecdote:

While the connection issue is happening, it seems that if you restart the mysqld process on the backend server and let RM change the status to SUSPECT and back to SLAVE, it stops spamming connections, and maintains one or two consistently.

Restarting RM doesn't reintroduce the problem, so I think the internal database go into a weird state that causes the problem. Also explains why identical configuration from before didn't trigger it.

0x6d617474 commented 5 years ago

After leaving it running for a while, it hit the same issue on one of the slaves again:

/var/log/replication-manager.log

``` 2019/03/08 20:27:12 [cluster01] INFO - Failover monitor switched to manual mode 2019/03/08 23:05:11 [cluster01] ERROR - Could not get slaves status Error 1040: Too many connections 2019/03/08 23:05:12 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:12 [cluster01] STATE - OPENED ERR00033 : Skip slave in election 152.1.0.152 have no master log file, slave might have failed 2019/03/08 23:05:14 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:16 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:18 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:20 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:22 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:25 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:27 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:29 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:31 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:33 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:36 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:38 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:40 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:42 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:44 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:47 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:49 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:51 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:53 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:55 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:05:58 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:00 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:02 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:04 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:06 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:08 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:11 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:13 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:15 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:17 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:19 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:22 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:24 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:26 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:28 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:30 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:32 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:34 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:37 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:39 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:41 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:43 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:45 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:48 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:50 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:52 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:54 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:56 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:06:58 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:01 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:03 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:05 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:07 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:09 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:12 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:14 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:16 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:18 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:20 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:23 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:25 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:27 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:29 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:31 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:34 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:36 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:38 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:40 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:42 [cluster01] INFO - Enforce GTID replication on slave 152.1.0.152 2019/03/08 23:07:44 [cluster01] ALERT - Server 152.1.0.152 state changed from Slave to Suspect 2019/03/08 23:07:44 [cluster01] STATE - RESOLV ERR00033 : Skip slave in election 152.1.0.152 have no master log file, slave might have failed 2019/03/08 23:07:53 [cluster01] INFO - Declaring server 152.1.0.152 as failed 2019/03/08 23:07:53 [cluster01] ALERT - Server 152.1.0.152 state changed from Suspect to Failed 2019/03/08 23:07:55 [cluster01] ERROR - No master found from replication 2019/03/08 23:07:57 [cluster01] ERROR - No master found from replication 2019/03/08 23:07:59 [cluster01] ERROR - No master found from replication 2019/03/08 23:08:01 [cluster01] ERROR - No master found from replication 2019/03/08 23:08:05 [cluster01] WARN - No crash found on current master 152.1.0.150 2019/03/08 23:08:05 [cluster01] INFO - Enforce binlog compression on slave 152.1.0.152 ```


The first error is when the connections filled up on the slave, which triggered a bunch of strangeness with trying to enforce GTID replication (which was enabled on the server). The ALERT at 23:07:44 was when i restarted the mysqld process on the slave.

There's nothing in any logs I can find for why it suddenly started spamming connections again.

svaroqui commented 5 years ago

I'm Matt We do get a deployement on version 2.1 in production on kubernetes, and a moving weave network cross continent ,without such issues can you let me know :

svaroqui commented 5 years ago

For 2.1 testing can you start with minimalist config

[Default]
log-file="/var/log/replication-manager/replication-manager.log"
graphite-metrics = true
graphite-embedded = true

[cluster1]
title = "cluster1" 
db-servers-hosts = "..."
db-servers-prefered-master = "..."
db-servers-ignored-hosts = ""
db-servers-credential = "xxx"
db-servers-connect-timeout = 2
replication-credential = "xxxx"
monitoring-scheduler = false
scheduler-db-servers-logical-backup = false
scheduler-db-servers-logs = false
scheduler-db-servers-optimize = false
scheduler-db-servers-physical-backup = false   
proxysql=false
svaroqui commented 5 years ago

I notice that you are using proxysql copy user with i only get deployed once That beast is having is own pool You can use a proxysql conf that get all server in reader group, that proxy sql will follow read only flag 

mysql_variables=
{
    threads=4
    max_connections=100
    default_query_delay=0
    default_query_timeout=36000000
    have_compress=true
    poll_timeout=2000
    interfaces="0.0.0.0:3306;/tmp/proxysql.sock"
    default_schema="information_schema"
    stacksize=1048576
    server_version="5.5.30"
    connect_timeout_server=3000
    monitor_history=600000
    monitor_connect_interval=60000
        monitor_ping_interval=4000
    monitor_read_only_interval=1500
    monitor_read_only_timeout=500
        monitor_username="xxx"
        monitor_password="xxxx"
    ping_interval_server_msec=20000
    ping_timeout_server=1000
    commands_stats=true
    sessions_sort=true
    connect_retries_on_failure=10
    monitor_writer_is_also_reader=1
}

# defines all the MySQL servers
mysql_servers =
(

{ address="db1" , port=3306 , hostgroup=1, max_connections=1024, weight=1 },
{ address="db2" , port=3306 , hostgroup=1, max_connections=1024, weight=1 }

)

mysql_users:
(
 { username = "usr" , password = "pwd" , default_hostgroup = 0 , active = 1 }
) 

mysql_replication_hostgroups=
(
        {
                writer_hostgroup=0
                reader_hostgroup=1
                comment="repl 1"
       }
)
svaroqui commented 5 years ago

Here is good kernel setup for buzy connection server Connections machines:

net.core.somaxconn = 8192
net.ipv4.tcp_max_orphans = 200000
net.ipv4.tcp_max_syn_backlog = 8192
net.core.netdev_max_backlog = 262144
net.ipv4.ip_local_port_range = 1024 65535
net.ipv4.tcp_fin_timeout = 5

net.ipv4.tcp_tw_reuse = 1
# Discourage Linux from swapping idle processes to disk (default = 60)
vm.swappiness = 10
# Increase Linux autotuning TCP buffer limits
# Set max to 16MB for 1GE and 32M (33554432) or 54M (56623104) for 10GE
# Don't set tcp_mem itself! Let the kernel scale it based on RAM.
net.core.rmem_max = 16777216
net.core.wmem_max = 16777216
net.core.rmem_default = 16777216
net.core.wmem_default = 16777216
net.core.optmem_max = 40960
net.ipv4.tcp_rmem = 4096 87380 16777216
net.ipv4.tcp_wmem = 4096 65536 16777216
# Make room for more TIME_WAIT sockets due to more clients,
# and allow them to be reused if we run out of sockets
# Also increase the max packet backlog
net.core.netdev_max_backlog = 50000
net.ipv4.tcp_max_syn_backlog = 30000
net.ipv4.tcp_max_tw_buckets = 2000000
net.ipv4.tcp_tw_reuse = 1
net.ipv4.tcp_fin_timeout = 10
# Disable TCP slow start on idle connections
net.ipv4.tcp_slow_start_after_idle = 0
# If your servers talk UDP, also up these limits
net.ipv4.udp_rmem_min = 8192
net.ipv4.udp_wmem_min = 8192
# Disable source routing and redirects
net.ipv4.conf.all.send_redirects = 0
net.ipv4.conf.all.accept_redirects = 0
net.ipv4.conf.all.accept_source_route = 0
# Log packets with impossible addresses for security
net.ipv4.conf.all.log_martians = 1

Client machines

net.core.rmem_max = 16777216
net.core.wmem_max = 16777216
net.core.rmem_default = 16777216
net.core.wmem_default = 16777216
net.core.optmem_max = 40960
net.ipv4.tcp_rmem = 1024 4096 16384
net.ipv4.tcp_wmem = 1024 4096 16384
0x6d617474 commented 5 years ago

svar,

We unfortunately aren't able to reliably reproduce the issue ourselves. With no config changes, sometimes everything will run fine after a mysqld restart, and then we'll hit the issue again after ~3 hours.

We also ran this in a test environment for several weeks without issue, and only started running into problems once we loaded data onto it and pointed clients at it.

So I'm not sure if this will help to reproduce the issue, but here is the information you asked for:

0x6d617474 commented 5 years ago

Since we run into the issue when all the proxysql stuff is disabled, I don't think that's a direct contributor.

We are a bit unique in our setup because although we manage all the infrastructure, we essentially offer hosted databases to end-users, and we don't get much say in how the databases get used. (We are a university, and anyone from researchers to students use this infrastructure). We have a single proxysql server that we manage (well, two with a keepalived failover) that acts as a gateway to the cluster, rather than having proxysql deployed on the application servers (since we often time cannot control those).

We enable proxysql-copy-grants so that users created at runtime are populated into proxysql. Since we have end-users who can create new users, this is essential to allow them to connect after creating the user. We have several hundred user accounts at any given time, and we do not have plaintext passwords for most of them, so putting them in the proxysql config is not an option.

We could make use of the proxysql-admin script from Percona to sync the proxysql node with the backend at regular intervals, but having it immediately available from replication-manager populating it is very convenient.

0x6d617474 commented 5 years ago

Confirmed that running 2.1 (via Docker) with the config you posted also has the same issue.

svaroqui commented 5 years ago

Thanks for all information

While you are the first one reporting such issue , we will investigate 2 different solutions

I'll keep you posted when we will be ready to test

svaroqui commented 5 years ago

Build using go-mysql 1.4.1 is in http://ci.signal18.io/mrm/builds/2.1/ appreciate if you get a chance to test this release

0x6d617474 commented 5 years ago

Confirmed that the issue still persists when using the OSC RPM in the repo you linked.

EDIT: Some more observations that may help with debugging:

I'll continue try to see if I can find some way to trigger the problem, since I have a known way to reset.

svaroqui commented 5 years ago

Re,

In 2.1 you can increase the repman log level , there is connection error tracking to help digging what can be the issue

Assigning a global connection on server no global connection is yet assigned in repman ping

Server refresh failed but ping connect Reopen a connection if an error is return from Refresh if server.Conn == nil { return errors.New("Connection is nil, server unreachable") } if server.Conn.Unsafe() == nil { return errors.New("Connection is unsafe, server unreachable") }

err := server.Conn.Ping() if err != nil { return err } server.Variables, err = dbhelper.GetVariables(server.Conn) if err != nil { server.ClusterGroup.LogPrintf(LvlErr, "Could not get variables %s", err) return err }

Would really help to figure out the case connections are recreated ?

svaroqui commented 5 years ago

I've build a new release removing one possible connection leak if show variables is incorrectly parse witch i doubt it can happen but who knows

0x6d617474 commented 5 years ago

Alright, we encountered the issue on one of our replicas again. We started replication-manager, waited for a few seconds to ensure that the server was accumulating open connections, and then killed replman.

152.1.0.150 is the master, working as expected. 152.1.0.151 is the replica, which doesn't seem to close connections.

Here's the log file from running the latest 2.1 build with log-level set to 7 during that time:

/var/log/replication-manager.log

``` 2019/03/13 17:46:03 [cluster1] INFO - Loading 0 proxies 2019/03/13 17:46:03 [cluster1] INFO - No file found: open /var/lib/replication-manager/cluster1/clusterstate.json: no such file or directory 2019/03/13 17:46:03 [cluster1] DEBUG - Monitoring server loop 2019/03/13 17:46:03 [cluster1] DEBUG - Server [0]: URL: 152.1.0.150 State: Suspect PrevState: Suspect 2019/03/13 17:46:03 [cluster1] DEBUG - Server [1]: URL: 152.1.0.151 State: Suspect PrevState: Suspect 2019/03/13 17:46:03 [cluster1] DEBUG - State unconnected set by non-master rule on server 152.1.0.150 2019/03/13 17:46:03 [cluster1] DEBUG - Server 152.1.0.150 was set master as last non slave 2019/03/13 17:46:03 [cluster1] DEBUG - Privilege check on 152.1.0.150 2019/03/13 17:46:03 [cluster1] DEBUG - Client connection found on server 152.1.0.150 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:04 [cluster1] DEBUG - Server 152.1.0.151 is configured as a slave 2019/03/13 17:46:04 [cluster1] DEBUG - Privilege check on 152.1.0.151 2019/03/13 17:46:04 [cluster1] DEBUG - Client connection found on server 152.1.0.151 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:04 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:04 [cluster1] DEBUG - Checking if server 152.1.0.151 is a slave of server 152.1.0.150 2019/03/13 17:46:04 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:04 [cluster1] DEBUG - Lookup server 152.1.0.150 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:04 [cluster1] DEBUG - Lookup server 152.1.0.151 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:06 [cluster1] DEBUG - Monitoring server loop 2019/03/13 17:46:06 [cluster1] DEBUG - Server [0]: URL: 152.1.0.150 State: Master PrevState: StandAlone 2019/03/13 17:46:06 [cluster1] DEBUG - Server [1]: URL: 152.1.0.151 State: Slave PrevState: Slave 2019/03/13 17:46:06 [cluster1] DEBUG - Master [ ]: URL: 152.1.0.150 State: Master PrevState: StandAlone 2019/03/13 17:46:06 [cluster1] DEBUG - Slave [0]: URL: 152.1.0.151 State: Slave PrevState: Slave 2019/03/13 17:46:06 [cluster1] DEBUG - Server 152.1.0.150 was set master as last non slave 2019/03/13 17:46:06 [cluster1] DEBUG - Lookup server 152.1.0.150 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:06 [cluster1] DEBUG - Lookup server 152.1.0.151 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:06 [cluster1] DEBUG - Privilege check on 152.1.0.150 2019/03/13 17:46:06 [cluster1] DEBUG - Client connection found on server 152.1.0.150 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:06 [cluster1] DEBUG - Server 152.1.0.151 is configured as a slave 2019/03/13 17:46:06 [cluster1] DEBUG - Privilege check on 152.1.0.151 2019/03/13 17:46:06 [cluster1] DEBUG - Client connection found on server 152.1.0.151 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:06 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:06 [cluster1] DEBUG - Checking if server 152.1.0.151 is a slave of server 152.1.0.150 2019/03/13 17:46:06 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:06 [cluster1] STATE - OPENED WARN0084 : Variable diff: + Master Variable: RELAY_LOG_INDEX -> /VAR/LIB/MYSQL/ENGR-DBMSC-200-EOS-NCSU-EDU-RELAY-BIN.INDEX - Slave: 152.1.0.151 -> /VAR/LIB/MYSQL/ENGR-DBMSC-201-EOS-NCSU-EDU-RELAY-BIN.INDEX + Master Variable: RELAY_LOG -> ENGR-DBMSC-200-EOS-NCSU-EDU-RELAY-BIN - Slave: 152.1.0.151 -> ENGR-DBMSC-201-EOS-NCSU-EDU-RELAY-BIN + Master Variable: RELAY_LOG_BASENAME -> /VAR/LIB/MYSQL/ENGR-DBMSC-200-EOS-NCSU-EDU-RELAY-BIN - Slave: 152.1.0.151 -> /VAR/LIB/MYSQL/ENGR-DBMSC-201-EOS-NCSU-EDU-RELAY-BIN 2019/03/13 17:46:06 [cluster1] DEBUG - Lookup server 152.1.0.150 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:06 [cluster1] DEBUG - Lookup server 152.1.0.151 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:08 [cluster1] DEBUG - Monitoring server loop 2019/03/13 17:46:08 [cluster1] DEBUG - Server [0]: URL: 152.1.0.150 State: Master PrevState: Master 2019/03/13 17:46:08 [cluster1] DEBUG - Server [1]: URL: 152.1.0.151 State: Slave PrevState: Slave 2019/03/13 17:46:08 [cluster1] DEBUG - Master [ ]: URL: 152.1.0.150 State: Master PrevState: Master 2019/03/13 17:46:08 [cluster1] DEBUG - Slave [0]: URL: 152.1.0.151 State: Slave PrevState: Slave 2019/03/13 17:46:08 [cluster1] DEBUG - Server 152.1.0.150 was set master as last non slave 2019/03/13 17:46:08 [cluster1] DEBUG - Lookup server 152.1.0.150 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:08 [cluster1] DEBUG - Lookup server 152.1.0.151 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:08 [cluster1] DEBUG - Privilege check on 152.1.0.150 2019/03/13 17:46:08 [cluster1] DEBUG - Client connection found on server 152.1.0.150 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:08 [cluster1] DEBUG - Server 152.1.0.151 is configured as a slave 2019/03/13 17:46:08 [cluster1] DEBUG - Privilege check on 152.1.0.151 2019/03/13 17:46:08 [cluster1] DEBUG - Client connection found on server 152.1.0.151 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:08 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:08 [cluster1] DEBUG - Checking if server 152.1.0.151 is a slave of server 152.1.0.150 2019/03/13 17:46:08 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:08 [cluster1] DEBUG - Lookup server 152.1.0.150 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:08 [cluster1] DEBUG - Lookup server 152.1.0.151 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:10 [cluster1] DEBUG - Monitoring server loop 2019/03/13 17:46:10 [cluster1] DEBUG - Server [0]: URL: 152.1.0.150 State: Master PrevState: Master 2019/03/13 17:46:10 [cluster1] DEBUG - Server [1]: URL: 152.1.0.151 State: Slave PrevState: Slave 2019/03/13 17:46:10 [cluster1] DEBUG - Master [ ]: URL: 152.1.0.150 State: Master PrevState: Master 2019/03/13 17:46:10 [cluster1] DEBUG - Slave [0]: URL: 152.1.0.151 State: Slave PrevState: Slave 2019/03/13 17:46:10 [cluster1] DEBUG - Server 152.1.0.150 was set master as last non slave 2019/03/13 17:46:10 [cluster1] DEBUG - Lookup server 152.1.0.150 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:10 [cluster1] DEBUG - Lookup server 152.1.0.151 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:10 [cluster1] DEBUG - Privilege check on 152.1.0.150 2019/03/13 17:46:10 [cluster1] DEBUG - Client connection found on server 152.1.0.150 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:10 [cluster1] DEBUG - Server 152.1.0.151 is configured as a slave 2019/03/13 17:46:10 [cluster1] DEBUG - Privilege check on 152.1.0.151 2019/03/13 17:46:10 [cluster1] DEBUG - Client connection found on server 152.1.0.151 with IP 152.1.0.154 for host 152.1.0.154 2019/03/13 17:46:10 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:10 [cluster1] DEBUG - Checking if server 152.1.0.151 is a slave of server 152.1.0.150 2019/03/13 17:46:10 [cluster1] DEBUG - GetMasterFromReplication server 23110119 lookup if server 152.1.0.150 is the one : 23110119 2019/03/13 17:46:10 [cluster1] DEBUG - Lookup server 152.1.0.150 if maxscale binlog server: 152.1.0.150 2019/03/13 17:46:10 [cluster1] DEBUG - Lookup server 152.1.0.151 if maxscale binlog server: 152.1.0.150 ```


Nothing strikes me as particularly out of place.

tanji commented 5 years ago

Hi, do you mean to say that the open connections are accumulated in just a few seconds?

svaroqui commented 5 years ago

Can you try out this,

http://ci.signal18.io/mrm/builds/2.1/replication-manager-osc-cgo-2.1.0_dev_642_g13f9-1.x86_64.rpm This is using the glibc for DNS resolution and socket communication . Tx

mdwheele commented 5 years ago

Hi, do you mean to say that the open connections are accumulated in just a few seconds?

@tanji

Yes, once we have a replica experiencing this issue, stopping replication-manager will drop all connections. Upon restart of replication-manager, the affected replica will immediately pick up an extra connection every 2 seconds until we stop the service again.

Restarting the mysqld process will clear this behaviour for any particular replica for some indeterminate amount of time. After some period of time, it inevitably happens again and we can then reproduce the behaviour.

0x6d617474 commented 5 years ago

Same results via http://ci.signal18.io/mrm/builds/2.1/replication-manager-osc-2.1.0_dev_646_gb56c-1.x86_64.rpm

The 642 build was no longer available.

This is the list of active processes in mariadb for the three servers a few seconds after starting RM. Under "normal" operation, there is only a single process.

image

svaroqui commented 5 years ago

Ok that's not good binar,y i would like you to test package named osc-cgo

0x6d617474 commented 5 years ago

For reference, here is the same taken just after restarting the mysql process on the bottom server. Note how there is only a single process.

image

0x6d617474 commented 5 years ago

Same issue via http://ci.signal18.io/mrm/builds/2.1/replication-manager-osc-cgo-2.1.0_dev_646_gb56c-1.x86_64.rpm

image

svaroqui commented 5 years ago

Any idea why this query is taking 13 second , in checking permission

0x6d617474 commented 5 years ago

I'm not sure. It only happens for the 2.1 builds on the master, and it doesn't appear to ever complete.

Here's the privs for the sys_monitor user: 

MariaDB [(none)]> SHOW GRANTS FOR sys_monitor;
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Grants for sys_monitor@%                                                                                                                                                  |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| GRANT SELECT, RELOAD, PROCESS, SUPER, REPLICATION CLIENT ON *.* TO 'sys_monitor'@'%' IDENTIFIED BY PASSWORD '[REDACTED]' WITH GRANT OPTION |
| GRANT ALL PRIVILEGES ON `replication_manager_schema`.* TO 'sys_monitor'@'%' WITH GRANT OPTION                                                                             |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set (0.000 sec)
svaroqui commented 5 years ago

Can you send a compete show global variables on the master and a select count(*) from information_schema.tables

0x6d617474 commented 5 years ago 
MariaDB [(none)]> select count(*) from information_schema.tables;
+----------+
| count(*) |
+----------+
|     6148 |
+----------+
1 row in set (0.009 sec)
SHOW GLOBAL VARIABLES

``` Variable_name Value alter_algorithm DEFAULT aria_block_size 8192 aria_checkpoint_interval 30 aria_checkpoint_log_activity 1048576 aria_encrypt_tables OFF aria_force_start_after_recovery_failures 0 aria_group_commit none aria_group_commit_interval 0 aria_log_file_size 1073741824 aria_log_purge_type immediate aria_max_sort_file_size 9223372036853727232 aria_page_checksum ON aria_pagecache_age_threshold 300 aria_pagecache_buffer_size 134217728 aria_pagecache_division_limit 100 aria_pagecache_file_hash_size 512 aria_recover_options BACKUP,QUICK aria_repair_threads 1 aria_sort_buffer_size 268434432 aria_stats_method nulls_unequal aria_sync_log_dir NEWFILE aria_used_for_temp_tables ON auto_increment_increment 1 auto_increment_offset 1 autocommit ON automatic_sp_privileges ON back_log 80 basedir /usr big_tables OFF bind_address 0.0.0.0 binlog_annotate_row_events ON binlog_cache_size 32768 binlog_checksum CRC32 binlog_commit_wait_count 0 binlog_commit_wait_usec 100000 binlog_direct_non_transactional_updates OFF binlog_file_cache_size 16384 binlog_format ROW binlog_optimize_thread_scheduling ON binlog_row_image FULL binlog_stmt_cache_size 32768 bulk_insert_buffer_size 8388608 character_set_client latin1 character_set_connection latin1 character_set_database latin1 character_set_filesystem binary character_set_results latin1 character_set_server latin1 character_set_system utf8 character_sets_dir /usr/share/mysql/charsets/ check_constraint_checks ON collation_connection latin1_swedish_ci collation_database latin1_swedish_ci collation_server latin1_swedish_ci column_compression_threshold 100 column_compression_zlib_level 6 column_compression_zlib_strategy DEFAULT_STRATEGY column_compression_zlib_wrap OFF completion_type NO_CHAIN concurrent_insert AUTO connect_timeout 10 core_file OFF datadir /var/lib/mysql/ date_format %Y-%m-%d datetime_format %Y-%m-%d %H:%i:%s deadlock_search_depth_long 15 deadlock_search_depth_short 4 deadlock_timeout_long 50000000 deadlock_timeout_short 10000 debug_no_thread_alarm OFF default_regex_flags default_storage_engine InnoDB default_tmp_storage_engine default_week_format 0 delay_key_write ON delayed_insert_limit 100 delayed_insert_timeout 300 delayed_queue_size 1000 div_precision_increment 4 encrypt_binlog OFF encrypt_tmp_disk_tables OFF encrypt_tmp_files OFF enforce_storage_engine eq_range_index_dive_limit 0 event_scheduler OFF expensive_subquery_limit 100 expire_logs_days 5 explicit_defaults_for_timestamp OFF extra_max_connections 1 extra_port 0 flush OFF flush_time 0 foreign_key_checks ON ft_boolean_syntax + -><()~*:""&| ft_max_word_len 84 ft_min_word_len 4 ft_query_expansion_limit 20 ft_stopword_file (built-in) general_log OFF general_log_file engr-dbmsc-200-eos-ncsu-edu.log group_concat_max_len 1048576 gtid_binlog_pos 1-23110119-753850 gtid_binlog_state 1-23110119-753850 gtid_current_pos 1-23110119-753850 gtid_domain_id 1 gtid_ignore_duplicates OFF gtid_pos_auto_engines gtid_slave_pos gtid_strict_mode OFF have_compress YES have_crypt YES have_dynamic_loading YES have_geometry YES have_openssl YES have_profiling YES have_query_cache YES have_rtree_keys YES have_ssl DISABLED have_symlink YES histogram_size 0 histogram_type SINGLE_PREC_HB host_cache_size 279 hostname engr-dbmsc-200.eos.ncsu.edu idle_readonly_transaction_timeout 0 idle_transaction_timeout 0 idle_write_transaction_timeout 0 ignore_builtin_innodb OFF ignore_db_dirs init_connect init_file init_slave innodb_adaptive_flushing ON innodb_adaptive_flushing_lwm 10.000000 innodb_adaptive_hash_index ON innodb_adaptive_hash_index_parts 8 innodb_adaptive_max_sleep_delay 150000 innodb_autoextend_increment 64 innodb_autoinc_lock_mode 1 innodb_background_scrub_data_check_interval 3600 innodb_background_scrub_data_compressed OFF innodb_background_scrub_data_interval 604800 innodb_background_scrub_data_uncompressed OFF innodb_buf_dump_status_frequency 0 innodb_buffer_pool_chunk_size 134217728 innodb_buffer_pool_dump_at_shutdown ON innodb_buffer_pool_dump_now OFF innodb_buffer_pool_dump_pct 25 innodb_buffer_pool_filename ib_buffer_pool innodb_buffer_pool_instances 1 innodb_buffer_pool_load_abort OFF innodb_buffer_pool_load_at_startup ON innodb_buffer_pool_load_now OFF innodb_buffer_pool_size 134217728 innodb_change_buffer_max_size 25 innodb_change_buffering all innodb_checksum_algorithm crc32 innodb_checksums ON innodb_cmp_per_index_enabled OFF innodb_commit_concurrency 0 innodb_compression_algorithm zlib innodb_compression_default OFF innodb_compression_failure_threshold_pct 5 innodb_compression_level 6 innodb_compression_pad_pct_max 50 innodb_concurrency_tickets 5000 innodb_data_file_path ibdata1:12M:autoextend innodb_data_home_dir innodb_deadlock_detect ON innodb_default_encryption_key_id 1 innodb_default_row_format dynamic innodb_defragment OFF innodb_defragment_fill_factor 0.900000 innodb_defragment_fill_factor_n_recs 20 innodb_defragment_frequency 40 innodb_defragment_n_pages 7 innodb_defragment_stats_accuracy 0 innodb_disable_sort_file_cache OFF innodb_disallow_writes OFF innodb_doublewrite ON innodb_encrypt_log OFF innodb_encrypt_tables OFF innodb_encryption_rotate_key_age 1 innodb_encryption_rotation_iops 100 innodb_encryption_threads 0 innodb_fast_shutdown 1 innodb_fatal_semaphore_wait_threshold 600 innodb_file_format innodb_file_per_table ON innodb_fill_factor 100 innodb_flush_log_at_timeout 1 innodb_flush_log_at_trx_commit 1 innodb_flush_method fsync innodb_flush_neighbors 1 innodb_flush_sync ON innodb_flushing_avg_loops 30 innodb_force_load_corrupted OFF innodb_force_primary_key OFF innodb_force_recovery 0 innodb_ft_aux_table innodb_ft_cache_size 8000000 innodb_ft_enable_diag_print OFF innodb_ft_enable_stopword ON innodb_ft_max_token_size 84 innodb_ft_min_token_size 3 innodb_ft_num_word_optimize 2000 innodb_ft_result_cache_limit 2000000000 innodb_ft_server_stopword_table innodb_ft_sort_pll_degree 2 innodb_ft_total_cache_size 640000000 innodb_ft_user_stopword_table innodb_idle_flush_pct 100 innodb_immediate_scrub_data_uncompressed OFF innodb_io_capacity 200 innodb_io_capacity_max 2000 innodb_large_prefix innodb_lock_schedule_algorithm fcfs innodb_lock_wait_timeout 50 innodb_locks_unsafe_for_binlog OFF innodb_log_buffer_size 16777216 innodb_log_checksums ON innodb_log_compressed_pages ON innodb_log_file_size 50331648 innodb_log_files_in_group 2 innodb_log_group_home_dir ./ innodb_log_optimize_ddl ON innodb_log_write_ahead_size 8192 innodb_lru_scan_depth 1024 innodb_max_dirty_pages_pct 75.000000 innodb_max_dirty_pages_pct_lwm 0.000000 innodb_max_purge_lag 0 innodb_max_purge_lag_delay 0 innodb_max_undo_log_size 10485760 innodb_monitor_disable innodb_monitor_enable innodb_monitor_reset innodb_monitor_reset_all innodb_old_blocks_pct 37 innodb_old_blocks_time 1000 innodb_online_alter_log_max_size 134217728 innodb_open_files 2000 innodb_optimize_fulltext_only OFF innodb_page_cleaners 1 innodb_page_size 16384 innodb_prefix_index_cluster_optimization OFF innodb_print_all_deadlocks OFF innodb_purge_batch_size 300 innodb_purge_rseg_truncate_frequency 128 innodb_purge_threads 4 innodb_random_read_ahead OFF innodb_read_ahead_threshold 56 innodb_read_io_threads 4 innodb_read_only OFF innodb_replication_delay 0 innodb_rollback_on_timeout OFF innodb_rollback_segments 128 innodb_scrub_log OFF innodb_scrub_log_speed 256 innodb_sort_buffer_size 1048576 innodb_spin_wait_delay 4 innodb_stats_auto_recalc ON innodb_stats_include_delete_marked OFF innodb_stats_method nulls_equal innodb_stats_modified_counter 0 innodb_stats_on_metadata OFF innodb_stats_persistent ON innodb_stats_persistent_sample_pages 20 innodb_stats_sample_pages 8 innodb_stats_traditional ON innodb_stats_transient_sample_pages 8 innodb_status_output OFF innodb_status_output_locks OFF innodb_strict_mode ON innodb_sync_array_size 1 innodb_sync_spin_loops 30 innodb_table_locks ON innodb_temp_data_file_path ibtmp1:12M:autoextend innodb_thread_concurrency 0 innodb_thread_sleep_delay 10000 innodb_tmpdir innodb_undo_directory ./ innodb_undo_log_truncate OFF innodb_undo_logs 128 innodb_undo_tablespaces 0 innodb_use_atomic_writes ON innodb_use_native_aio ON innodb_version 10.3.13 innodb_write_io_threads 4 interactive_timeout 28800 join_buffer_size 262144 join_buffer_space_limit 2097152 join_cache_level 2 keep_files_on_create OFF key_buffer_size 16777216 key_cache_age_threshold 300 key_cache_block_size 1024 key_cache_division_limit 100 key_cache_file_hash_size 512 key_cache_segments 0 large_files_support ON large_page_size 0 large_pages OFF lc_messages en_US lc_messages_dir lc_time_names en_US license GPL local_infile ON lock_wait_timeout 86400 locked_in_memory OFF log_bin ON log_bin_basename /var/lib/mysql/mariadb-bin log_bin_compress ON log_bin_compress_min_len 256 log_bin_index /var/lib/mysql/engr-dbmsc-200-eos-ncsu-edu-bin.index log_bin_trust_function_creators OFF log_disabled_statements sp log_error /var/log/mariadb/mariadb.log log_output FILE log_queries_not_using_indexes OFF log_slave_updates ON log_slow_admin_statements ON log_slow_disabled_statements sp log_slow_filter admin,filesort,filesort_on_disk,filesort_priority_queue,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk log_slow_rate_limit 1 log_slow_slave_statements ON log_slow_verbosity log_tc_size 24576 log_warnings 2 long_query_time 10.000000 low_priority_updates OFF lower_case_file_system OFF lower_case_table_names 0 master_verify_checksum OFF max_allowed_packet 16777216 max_binlog_cache_size 18446744073709547520 max_binlog_size 104857600 max_binlog_stmt_cache_size 18446744073709547520 max_connect_errors 100 max_connections 151 max_delayed_threads 20 max_digest_length 1024 max_error_count 64 max_heap_table_size 16777216 max_insert_delayed_threads 20 max_join_size 18446744073709551615 max_length_for_sort_data 1024 max_long_data_size 16777216 max_prepared_stmt_count 16382 max_recursive_iterations 4294967295 max_relay_log_size 104857600 max_seeks_for_key 4294967295 max_session_mem_used 9223372036854775807 max_sort_length 1024 max_sp_recursion_depth 0 max_statement_time 0.000000 max_tmp_tables 32 max_user_connections 0 max_write_lock_count 4294967295 metadata_locks_cache_size 1024 metadata_locks_hash_instances 8 min_examined_row_limit 0 mrr_buffer_size 262144 multi_range_count 256 myisam_block_size 1024 myisam_data_pointer_size 6 myisam_max_sort_file_size 9223372036853727232 myisam_mmap_size 18446744073709551615 myisam_recover_options BACKUP,QUICK myisam_repair_threads 1 myisam_sort_buffer_size 134216704 myisam_stats_method NULLS_UNEQUAL myisam_use_mmap OFF mysql56_temporal_format ON net_buffer_length 16384 net_read_timeout 30 net_retry_count 10 net_write_timeout 60 old OFF old_alter_table DEFAULT old_mode old_passwords OFF open_files_limit 4184 optimizer_prune_level 1 optimizer_search_depth 62 optimizer_selectivity_sampling_limit 100 optimizer_switch index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on,split_materialized=on optimizer_use_condition_selectivity 1 performance_schema ON performance_schema_accounts_size 100 performance_schema_digests_size 5000 performance_schema_events_stages_history_long_size 1000 performance_schema_events_stages_history_size 20 performance_schema_events_statements_history_long_size 1000 performance_schema_events_statements_history_size 20 performance_schema_events_waits_history_long_size 1000 performance_schema_events_waits_history_size 20 performance_schema_hosts_size 100 performance_schema_max_cond_classes 80 performance_schema_max_cond_instances 1360 performance_schema_max_digest_length 1024 performance_schema_max_file_classes 50 performance_schema_max_file_handles 32768 performance_schema_max_file_instances 2500 performance_schema_max_mutex_classes 200 performance_schema_max_mutex_instances 5648 performance_schema_max_rwlock_classes 40 performance_schema_max_rwlock_instances 3073 performance_schema_max_socket_classes 10 performance_schema_max_socket_instances 230 performance_schema_max_stage_classes 160 performance_schema_max_statement_classes 200 performance_schema_max_table_handles 2858 performance_schema_max_table_instances 667 performance_schema_max_thread_classes 50 performance_schema_max_thread_instances 288 performance_schema_session_connect_attrs_size 512 performance_schema_setup_actors_size 100 performance_schema_setup_objects_size 100 performance_schema_users_size 100 pid_file /var/run/mariadb/mariadb.pid plugin_dir /usr/lib64/mysql/plugin/ plugin_maturity gamma port 3306 preload_buffer_size 32768 profiling OFF profiling_history_size 15 progress_report_time 5 protocol_version 10 proxy_protocol_networks query_alloc_block_size 16384 query_cache_limit 262144 query_cache_min_res_unit 2048 query_cache_size 83886080 query_cache_strip_comments OFF query_cache_type ON query_cache_wlock_invalidate OFF query_prealloc_size 24576 range_alloc_block_size 4096 read_binlog_speed_limit 0 read_buffer_size 131072 read_only OFF read_rnd_buffer_size 262144 relay_log engr-dbmsc-200-eos-ncsu-edu-relay-bin relay_log_basename /var/lib/mysql/engr-dbmsc-200-eos-ncsu-edu-relay-bin relay_log_index /var/lib/mysql/engr-dbmsc-200-eos-ncsu-edu-relay-bin.index relay_log_info_file relay-log.info relay_log_purge ON relay_log_recovery OFF relay_log_space_limit 0 replicate_annotate_row_events ON replicate_do_db replicate_do_table replicate_events_marked_for_skip REPLICATE replicate_ignore_db replicate_ignore_table replicate_wild_do_table replicate_wild_ignore_table report_host engr-dbmsc-200.eos.ncsu.edu report_password report_port 3306 report_user rowid_merge_buff_size 8388608 rpl_semi_sync_master_enabled ON rpl_semi_sync_master_timeout 50 rpl_semi_sync_master_trace_level 32 rpl_semi_sync_master_wait_no_slave ON rpl_semi_sync_master_wait_point AFTER_COMMIT rpl_semi_sync_slave_delay_master OFF rpl_semi_sync_slave_enabled ON rpl_semi_sync_slave_kill_conn_timeout 5 rpl_semi_sync_slave_trace_level 32 secure_auth ON secure_file_priv secure_timestamp NO server_id 23110119 session_track_schema ON session_track_state_change OFF session_track_system_variables autocommit,character_set_client,character_set_connection,character_set_results,time_zone session_track_transaction_info OFF skip_external_locking ON skip_name_resolve ON skip_networking OFF skip_show_database OFF slave_compressed_protocol OFF slave_ddl_exec_mode IDEMPOTENT slave_domain_parallel_threads 2 slave_exec_mode STRICT slave_load_tmpdir /tmp slave_max_allowed_packet 1073741824 slave_net_timeout 60 slave_parallel_max_queued 131072 slave_parallel_mode optimistic slave_parallel_threads 2 slave_parallel_workers 2 slave_run_triggers_for_rbr NO slave_skip_errors OFF slave_sql_verify_checksum ON slave_transaction_retries 10 slave_transaction_retry_errors 1213,1205 slave_transaction_retry_interval 0 slave_type_conversions slow_launch_time 2 slow_query_log OFF slow_query_log_file engr-dbmsc-200-eos-ncsu-edu-slow.log socket /var/lib/mysql/mysql.sock sort_buffer_size 2097152 sql_auto_is_null OFF sql_big_selects ON sql_buffer_result OFF sql_log_bin ON sql_log_off OFF sql_mode STRICT_TRANS_TABLES,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION sql_notes ON sql_quote_show_create ON sql_safe_updates OFF sql_select_limit 18446744073709551615 sql_slave_skip_counter 0 sql_warnings OFF ssl_ca ssl_capath ssl_cert ssl_cipher ssl_crl ssl_crlpath ssl_key standard_compliant_cte ON storage_engine InnoDB stored_program_cache 256 strict_password_validation ON sync_binlog 1 sync_frm ON sync_master_info 10000 sync_relay_log 10000 sync_relay_log_info 10000 system_time_zone EDT system_versioning_alter_history ERROR system_versioning_asof DEFAULT table_definition_cache 400 table_open_cache 2000 table_open_cache_instances 8 tcp_keepalive_interval 0 tcp_keepalive_probes 0 tcp_keepalive_time 0 thread_cache_size 8 thread_concurrency 10 thread_handling one-thread-per-connection thread_pool_idle_timeout 60 thread_pool_max_threads 65536 thread_pool_oversubscribe 3 thread_pool_prio_kickup_timer 1000 thread_pool_priority auto thread_pool_size 2 thread_pool_stall_limit 500 thread_stack 262144 time_format %H:%i:%s time_zone SYSTEM timed_mutexes OFF tmp_disk_table_size 18446744073709551615 tmp_memory_table_size 16777216 tmp_table_size 16777216 tmpdir /tmp transaction_alloc_block_size 8192 transaction_prealloc_size 4096 tx_isolation REPEATABLE-READ tx_read_only OFF unique_checks ON updatable_views_with_limit YES use_stat_tables NEVER userstat OFF version 10.3.13-MariaDB-log version_comment MariaDB Server version_compile_machine x86_64 version_compile_os Linux version_malloc_library system version_source_revision c8f9b3f915a729ec35c00e92cc534a01271aa6e6 version_ssl_library OpenSSL 1.0.1e-fips 11 Feb 2013 wait_timeout 28800 wsrep_osu_method TOI wsrep_auto_increment_control ON wsrep_causal_reads OFF wsrep_certification_rules strict wsrep_certify_nonpk ON wsrep_cluster_address wsrep_cluster_name my_wsrep_cluster wsrep_convert_lock_to_trx OFF wsrep_data_home_dir /var/lib/mysql/ wsrep_dbug_option wsrep_debug OFF wsrep_desync OFF wsrep_dirty_reads OFF wsrep_drupal_282555_workaround OFF wsrep_forced_binlog_format NONE wsrep_gtid_domain_id 0 wsrep_gtid_mode OFF wsrep_load_data_splitting ON wsrep_log_conflicts OFF wsrep_max_ws_rows 0 wsrep_max_ws_size 2147483647 wsrep_mysql_replication_bundle 0 wsrep_node_address wsrep_node_incoming_address AUTO wsrep_node_name engr-dbmsc-200.eos.ncsu.edu wsrep_notify_cmd wsrep_on OFF wsrep_patch_version wsrep_25.24 wsrep_provider none wsrep_provider_options wsrep_recover OFF wsrep_reject_queries NONE wsrep_replicate_myisam OFF wsrep_restart_slave OFF wsrep_retry_autocommit 1 wsrep_slave_fk_checks ON wsrep_slave_uk_checks OFF wsrep_slave_threads 1 wsrep_sst_auth wsrep_sst_donor wsrep_sst_donor_rejects_queries OFF wsrep_sst_method rsync wsrep_sst_receive_address AUTO wsrep_start_position 00000000-0000-0000-0000-000000000000:-1 wsrep_sync_wait 0 ```


svaroqui commented 5 years ago

I guess this issue is happening because of virtualization with only 2 cores

For MariaDB can you please increase

open_files_limit=65000 table_open_cache=15000 innodb_open_files=15000 table_definition_cache =15000 query_cache_size=0 thread_handling = pool-of-threads extra_port = 3307 extra_max_connections = 10

And for repman monitoring-ticker=10

0x6d617474 commented 5 years ago

I've made the requested changes, omitting the extra port for now because it requires additional configuration changes in our environment (network level firewalls, etc).

I'll see if the issue re-appears as it usually does in a few hours.

0x6d617474 commented 5 years ago

One of the replicas has hit the issue again, after making the changes requested.

0x6d617474 commented 5 years ago

I started hacking on the code, and found the cause of this issue. I submitted a patch with more details here: https://github.com/signal18/replication-manager/pull/275

tanji commented 5 years ago

Great find! I assume we rarely run with PFS in production so that bug was tricky and hard to find out. I'll do the merge for you ASAP.

svaroqui commented 5 years ago

That's strange i have PFS on some of our clusters , good job !

tanji commented 5 years ago

Next build should be available through CI in a few minutes