| Bug #75879 | memory consumed quickly while executing loop in procedure | ||
|---|---|---|---|
| Submitted: | 12 Feb 2015 17:04 | Modified: | 27 Apr 2015 14:25 |
| Reporter: | zhai weixiang (OCA) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Utilities: Binlog Events | Severity: | S2 (Serious) |
| Version: | 5.6,5.7 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[12 Feb 2015 19:07]
MySQL Verification Team
Thanks for the report! Requires --log-bin --server-id=2 to repeat.
[12 Feb 2015 19:11]
MySQL Verification Team
can clearly see the set_trans_pos call gobbling up memory!
Attachment: bug75879_5.7.6_memory_profile.pdf (application/pdf, text), 14.45 KiB.
[13 Feb 2015 2:28]
zhang yingqiang
mark
[27 Apr 2015 14:25]
David Moss
Thanks for your feedback, this is fixed in upcoming versions and the following was added to the changelog: When binary logging was enabled, using stored functions and triggers resulting in a long running procedure that inserted many records caused the memory use to increase rapidly. This was due to memory being allocated per variable. The fix ensures that in such a situation, memory is allocated once and the same memory is reused.
[24 Jun 2015 4:00]
Laurynas Biveinis
commit 03c5ef5516a11cd6aafb33aaae5ae09b09f5a582
Author: Sujatha Sivakumar <sujatha.sivakumar@oracle.com>
Date: Tue Mar 31 16:21:08 2015 +0530
Bug#20531812: MEMORY CONSUMED QUICKLY WHILE EXECUTING LOOP
IN PROCEDURE
Problem:
========
With a long running procedure the thd::main_mem_root grows
very rapidly.
Analysis:
========
With binlog enabled, during commit of each instruction
set_trans_pos gets called which stores the current binary
log file name in a variable named "m_trans_fixed_log_file".
Memory for the variable is allocated from thd::main_mem_root
and it is set to NULL as part of THD::cleanup_after_query()
at the end of the instruction. The thd::main_mem_root also
gets freed at the end of the instruction. But a procedure
which inserts thousands of records, is in progrees, the
thd::main_mem_root will be getting cleared only at the end
of the procedure. But for each instruction within the
procedure, memory will be allocated from main_mem_root and
the m_trans_fixed_log_file will be set to NULL at the end
of each instruction. This causes the main_mem_root to grow
very rapidly as we keep on allocating 512 bytes from the
main_mem_root.
Fix:
===
At present in case of stored functions and triggers we will
not reset this variable to NULL. We allocate memory once and
the same memory is reused. Hence a similar fix has been
implemented as part of stored procedures as well. There is
flag named "sp_runtime_ctx". This flag is set to true when
the execution context refers to stored procedure, stored
functions, triggers and events. So now when this flag is set
we will not reset the "m_trans_fixed_log_file" to NULL. The
memory will be allocated once from the main_mem_root and it
will be reused. Hence no memory growth.
Description: Procedure: DELIMITER // CREATE PROCEDURE proc1() BEGIN DECLARE i int default 1; DECLARE j int default 1; WHILE(i < 100000000 ) DO SET j=100000000*rand(); insert into c(ming) values( j); SET i = i+1; END WHILE; END // DELIMITER ; call proc1() then observed memory/sql/thd::main_mem_root increased quickly root@performance_schema 12:51:29>select event_name, CURRENT_NUMBER_OF_BYTES_USED from memory_summary_global_by_event_name where event_name like '%mem%root%' order by CURRENT_NUMBER_OF_BYTES_USED desc limit 10; +----------------------------------------------+------------------------------+ | event_name | CURRENT_NUMBER_OF_BYTES_USED | +----------------------------------------------+------------------------------+ | memory/sql/thd::main_mem_root | 494112480 | | memory/sql/TABLE_SHARE::mem_root | 660104 | | memory/sql/sp_head::main_mem_root | 57168 | | memory/sql/plugin_mem_root | 44752 | | memory/sql/sp_head::execute_mem_root | 8160 | | memory/sql/plugin_int_mem_root | 4112 | | memory/sql/root | 144 | | memory/sql/Protocol_local::m_rset_root | 0 | | memory/sql/Prepared_statement::main_mem_root | 0 | | memory/sql/Delegate::memroot | 0 | +----------------------------------------------+------------------------------+ 10 rows in set (0.14 sec because thd::main_mem_root is freed after finishing the procedure. But it will call set_trans_pos to allocate memory from thd::main_mem_root every loop. After pathing (see suggested fix), everything works well. root@performance_schema 01:01:16>select event_name, CURRENT_NUMBER_OF_BYTES_USED from memory_summary_global_by_event_name where event_name like '%mem%root%' order by CURRENT_NUMBER_OF_BYTES_USED desc limit 10; +----------------------------------------------+------------------------------+ | event_name | CURRENT_NUMBER_OF_BYTES_USED | +----------------------------------------------+------------------------------+ | memory/sql/TABLE_SHARE::mem_root | 660104 | | memory/sql/sp_head::main_mem_root | 57168 | | memory/sql/plugin_mem_root | 44752 | | memory/sql/thd::main_mem_root | 16320 | | memory/sql/sp_head::execute_mem_root | 8160 | | memory/sql/plugin_int_mem_root | 4112 | | memory/sql/root | 144 | | memory/sql/Protocol_local::m_rset_root | 0 | | memory/sql/Prepared_statement::main_mem_root | 0 | | memory/sql/Delegate::memroot | 0 | +----------------------------------------------+------------------------------+ 10 rows in set (0.14 sec) How to repeat: described above Suggested fix: A simple patch to verify this bug report, not fully tested: Index: sql/sql_class.h =================================================================== --- sql/sql_class.h (revision 7133) +++ sql/sql_class.h (working copy) @@ -1990,8 +1990,8 @@ these positions instead of maintaining three different ones. */ /**@{*/ + char m_trans_fixed_log_file[FN_REFLEN+1]; const char *m_trans_log_file; - char *m_trans_fixed_log_file; my_off_t m_trans_end_pos; /**@}*/ @@ -2479,15 +2479,13 @@ DBUG_PRINT("enter", ("file: %s, pos: %llu", file, pos)); // Only the file name should be used, not the full path m_trans_log_file= file + dirname_length(file); - if (!m_trans_fixed_log_file) - m_trans_fixed_log_file= (char*) alloc_root(&main_mem_root, FN_REFLEN+1); DBUG_ASSERT(strlen(m_trans_log_file) <= FN_REFLEN); strcpy(m_trans_fixed_log_file, m_trans_log_file); } else { m_trans_log_file= NULL; - m_trans_fixed_log_file= NULL; + m_trans_fixed_log_file[0]= '\0'; } m_trans_end_pos= pos; Index: sql/sql_class.cc =================================================================== --- sql/sql_class.cc (revision 7133) +++ sql/sql_class.cc (working copy) @@ -1119,7 +1119,6 @@ binlog_table_maps(0), binlog_accessed_db_names(NULL), m_trans_log_file(NULL), - m_trans_fixed_log_file(NULL), m_trans_end_pos(0), m_transaction(new Transaction_ctx()), m_attachable_trx(NULL), @@ -1161,6 +1160,8 @@ &main_mem_root, global_system_variables.query_alloc_block_size, global_system_variables.query_prealloc_size); + + m_trans_fixed_log_file[0]='\0', stmt_arena= this; thread_stack= 0; m_catalog.str= "std"; @@ -2262,7 +2263,7 @@ auto_inc_intervals_in_cur_stmt_for_binlog.empty(); rand_used= 0; binlog_accessed_db_names= NULL; - m_trans_fixed_log_file= NULL; + m_trans_fixed_log_file[0]= '\0'; if (gtid_mode > 0) gtid_post_statement_checks(this); Index: sql/sql_parse.cc =================================================================== --- sql/sql_parse.cc (revision 7133) +++ sql/sql_parse.cc (working copy) @@ -5214,7 +5214,7 @@ thd->m_trans_end_pos= 0; thd->m_trans_log_file= NULL; - thd->m_trans_fixed_log_file= NULL; + thd->m_trans_fixed_log_file[0]= '\0'; thd->commit_error= THD::CE_NONE; thd->durability_property= HA_REGULAR_DURABILITY; thd->set_trans_pos(NULL, 0);