Details
High Description
This looks very similar to PS-6939 and PS-6000 (customer is precisely on Percona server 5.7.26 where PS-6000 should not happen). I can very easily reproduce with a PS 5.7.29 sandbox set in replication:
Master my.cnf
[mysql] prompt='master [\h:29410] {\u} (\d) > ' # [client] user = msandbox password = msandbox port = 29410 socket = /tmp/mysql_sandbox29410.sock [mysqld] user = marcos.albe port = 29410 socket = /tmp/mysql_sandbox29410.sock basedir = /opt/percona_server/5.7.29 datadir = /home/marcos.albe/sandboxes/rsandbox_5_7_29/master/data tmpdir = /home/marcos.albe/sandboxes/rsandbox_5_7_29/master/tmp pid-file = /home/marcos.albe/sandboxes/rsandbox_5_7_29/master/data/mysql_sandbox29410.pid bind-address = 127.0.0.1 report-host = node-1 report-port=29410 log-error=/home/marcos.albe/sandboxes/rsandbox_5_7_29/master/data/msandbox.err server-id=100 # basic replication options relay-log-index=mysql-relay relay-log=mysql-relay log-bin=mysql-bin binlog-format=STATEMENT plugin-load = "audit_log=audit_log.so" audit_log_rotate_on_size = 200M audit_log_rotations = 5 audit_log_handler = FILE audit_log_format = "csv" audit_log_exclude_accounts = '[email protected]%.wd,[email protected]%.wd,[email protected]%.wd,`system user`,[email protected]'
Replica cnf:
[mysql] prompt='slave1 [\h:29411] {\u} (\d) > ' # [client] user = msandbox password = msandbox port = 29411 socket = /tmp/mysql_sandbox29411.sock [mysqld] user = marcos.albe port = 29411 socket = /tmp/mysql_sandbox29411.sock basedir = /opt/percona_server/5.7.29 datadir = /home/marcos.albe/sandboxes/rsandbox_5_7_29/node1/data tmpdir = /home/marcos.albe/sandboxes/rsandbox_5_7_29/node1/tmp pid-file = /home/marcos.albe/sandboxes/rsandbox_5_7_29/node1/data/mysql_sandbox29411.pid bind-address = 127.0.0.1 report-host = node-2 report-port=29411 log-error=/home/marcos.albe/sandboxes/rsandbox_5_7_29/node1/data/msandbox.err server-id=200 # basic replication options relay-log-index=mysql-relay relay-log=mysql-relay log-bin=mysql-bin plugin-load = "audit_log=audit_log.so" audit_log_rotate_on_size = 200M audit_log_rotations = 5 audit_log_handler = FILE audit_log_format = "csv" audit_log_exclude_accounts = '[email protected]%.wd,[email protected]%.wd,[email protected]%.wd,`system user`,[email protected]'
So, with the audit plugin working, setup this simple RSS watch on both master and replica
#!/bin/bash # Thanks Daniel Nichter! # I like this snippet better than mine :D set -eu pid=$1 rss=$(ps -orss -p $pid | tail -n 1) run=0 echo "ts,current,diff,running_total" echo "$( date -u +'%Y-%m-%d %T'),$rss,0,0" while true; do sleep 5 rss2=$(ps -orss -p $pid | tail -n 1) [[ -z "$rss2" ]] && exit 0 diff=$((rss2 - rss)) run=$((run + diff)) echo "$( date -u +'%Y-%m-%d %T'),$rss2,$diff,$run" rss=$rss2 done
Then simply run the following queries:
SELECT NOW(); CREATE TABLE bad (i INT NOT NULL AUTO_INCREMENT PRIMARY KEY, b LONGTEXT); INSERT INTO bad VALUES (NULL, REPEAT('X',512*1024*1024)); SELECT NOW(); CREATE TABLE verybad LIKE bad; INSERT INTO verybad VALUES (NULL, REPEAT('X',1024*1024*1024)); SELECT NOW();
You should get something like:
master [localhost:29410] {msandbox} (test) > \s
--------------
/opt/percona_server/5.7.29/bin/mysql Ver 14.14 Distrib 5.7.29-32, for Linux (x86_64) using 6.2
Connection id: 9
Current database: test
Current user: [email protected]
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server version: 5.7.29-32-log Percona Server (GPL), Release 32, Revision 56bce88
Protocol version: 10
Connection: Localhost via UNIX socket
Server characterset: latin1
Db characterset: latin1
Client characterset: utf8
Conn. characterset: utf8
UNIX socket: /tmp/mysql_sandbox29410.sock
Uptime: 1 hour 49 min 44 sec
Threads: 2 Questions: 145 Slow queries: 0 Opens: 126 Flush tables: 9 Open tables: 0 Queries per second avg: 0.022
master [localhost:29410] {msandbox} (test) > CREATE TABLE bad (i INT NOT NULL AUTO_INCREMENT PRIMARY KEY, b LONGTEXT);
Query OK, 0 rows affected (0.05 sec)
master [localhost:29410] {msandbox} (test) > SELECT NOW();
+---------------------+
| NOW() |
+---------------------+
| 2020-07-21 20:27:21 |
+---------------------+
1 row in set (0.00 sec)
master [localhost:29410] {msandbox} (test) > INSERT INTO bad VALUES (NULL, REPEAT('X',512*1024*1024));
Query OK, 1 row affected (24.09 sec)
master [localhost:29410] {msandbox} (test) > SELECT NOW();
+---------------------+
| NOW() |
+---------------------+
| 2020-07-21 20:27:45 |
+---------------------+
1 row in set (0.00 sec)
And the RSS monitors in my case showed, on the master:
./rssmon.sh $(cat data/*pid); ts,current,diff,running_total 2020-07-22 00:21:02,296588,0,0 ... 2020-07-22 00:27:11,298500,0,1912 2020-07-22 00:27:16,298500,0,1912 2020-07-22 00:27:21,298500,0,1912 2020-07-22 00:27:26,954460,655960,657872 2020-07-22 00:27:31,1347448,392988,1050860 2020-07-22 00:27:36,1347480,32,1050892 2020-07-22 00:27:41,1347548,68,1050960 2020-07-22 00:27:47,823224,-524324,526636 2020-07-22 00:27:52,823264,40,526676 2020-07-22 00:27:57,823264,0,526676 2020-07-22 00:28:02,821648,-1616,525060 2020-07-22 00:28:10,821316,-332,524728 2020-07-22 00:28:16,821316,0,524728 2020-07-22 00:28:21,821316,0,524728 2020-07-22 00:28:26,821316,0,524728 2020-07-22 00:28:31,821316,0,524728 2020-07-22 00:28:36,821316,0,524728 ^C
And in the replica:
./rssmon.sh $(cat data/*pid) ts,current,diff,running_total 2020-07-22 00:27:16,298280,0,8908 2020-07-22 00:27:21,298280,0,8908 2020-07-22 00:27:26,298280,0,8908 2020-07-22 00:27:31,298280,0,8908 2020-07-22 00:27:36,298600,320,9228 2020-07-22 00:27:41,298608,8,9236 2020-07-22 00:27:46,463180,164572,173808 2020-07-22 00:27:52,837524,374344,548152 2020-07-22 00:27:57,822924,-14600,533552 2020-07-22 00:28:02,2394508,1571584,2105136 2020-07-22 00:28:10,2393980,-528,2104608 2020-07-22 00:28:16,2393980,0,2104608 2020-07-22 00:28:21,821680,-1572300,532308 2020-07-22 00:28:26,821680,0,532308 2020-07-22 00:28:31,821680,0,532308 2020-07-22 00:28:36,821680,0,532308 2020-07-22 00:28:42,821680,0,532308 ^C
We can bn certain that is not the buffer pool, as it's well beyond the size:
master [localhost:29410] {msandbox} ((none)) > select @@global.innodb_buffer_pool_size/1024/1024;
+--------------------------------------------+
| @@global.innodb_buffer_pool_size/1024/1024 |
+--------------------------------------------+
| 128.00000000 |
+--------------------------------------------+
1 row in set (0.00 sec)
And we have high-degree of certain regarding the fact that is the audit plugin because:
1) Customer got the following on one of the writers:
2020-07-18T06:54:40.817006Z 45063883 [Warning] Event 'MYSQL_AUDIT_GENERAL_STATUS' cannot be aborted. The trigger error was (5) [HY000]: Out of memory (Needed 1203477327 bytes) 2020-07-18T06:54:40.827321Z 45063883 [ERROR] /usr/local/mysql/bin/mysqld: Out of memory (Needed 1203477327 bytes) 2020-07-18T06:54:40.817035Z 45067404 [Warning] Event 'MYSQL_AUDIT_GENERAL_STATUS' cannot be aborted. The trigger error was (5) [HY000]: Out of memory (Needed 1204699173 bytes) 2020-07-18T06:54:40.827358Z 45067404 [ERROR] /usr/local/mysql/bin/mysqld: Out of memory (Needed 1204699173 bytes) 06:54:40 UTC - mysqld got signal 11 ;
So it was allocating all that memory (We are still working to find the statement)
2) We did perf record -e 'faults' during the time of the event and it shows clearly that the stack producing the most page faults is that related to audit_log_nofity (see attached).
3) UNINSTALL PLUGIN audit_log; immediately resulted in all memory being released.
Observations:
- Sometimes repeating one of those large INSERTs on same table will not make RSS grow any more. But creating identical table with different name and INSERT'ing there does repeat the problem.
- Stopping the replication SQL thread clears most of the memory on replica (consistently)
- FLUSH TABLES appears to clear most memory on master (erratically)
Question:
No way to skip this particular plugin hook when it's being run within a replica thread? The plugin will dispose the event anyway as it does not logs replication event (And the documentation does not state what should be the behavior. Is more clear for ROW, but for STATEMENT...?)
In the master's audit log we see, for example:
"Query","13773_2020-07-21T23:10:35","2020-07-22T00:45:19 UTC","insert","9",0,"INSERT INTO yay VALUES (NULL, REPEAT('X',840*1024*1024))","msandbox[msandbox] @ localhost []","localhost","","",""
# Memory mamagement ########################################## Transparent huge pages are currently disabled on the system. # The End ####################################################
