Uploaded image for project: 'Percona Server for MySQL'
  1. Percona Server for MySQL
  2. PS-7203

Fix audit plugin memory leak on replicas when opening tables

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Done
    • Priority: High
    • Resolution: Fixed
    • Affects Version/s: 5.7.26-29, 5.7.29-32
    • Fix Version/s: 5.7.31-34, 8.0.21-12
    • Component/s: None
    • Labels:
      None
    • Needs Review:
      Yes

      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 = 'wdadmin@%.wd,ptadmin@%.wd,wsadmin@%.wd,`system user`,rsandbox@localhost'
      

       

      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 = 'wdadmin@%.wd,ptadmin@%.wd,wsadmin@%.wd,`system user`,rsandbox@localhost'
      

      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: msandbox@localhost
      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 ####################################################

       

      2020-07-09_01-35-50-perf.data.script.svg

        Smart Checklist

          Attachments

            Activity

              People

              Assignee:
              marcelo.altmann Marcelo Altmann
              Reporter:
              marcos.albe Marcos Albe
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - Not Specified
                  Not Specified
                  Logged:
                  Time Spent - 3 days, 1 hour, 55 minutes
                  3d 1h 55m