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:
None 
Category:MySQL Utilities: Binlog Events Severity:S2 (Serious)
Version:5.6,5.7 OS:Any
Assigned to: CPU Architecture:Any

[12 Feb 2015 17:04] zhai weixiang
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);
[12 Feb 2015 19:07] Shane Bester
Thanks for the report!   Requires --log-bin --server-id=2 to repeat.
[12 Feb 2015 19:11] Shane Bester
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.