The audit log plugin uses too much memory

Bug #1620152 reported by monty solomon
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
Invalid
Undecided
Unassigned
5.6
Fix Released
High
Sergei Glushchenko
5.7
Fix Released
High
Sergei Glushchenko

Bug Description

+---------------------------+---------------+
| 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

Revision history for this message
monty solomon (monty+launchpad) wrote :

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

Revision history for this message
monty solomon (monty+launchpad) wrote :

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

summary: - The audit_log uses too much memory
+ The audit_log plugin uses too much memory
summary: - The audit_log plugin uses too much memory
+ The audit log plugin uses too much memory
tags: added: audit
Revision history for this message
monty solomon (monty+launchpad) wrote :

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)

Revision history for this message
monty solomon (monty+launchpad) wrote :

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

Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
Download full text (3.3 KiB)

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 *...

Read more...

Revision history for this message
monty solomon (monty+launchpad) wrote :

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

Revision history for this message
monty solomon (monty+launchpad) wrote :

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

Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :
tags: added: upstream
Revision history for this message
monty solomon (monty+launchpad) wrote :

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 |
+---------------------------+---------------+

Revision history for this message
monty solomon (monty+launchpad) wrote :

+---------------------------+---------------+
| 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 |
+---------------------------+---------------+

Revision history for this message
monty solomon (monty+launchpad) wrote :

+---------------------------+---------------+
| 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 |
+---------------------------+---------------+

Revision history for this message
monty solomon (monty+launchpad) wrote :

+---------------------------+---------------+
| 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 |
+---------------------------+---------------+

Revision history for this message
Sergei Glushchenko (sergei.glushchenko) wrote :

Yes, it has the same underlying reason.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.