[MDEV-25050] Memory leak in create_file and dangling open files after failing SELECT INTO OUTFILE inside stored procedure Created: 2021-03-04  Updated: 2023-10-01

Status: Stalled
Project: MariaDB Server
Component/s: Server
Affects Version/s: 10.2, 10.3, 10.4, 10.5, 10.6
Fix Version/s: 10.4, 10.5

Type: Bug Priority: Critical
Reporter: Elena Stepanova Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: None


 Description   

Note: the test case is scalable and not limited to extremely low values of max_join_size, it just needs more data in the table for higher variable values.

--source include/have_sequence.inc
 
CREATE TABLE t (a INT);
INSERT INTO t SELECT seq FROM seq_1_to_100;
CREATE PROCEDURE sp() SELECT * INTO OUTFILE 'load_t' FROM t;
SET MAX_JOIN_SIZE= 20;
--error ER_TOO_BIG_SELECT
CALL sp;
 
# Cleanup
DROP PROCEDURE sp;
DROP TABLE t;
--let $datadir= `SELECT @@datadir`
--remove_file $datadir/test/load_t

10.2 676987c4 ASAN non-debug

Warning: Memory not freed: 131168
 
=================================================================
==799560==ERROR: LeakSanitizer: detected memory leaks
 
Direct leak of 131080 byte(s) in 1 object(s) allocated from:
    #0 0x7fe6e230cbc8 in malloc (/lib/x86_64-linux-gnu/libasan.so.5+0x10dbc8)
    #1 0x5607dc545786 in my_malloc /data/src/10.2/mysys/my_malloc.c:101
    #2 0x5607dc511293 in init_io_cache /data/src/10.2/mysys/mf_iocache.c:247
    #3 0x5607dadd3c35 in create_file /data/src/10.2/sql/sql_class.cc:2872
    #4 0x5607dade0bc9 in select_export::prepare(List<Item>&, st_select_lex_unit*) /data/src/10.2/sql/sql_class.cc:2894
    #5 0x5607dafaf57e in JOIN::prepare(TABLE_LIST*, unsigned int, Item*, unsigned int, st_order*, bool, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*) /data/src/10.2/sql/sql_select.cc:1053
    #6 0x5607dafec878 in mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /data/src/10.2/sql/sql_select.cc:3818
    #7 0x5607dafed622 in handle_select(THD*, LEX*, select_result*, unsigned long) /data/src/10.2/sql/sql_select.cc:361
    #8 0x5607dae7b78b in execute_sqlcom_select /data/src/10.2/sql/sql_parse.cc:6275
    #9 0x5607daea90ff in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:3586
    #10 0x5607dad0a578 in sp_instr_stmt::exec_core(THD*, unsigned int*) /data/src/10.2/sql/sp_head.cc:3332
    #11 0x5607dad242db in sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) /data/src/10.2/sql/sp_head.cc:3095
    #12 0x5607dad2553f in sp_instr_stmt::execute(THD*, unsigned int*) /data/src/10.2/sql/sp_head.cc:3248
    #13 0x5607dad146ec in sp_head::execute(THD*, bool) /data/src/10.2/sql/sp_head.cc:1326
    #14 0x5607dad18e40 in sp_head::execute_procedure(THD*, List<Item>*) /data/src/10.2/sql/sp_head.cc:2202
    #15 0x5607dae7af84 in do_execute_sp /data/src/10.2/sql/sql_parse.cc:2981
    #16 0x5607daea41b0 in mysql_execute_command(THD*) /data/src/10.2/sql/sql_parse.cc:5626
    #17 0x5607daeb2d4f in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.2/sql/sql_parse.cc:7790
    #18 0x5607daebc2db in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.2/sql/sql_parse.cc:1827
    #19 0x5607daec11b5 in do_command(THD*) /data/src/10.2/sql/sql_parse.cc:1381
    #20 0x5607db1c0ef6 in do_handle_one_connection(CONNECT*) /data/src/10.2/sql/sql_connect.cc:1336
    #21 0x5607db1c163e in handle_one_connection /data/src/10.2/sql/sql_connect.cc:1241
    #22 0x5607dc48cdf8 in pfs_spawn_thread /data/src/10.2/storage/perfschema/pfs.cc:1869
    #23 0x7fe6e1d41608 in start_thread /build/glibc-eX1tMB/glibc-2.31/nptl/pthread_create.c:477
 
SUMMARY: AddressSanitizer: 131080 byte(s) leaked in 1 allocation(s).
210304 15:25:35 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
Server version: 10.2.38-MariaDB-log
read_buffer_size=131072
max_used_connections=1
thread_count=0
Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x0 thread_stack 0x5b000
/lib/x86_64-linux-gnu/libasan.so.5(+0x6cd30)[0x7fe6e226bd30]
/data/bld/10.2-rel-asan-nightly/bin/mysqld(my_print_stacktrace+0xf6)[0x5607dc54fc26]
/data/bld/10.2-rel-asan-nightly/bin/mysqld(handle_fatal_signal+0xbd2)[0x5607db43c822]
sigaction.c:0(__restore_rt)[0x7fe6e1d4d3c0]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcb)[0x7fe6e184118b]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x12b)[0x7fe6e1820859]
/lib/x86_64-linux-gnu/libasan.so.5(+0x12b6a2)[0x7fe6e232a6a2]
/lib/x86_64-linux-gnu/libasan.so.5(+0x13624c)[0x7fe6e233524c]
/lib/x86_64-linux-gnu/libasan.so.5(+0x13bb9c)[0x7fe6e233ab9c]
/lib/x86_64-linux-gnu/libasan.so.5(+0x13b3dd)[0x7fe6e233a3dd]
/lib/x86_64-linux-gnu/libc.so.6(__cxa_finalize+0xce)[0x7fe6e184515e]
/lib/x86_64-linux-gnu/libasan.so.5(+0x22be7)[0x7fe6e2221be7]
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains
information that should help you find out what is causing the crash.
Writing a core file...
Working directory at /dev/shm/var_auto_Jb5S/mysqld.1/data
Resource Limits:
Fatal signal 11 while backtracing

10.2 676987c4 debug

Warning: Memory not freed: 131144
Warning: 131072 bytes lost at 0x7f44f003aa50, allocated by T@0 at mysys/mf_iocache.c:247, sql/sql_class.cc:2872, sql/sql_class.cc:2894, sql/sql_select.cc:1053, sql/sql_select.cc:3818, sql/sql_select.cc:361, sql/sql_parse.cc:6275, sql/sql_parse.cc:3586
Warning:   72 bytes lost at 0x562a0d214af0, allocated by T@0 at mysys/my_malloc.c:241, mysys/my_open.c:141, mysys/my_create.c:57, psi/mysql_file.h:1008, sql/sql_class.cc:2864, sql/sql_class.cc:2894, sql/sql_select.cc:1053, sql/sql_select.cc:3818
Warning: 131072 bytes lost at 0x7f44f003aa50, allocated by T@0 at mysys/mf_iocache.c:247, sql/sql_class.cc:2872, sql/sql_class.cc:2894, sql/sql_select.cc:1053, sql/sql_select.cc:3818, sql/sql_select.cc:361, sql/sql_parse.cc:6275, sql/sql_parse.cc:3586
Warning:   72 bytes lost at 0x562a0d214af0, allocated by T@0 at mysys/my_malloc.c:241, mysys/my_open.c:141, mysys/my_create.c:57, psi/mysql_file.h:1008, sql/sql_class.cc:2864, sql/sql_class.cc:2894, sql/sql_select.cc:1053, sql/sql_select.cc:3818

10.2 676987c4 Valgrind

Warning: Memory not freed: 131168
==799989== 88 bytes in 1 blocks are still reachable in loss record 1 of 2
==799989==    at 0x483B7F3: malloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so)
==799989==    by 0x112EE8E: my_malloc (my_malloc.c:101)
==799989==    by 0x112F58D: my_strdup (my_malloc.c:241)
==799989==    by 0x1130C7C: my_register_filename (my_open.c:141)
==799989==    by 0x1123850: my_create (my_create.c:57)
==799989==    by 0x6AB5B0: inline_mysql_file_create(unsigned int, char const*, unsigned int, char const*, int, int, unsigned long) (mysql_file.h:1008)
==799989==    by 0x6B360A: create_file(THD*, char*, sql_exchange*, st_io_cache*) (sql_class.cc:2864)
==799989==    by 0x6B378E: select_export::prepare(List<Item>&, st_select_lex_unit*) (sql_class.cc:2894)
==799989==    by 0x73E645: JOIN::prepare(TABLE_LIST*, unsigned int, Item*, unsigned int, st_order*, bool, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*) (sql_select.cc:1053)
==799989==    by 0x747F7B: mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:3818)
==799989==    by 0x73C02F: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:361)
==799989==    by 0x705E06: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:6275)
==799989==    by 0x6FC978: mysql_execute_command(THD*) (sql_parse.cc:3586)
==799989==    by 0x64B623: sp_instr_stmt::exec_core(THD*, unsigned int*) (sp_head.cc:3332)
==799989==    by 0x64AC84: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) (sp_head.cc:3095)
==799989==    by 0x64B2C8: sp_instr_stmt::execute(THD*, unsigned int*) (sp_head.cc:3248)
==799989== 131,080 bytes in 1 blocks are definitely lost in loss record 2 of 2
==799989==    at 0x483B7F3: malloc (in /usr/lib/x86_64-linux-gnu/valgrind/vgpreload_memcheck-amd64-linux.so)
==799989==    by 0x112EE8E: my_malloc (my_malloc.c:101)
==799989==    by 0x110A079: init_io_cache (mf_iocache.c:247)
==799989==    by 0x6B365D: create_file(THD*, char*, sql_exchange*, st_io_cache*) (sql_class.cc:2872)
==799989==    by 0x6B378E: select_export::prepare(List<Item>&, st_select_lex_unit*) (sql_class.cc:2894)
==799989==    by 0x73E645: JOIN::prepare(TABLE_LIST*, unsigned int, Item*, unsigned int, st_order*, bool, st_order*, Item*, st_order*, st_select_lex*, st_select_lex_unit*) (sql_select.cc:1053)
==799989==    by 0x747F7B: mysql_select(THD*, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:3818)
==799989==    by 0x73C02F: handle_select(THD*, LEX*, select_result*, unsigned long) (sql_select.cc:361)
==799989==    by 0x705E06: execute_sqlcom_select(THD*, TABLE_LIST*) (sql_parse.cc:6275)
==799989==    by 0x6FC978: mysql_execute_command(THD*) (sql_parse.cc:3586)
==799989==    by 0x64B623: sp_instr_stmt::exec_core(THD*, unsigned int*) (sp_head.cc:3332)
==799989==    by 0x64AC84: sp_lex_keeper::reset_lex_and_exec_core(THD*, unsigned int*, bool, sp_instr*) (sp_head.cc:3095)
==799989==    by 0x64B2C8: sp_instr_stmt::execute(THD*, unsigned int*) (sp_head.cc:3248)
==799989==    by 0x646295: sp_head::execute(THD*, bool) (sp_head.cc:1326)
==799989==    by 0x6484B5: sp_head::execute_procedure(THD*, List<Item>*) (sp_head.cc:2202)
==799989==    by 0x6FAD22: do_execute_sp(THD*, sp_head*) (sql_parse.cc:2981)

The same scenario makes the files created by the failing SELECT remain open:

--source include/have_sequence.inc
 
CREATE TABLE t (a INT);
INSERT INTO t SELECT seq FROM seq_1_to_100;
SET MAX_JOIN_SIZE= 20;
--let $datadir= `SELECT @@datadir`
 
SHOW STATUS LIKE 'Open_files';
CREATE OR REPLACE PROCEDURE sp() SELECT * INTO OUTFILE 'load_t1' FROM t;
--error ER_TOO_BIG_SELECT
CALL sp;
--remove_file $datadir/test/load_t1
CREATE OR REPLACE PROCEDURE sp() SELECT * INTO OUTFILE 'load_t2' FROM t;
--error ER_TOO_BIG_SELECT
CALL sp;
--remove_file $datadir/test/load_t2
CREATE OR REPLACE PROCEDURE sp() SELECT * INTO OUTFILE 'load_t3' FROM t;
--error ER_TOO_BIG_SELECT
CALL sp;
--remove_file $datadir/test/load_t3
SHOW STATUS LIKE 'Open_files';
 
# Cleanup
DROP PROCEDURE sp;
DROP TABLE t;

10.2 676987c4

SHOW STATUS LIKE 'Open_files';
Variable_name	Value
Open_files	52
...
SHOW STATUS LIKE 'Open_files';
Variable_name	Value
Open_files	55

Repeating the exercise eventually makes the server exceed the open files limit.



 Comments   
Comment by Oleksandr Byelkin [ 2023-09-27 ]

probably my_close was not called

Comment by Oleksandr Byelkin [ 2023-09-27 ]

memory leaks are today super interesting

Comment by Oleksandr Byelkin [ 2023-09-27 ]

so JOIN::execute was not called due to error and so JOIN::eof or cleanup

Comment by Oleksandr Byelkin [ 2023-09-28 ]

The problem is that result object can be cleaned when we cleanup JOIN object (too early, eof is not send)

Generated at Thu Feb 08 09:34:44 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.