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

Huge memory usage for audit plugin when large queries are executed.

    Details

      Description

      When audit_plugin is enabled MySQL uses a lot of memory when handling large queries.

      Steps to reproduce:

      1. Install audit plugin
      mysql> INSTALL PLUGIN audit_log SONAME 'audit_log.so';
      1. Test-case:
      $ for i in $(seq 1 $((1*1024*1024))); do echo -ne "a" >> blob_part; done;
      $ for i in {1..10}; do cat blob_part >> blob; done;
      $ cat test.sh
      mysql -e "truncate test.test;"
      
      for i in $(seq 1 10); do
       echo $i > /dev/stderr echo $i > /dev/stderr
       echo "insert into test (col04, col08, col07, col03, col06, col05, col02, col01, col10, col09) values ('application/json', null, '2018-12-31 13:16:55.762', '53fdbe8f03cb490284c30ee146693ce2', null, '$(cat blob)', 'application/json', $i, now(), now());"    
      sleep 1;
      
      done  | mysql test
      1. Create schema:
      CREATE TABLE `test` (
        `id` bigint(15) NOT NULL AUTO_INCREMENT,
        `col01` varchar(40) NOT NULL,
        `col02` varchar(100) NOT NULL,
        `col03` varchar(150) NOT NULL,
        `col04` varchar(150) DEFAULT NULL,
        `col05` longblob NOT NULL,
        `col06` varchar(255) DEFAULT NULL,
        `col07` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
        `col08` varchar(40) DEFAULT NULL,
        `col09` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
        `col10` varchar(40) DEFAULT NULL,
        PRIMARY KEY (`id`),
        UNIQUE KEY `col05_cache_idx1` (`col01`,`col02`,`col03`),
        KEY `col05_cache_date_idx` (`col09`)
      ) ENGINE=InnoDB AUTO_INCREMENT=21 DEFAULT CHARSET=latin1  
      1.  Memory usage when audit plugin is not enabled:
        Linux 4.9.0-8-amd64 (test) 	01.02.2019 	_x86_64_	(1 CPU)
        
        11:27:57      UID       PID  minflt/s  majflt/s     VSZ     RSS   %MEM  Command
        11:27:58      108     11140      0,00      0,00 1253856  181476   5,88  mysqld
        11:27:59      108     11140      0,00      0,00 1253856  181476   5,88  mysqld
        11:28:00      108     11140      0,00      0,00 1253856  181476   5,88  mysqld
        11:28:01      108     11140  26576,81      0,00 1254376  254116   8,24  mysqld
        11:28:02      108     11140   6504,41      0,00 1254376  230068   7,46  mysqld
        11:28:03      108     11140  19044,59      0,00 1254376  244520   7,93  mysqld
        11:28:04      108     11140  12727,69      0,00 1254376  277516   9,00  mysqld
        11:28:05      108     11140   2353,95      0,00 1254376  284644   9,23  mysqld
        11:28:06      108     11140   9066,29      0,00 1254376  275136   8,92  mysqld
        11:28:07      108     11140   5338,71      0,00 1254376  294936   9,56  mysqld
        11:28:08      108     11140  22476,00      0,00 1254376  278692   9,03  mysqld
        11:28:09      108     11140  13301,67      0,00 1254376  310368  10,06  mysqld
        11:28:10      108     11140   6748,00      0,00 1254376  330856  10,73  mysqld
        11:28:11      108     11140      0,00      0,00 1254376  330856  10,73  mysqld
        11:28:12      108     11140  15165,12      0,00 1254376  299268   9,70  mysqld
        11:28:13      108     11140  12316,67      0,00 1254376  322760  10,46  mysqld
        11:28:14      108     11140  13452,83      0,00 1254376  309556  10,04  mysqld
        11:28:15      108     11140  16508,86      0,00 1254376  361720  11,73  mysqld
        11:28:16      108     11140      0,00      0,00 1254376  319844  10,37  mysqld
        11:28:17      108     11140  11090,00      0,00 1254376  359704  11,66  mysqld
        11:28:18      108     11140   3601,18      0,00 1254376  330132  10,70  mysqld
        11:28:19      108     11140      0,00      0,00 1254376  330132  10,70  mysqld
        11:28:20      108     11140      0,00      0,00 1254376  330132  10,70  mysqld
        11:28:21      108     11140      0,00      0,00 1254376  330132  10,70  mysqld
        11:28:22      108     11140      0,00      0,00 1254376  330132  10,70  mysqld
        11:28:23      108     11140    678,85      0,00 1254376  331440  10,74  mysqld
        11:28:24      108     11140  13424,36      0,00 1254376  331444  10,74  mysqld
        11:28:25      108     11140  18368,42      0,00 1254376  373320  12,10  mysqld
        11:28:26      108     11140      0,00      0,00 1254376  331444  10,74  mysqld
        11:28:27      108     11140  13405,08      0,00 1254376  362856  11,76  mysqld
        11:28:28      108     11140   3607,04      0,00 1254376  373320  12,10  mysqld
        11:28:29      108     11140  14541,67      0,00 1254376  331444  10,74  mysqld
        11:28:30      108     11140    600,00      0,00 1254376  332496  10,78  mysqld
        11:28:31      108     11140  15909,38      0,00 1254376  331444  10,74  mysqld
        11:28:32      108     11140  11804,48      0,00 1254376  362856  11,76  mysqld
        11:28:33      108     11140   3123,17      0,00 1254376  373320  12,10  mysqld
        11:28:34      108     11140   9090,80      0,00 1254376  362856  11,76  mysqld
        11:28:35      108     11140   3048,81      0,00 1254376  331444  10,74  mysqld
        11:28:36      108     11140  11505,49      0,00 1254376  373320  12,10  mysqld
        11:28:37      108     11140   8691,21      0,00 1254376  362856  11,76  mysqld
        11:28:38      108     11140  14342,47      0,00 1254376  362856  11,76  mysqld
        11:28:39      108     11140   2671,88      0,00 1254376  331460  10,75  mysqld
        11:28:40      108     11140      0,00      0,00 1254376  331460  10,75  mysqld
        11:28:41      108     11140      0,00      0,00 1254376  331460  10,75  mysqld
        
      1. Memory usage when the audit plugin is enabled
        Linux 4.9.0-8-amd64 (test) 	01.02.2019 	_x86_64_	(1 CPU)
        
        11:25:50      UID       PID  minflt/s  majflt/s     VSZ     RSS   %MEM  Command
        11:25:51      108      7390      0,00      0,00 1256752  319620  10,36  mysqld
        11:25:52      108      7390      2,67      0,00 1256752  319620  10,36  mysqld
        11:25:53      108      7390  19500,00      0,00 1322288  370888  12,02  mysqld
        11:25:54      108      7390 339222,58      0,00 1666368  780396  25,30  mysqld
        11:25:55      108      7390   9046,77      0,00 1666368  780396  25,30  mysqld
        11:25:56      108      7390      0,00      0,00 1666368  780396  25,30  mysqld
        11:25:57      108      7390   1060,87      0,00 1731904  781336  25,33  mysqld
        11:25:58      108      7390   7212,68      0,00 1666368  780396  25,30  mysqld
        11:25:59      108      7390    542,22      0,00 1731904  781336  25,33  mysqld
        11:26:00      108      7390  12056,18      0,00 1666368  780396  25,30  mysqld
        11:26:01      108      7390      0,00      0,00 1666368  780396  25,30  mysqld
        11:26:02      108      7390    278,72      0,00 1731904  780540  25,30  mysqld
        11:26:03      108      7390    262,79      0,00 1731904  781336  25,33  mysqld
        11:26:04      108      7390  13756,41      0,00 1666368  780396  25,30  mysqld
        11:26:05      108      7390      0,00      0,00 1666368  780396  25,30  mysqld
        11:26:06      108      7390      0,00      0,00 1666368  780396  25,30  mysqld
        11:26:07      108      7390      0,00      0,00 1666368  780396  25,30  mysqld
        11:26:08      108      7390    697,14      0,00 1731904  781336  25,33  mysqld
        11:26:09      108      7390   6828,00      0,00 1666368  780396  25,30  mysqld
        11:26:10      108      7390    436,67      0,00 1731904  780540  25,30  mysqld
        11:26:11      108      7390   6290,59      0,00 1666368  780396  25,30  mysqld
        11:26:12      108      7390      0,00      0,00 1666368  780396  25,30  mysqld
        11:26:13      108      7390   7191,03      0,00 1666368  780396  25,30  mysqld
        11:26:14      108      7390      0,00      0,00 1666368  780396  25,30  mysqld
        11:26:15      108      7390      0,00      0,00 1256752  319668  10,36  mysqld
        11:26:16      108      7390      0,00      0,00 1256752  319668  10,36  mysqld
        11:26:17      108      7390      0,00      0,00 1256752  319668  10,36  mysqld
        
        

        Smart Checklist

          Attachments

            Activity

              People

              • Assignee:
                sergei.glushchenko Sergei Glushchenko
                Reporter:
                iwo.panowicz Iwo Panowicz
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 3 hours, 25 minutes
                  3h 25m