The audit log plugin uses too much memory

[monty solomon]

+---------------------------+---------------+
| code_area | current_alloc |
+---------------------------+---------------+
| memory/audit_log | 9.58 GiB |
| memory/innodb | 5.49 GiB |
| memory/sql | 266.00 MiB |
| memory/performance_schema | 148.88 MiB |
| memory/mysys | 74.70 MiB |
| memory/memory | 1.18 MiB |
| memory/myisam | 903.17 KiB |
| memory/csv | 18.14 KiB |
| memory/blackhole | 512 bytes |
| memory/vio | 8 bytes |
+---------------------------+---------------+
10 rows in set (0.01 sec)

mysql Ver 14.14 Distrib 5.7.14-7, for Linux (x86_64) using 6.0
Server version: 5.7.14-7-log Percona Server (GPL), Release 7, Revision 083e298
CentOS 6.7

[monty solomon (monty+launchpad)]

loose-audit-log = ON
loose-audit_log_file = /opt/mysql/dblogs1/monty-q0/audit/audit.log
loose-audit_log_format = JSON
loose-audit_log_handler = FILE
loose-audit_log_strategy = SEMISYNCHRONOUS
loose-audit_log_syslog_facility = LOG_LOCAL6
loose-audit_log_syslog_ident = mysql-audit

[monty solomon (monty+launchpad)]

mysql repeatedly gets killed by the oom-killer

Mon Sep 5 00:53:44 UTC 2016
Uptime: 45 min 30 sec

Sep 4 07:45:32 weathered-snowflake kernel: [2981186.731734] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0

Sep 4 15:42:46 weathered-snowflake kernel: [3009819.721854] mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0

Sep 4 18:27:34 weathered-snowflake kernel: [3019708.488066] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0

Sep 4 21:23:23 weathered-snowflake kernel: [3030256.995903] mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0

Sep 5 00:07:55 weathered-snowflake kernel: [3040129.850837] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0

[monty solomon (monty+launchpad)]

The crashes continue

Sep 5 00:07:55 weathered-snowflake kernel: [3040129.850837] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0
Sep 5 02:47:39 weathered-snowflake kernel: [3049714.056179] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0
Sep 5 05:31:09 weathered-snowflake kernel: [3059522.265078] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0

+---------------------------+---------------+
| code_area | current_alloc |
+---------------------------+---------------+
| memory/audit_log | 13.54 GiB |
| memory/innodb | 5.49 GiB |
| memory/sql | 265.75 MiB |
| memory/performance_schema | 148.63 MiB |
| memory/mysys | 84.85 MiB |
| memory/memory | 1.18 MiB |
| memory/myisam | 1.02 MiB |
| memory/csv | 18.14 KiB |
| memory/blackhole | 512 bytes |
| memory/vio | 8 bytes |
+---------------------------+---------------+
10 rows in set (0.03 sec)

[monty solomon (monty+launchpad)]

Sep 5 08:17:39 weathered-snowflake kernel: [3069513.524780] mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Sep 5 11:02:49 weathered-snowflake kernel: [3079422.981674] mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Sep 5 13:43:25 weathered-snowflake kernel: [3089058.364803] mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Sep 5 16:19:00 weathered-snowflake kernel: [3098394.203299] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0
Sep 5 21:48:28 weathered-snowflake kernel: [3118161.781780] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0
Sep 6 00:33:44 weathered-snowflake kernel: [3128077.932085] mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0

[Sergei Glushchenko (sergei.glushchenko)]

Looks like thd_local never gets released

mysql> SELECT event_name, sys.format_bytes(SUM(current_alloc)) AS current_alloc FROM sys.x$memory_global_by_current_bytes WHERE event_name like "%audit%" GROUP BY event_name ORDER BY SUM(current_alloc) DESC;
+------------------------------------------+---------------+
| event_name | current_alloc |
+------------------------------------------+---------------+
| memory/audit_log/audit_log_thd_local | 932.47 KiB |
| memory/audit_log/audit_log_query_stack | 211.12 KiB |
| memory/audit_log/audit_log_logger_handle | 712 bytes |
| memory/audit_log/audit_log_commands | 640 bytes |
| memory/audit_log/audit_log_databases | 640 bytes |
| memory/audit_log/audit_log_accounts | 640 bytes |
| memory/audit_log/audit_log_handler | 88 bytes |
+------------------------------------------+---------------+
7 rows in set (0.01 sec)

and few minutes later

mysql> SELECT event_name, sys.format_bytes(SUM(current_alloc)) AS current_alloc FROM sys.x$memory_global_by_current_bytes WHERE event_name like "%audit%" GROUP BY event_name ORDER BY SUM(current_alloc) DESC;
+------------------------------------------+---------------+
| event_name | current_alloc |
+------------------------------------------+---------------+
| memory/audit_log/audit_log_thd_local | 2.45 MiB |
| memory/audit_log/audit_log_query_stack | 567.84 KiB |
| memory/audit_log/audit_log_logger_handle | 712 bytes |
| memory/audit_log/audit_log_commands | 640 bytes |
| memory/audit_log/audit_log_databases | 640 bytes |
| memory/audit_log/audit_log_accounts | 640 bytes |
| memory/audit_log/audit_log_handler | 88 bytes |
+------------------------------------------+---------------+
7 rows in set (0.01 sec)

dynamic_variables_allocs is NULL:

* thread #26: tid = 0x2d4922, 0x000000010a5c50c3 mysqld`plugin_var_memalloc_free(vars=0x00007f87721509e0) + 35 at sql_plugin.cc:3322, stop reason = breakpoint 2.1
    frame #0: 0x000000010a5c50c3 mysqld`plugin_var_memalloc_free(vars=0x00007f87721509e0) + 35 at sql_plugin.cc:3322
   3319 static void plugin_var_memalloc_free(struct system_variables *vars)
   3320 {
   3321 LIST *next, *root;
-> 3322 DBUG_ENTER("plugin_var_memalloc_free");
   3323 for (root= vars->dynamic_variables_allocs; root; root= next)
   3324 {
   3325 next= root->next;
(lldb) p vars->dynamic_variables_allocs
(LIST *) $0 = 0x0000000000000000

variables added to that list in `plugin_var_memalloc_session_update` if `value` is not NULL, but it is NULL... looking further

* thread #26: tid = 0x2d4922, 0x000000010a5c32c3 mysqld`plugin_var_memalloc_session_update(thd=0x00007f87718a1c00, var=0x0000000000000000, dest=0x00007f87734b8580, value=0x0000000000000000) + 51 at sql_plugin.cc:3276, stop reason = breakpoint 3.1
    frame #0: 0x000000010a5c32c3 mysqld`plugin_var_memalloc_session_update(thd=0x00007f87718a1c00, var=0x0000000000000000, dest=0x00007f87734b8580, value=0x0000000000000000) + 51 at sql_plugin.cc:3276
   3273 char **dest, const char *...

[monty solomon (monty+launchpad)]

The audit_log caused mysqld to crash today

/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xec6b8c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x79dba1]
/lib64/libpthread.so.0[0x3e9360f7e0]
/usr/lib64/mysql/plugin/audit_log.so(+0x4de0)[0x7f7a64079de0]
/usr/lib64/mysql/plugin/audit_log.so(+0x67b5)[0x7f7a6407b7b5]
/usr/lib64/mysql/plugin/audit_log.so(+0x695f)[0x7f7a6407b95f]
/usr/sbin/mysqld[0x79dd93]
/usr/sbin/mysqld(_Z18mysql_audit_notifyP3THD30mysql_event_general_subclass_tiPKcm+0x1f4)[0x79e314]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x3ae)[0xcac2ee]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b7)[0xcae207]
/usr/sbin/mysqld(handle_connection+0x2a0)[0xd6fd00]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0xede504]
/lib64/libpthread.so.0[0x3e93607aa1]
/lib64/libc.so.6(clone+0x6d)[0x3e932e893d]
2016-09-07T09:46:01.917002Z mysqld_safe Number of processes running now: 0
2016-09-07T09:46:01.918718Z mysqld_safe mysqld restarted

[monty solomon (monty+launchpad)]

The crash was on a different server. It appears that the audit log is unreliable on PS 5.7.14.

mysql Ver 14.14 Distrib 5.7.14-7, for Linux (x86_64) using 6.0
Server version: 5.7.14-7-log Percona Server (GPL), Release 7, Revision 083e298

[Sergei Glushchenko (sergei.glushchenko)]

https://github.com/percona/percona-server/pull/1023
https://github.com/percona/percona-server/pull/1024

[monty solomon (monty+launchpad)]

We are seeing audit log memory issues on 5.7.13. Will the patches/fixes address those too?

+---------------------------+---------------+
| code_area | current_alloc |
+---------------------------+---------------+
| memory/innodb | 22.82 GiB |
| memory/audit_logger | 7.66 GiB |
| memory/sql | 273.05 MiB |
| memory/performance_schema | 194.65 MiB |
| memory/mysys | 182.13 MiB |
| memory/myisam | 1.23 MiB |
| memory/memory | 1.18 MiB |
| memory/csv | 130.14 KiB |
| memory/blackhole | 512 bytes |
| memory/vio | 8 bytes |
+---------------------------+---------------+

[monty solomon (monty+launchpad)]

+---------------------------+---------------+
| code_area | current_alloc |
+---------------------------+---------------+
| memory/audit_logger | 11.40 GiB |
| memory/performance_schema | 259.18 MiB |
| memory/mysys | 188.96 MiB |
| memory/innodb | 103.92 MiB |
| memory/memory | 53.03 MiB |
| memory/sql | 24.28 MiB |
| memory/myisam | 71.35 KiB |
| memory/csv | 8.00 KiB |
+---------------------------+---------------+

[monty solomon (monty+launchpad)]

+---------------------------+---------------+
| code_area | current_alloc |
+---------------------------+---------------+
| memory/innodb | 26.19 GiB |
| memory/audit_logger | 4.73 GiB |
| memory/mysys | 432.07 MiB |
| memory/sql | 287.04 MiB |
| memory/performance_schema | 239.69 MiB |
| memory/myisam | 1.30 MiB |
| memory/csv | 130.14 KiB |
| memory/memory | 3.06 KiB |
| memory/vio | 1.98 KiB |
| memory/blackhole | 512 bytes |
+---------------------------+---------------+

[monty solomon (monty+launchpad)]

+---------------------------+---------------+
| code_area | current_alloc |
+---------------------------+---------------+
| memory/innodb | 26.18 GiB |
| memory/audit_logger | 11.25 GiB |
| memory/sql | 854.70 MiB |
| memory/mysys | 554.02 MiB |
| memory/performance_schema | 220.19 MiB |
| memory/myisam | 1.25 MiB |
| memory/memory | 1.18 MiB |
| memory/csv | 130.14 KiB |
| memory/vio | 40.86 KiB |
| memory/blackhole | 512 bytes |
+---------------------------+---------------+

[Sergei Glushchenko (sergei.glushchenko)]

Yes, it has the same underlying reason.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1004