[MDEV-28613] Query from I_S.INNODB_SYS_INDEXES exceeding LIMIT ROWS EXAMINED causes ER_UNKNOWN_ERROR and LeakSanitizer errors in rec_copy_prefix_to_buf_old Created: 2022-05-18  Updated: 2023-12-07  Resolved: 2023-11-21

Status: Closed
Project: MariaDB Server
Component/s: Information Schema, Storage Engine - InnoDB
Affects Version/s: 10.3, 10.4, 10.5, 10.6, 10.7, 10.8, 11.0
Fix Version/s: 10.4.33, 10.5.24, 10.6.17, 10.11.7, 11.0.5, 11.1.4, 11.2.3

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: LSAN

Issue Links:
Relates
relates to MDEV-28658 ER_UNKNOWN_ERROR reported due to LIMI... Open

 Description    

--source include/have_innodb.inc
 
 
 
--error 0,ER_UNKNOWN_ERROR
 
SELECT * FROM INFORMATION_SCHEMA.INNODB_SYS_INDEXES LIMIT ROWS EXAMINED 5;
 
 
 
--source include/restart_mysqld.inc

10.3 3e564d46

 
==3364408==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 24 byte(s) in 1 object(s) allocated from:
 
    #0 0x7f2ad8cd7e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
 
    #1 0x55cf43204ab8 in rec_copy_prefix_to_buf_old /data/src/10.3/storage/innobase/rem/rem0rec.cc:1854
 
    #2 0x55cf43204ab8 in rec_copy_prefix_to_buf(unsigned char const*, dict_index_t const*, unsigned long, unsigned char**, unsigned long*) /data/src/10.3/stor
 
age/innobase/rem/rem0rec.cc:1888
 
    #3 0x55cf4344da99 in btr_pcur_store_position(btr_pcur_t*, mtr_t*) /data/src/10.3/storage/innobase/btr/btr0pcur.cc:200
 
    #4 0x55cf43518ff2 in dict_getnext_system_low /data/src/10.3/storage/innobase/dict/dict0load.cc:313
 
    #5 0x55cf430ea9d4 in i_s_sys_indexes_fill_table /data/src/10.3/storage/innobase/handler/i_s.cc:5595
 
    #6 0x55cf425b90bd in get_schema_tables_result(JOIN*, enum_schema_table_state) /data/src/10.3/sql/sql_show.cc:9031
 
    #7 0x55cf4255cf3b in JOIN::exec_inner() /data/src/10.3/sql/sql_select.cc:4114
 
    #8 0x55cf4255f839 in JOIN::exec() /data/src/10.3/sql/sql_select.cc:3945
 
    #9 0x55cf4255fc54 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.3/sql/sql_select.cc:4354
 
    #10 0x55cf425624ff in handle_select(THD*, LEX*, select_result*, unsigned long) /data/src/10.3/sql/sql_select.cc:372
 
    #11 0x55cf423f2eff in execute_sqlcom_select /data/src/10.3/sql/sql_parse.cc:6339
 
    #12 0x55cf42418068 in mysql_execute_command(THD*) /data/src/10.3/sql/sql_parse.cc:3870
 
    #13 0x55cf42420507 in mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool) /data/src/10.3/sql/sql_parse.cc:7870
 
    #14 0x55cf42425049 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool) /data/src/10.3/sql/sql_parse.cc:1852
 
    #15 0x55cf4242aded in do_command(THD*) /data/src/10.3/sql/sql_parse.cc:1398
 
    #16 0x55cf42748cd6 in do_handle_one_connection(CONNECT*) /data/src/10.3/sql/sql_connect.cc:1403
 
    #17 0x55cf4274953a in handle_one_connection /data/src/10.3/sql/sql_connect.cc:1308
 
    #18 0x55cf4398f074 in pfs_spawn_thread /data/src/10.3/storage/perfschema/pfs.cc:1869
 
    #19 0x7f2ad8435ea6 in start_thread nptl/pthread_create.c:477

The query ends with an error:

mysqltest: At line 3: query 'SELECT * FROM INFORMATION_SCHEMA.INNODB_SYS_INDEXES LIMIT ROWS EXAMINED 5' failed: 1105: Unknown error

Normally when a query exceeds the given LIMIT ROWS EXAMINED value, it succeeds with an incomplete result and a warning:

SELECT * FROM INFORMATION_SCHEMA.INNODB_SYS_COLUMNS LIMIT ROWS EXAMINED 5;
 
TABLE_ID	NAME	POS	MTYPE	PRTYPE	LEN
 
Warnings:
 
Warning	1931	Query execution was interrupted. The query examined at least 7 rows, which exceeds LIMIT ROWS EXAMINED (5). The query result may be incomplete

Reproducible on 10.3-10.9. Not reproducible on 10.2.

 Comments   
Comment by Thirunarayanan Balathandayuthapani [ 2022-05-19 ] 

diff --git a/storage/innobase/handler/i_s.cc b/storage/innobase/handler/i_s.cc
 
index 8fc40aa2856..f1c0324f18f 100644
 
--- a/storage/innobase/handler/i_s.cc
 
+++ b/storage/innobase/handler/i_s.cc
 
@@ -5616,6 +5616,7 @@ i_s_sys_indexes_fill_table(
 
                        if (int err = i_s_dict_fill_sys_indexes(
 
                                    thd, table_id, space_id, &index_rec,
 
                                    tables->table)) {
 
+                               btr_pcur_close(&pcur);
 
                                mem_heap_free(heap);
 
                                DBUG_RETURN(err);
 
                        }

This could fix the issue. The problem is that InnoDB stores the position of the cursor. EXAMINED query sets thd->killed, leads to schema_table_store_record() returns 1.
InnoDB I_S query fails to remove the cursor->old_rec_buf heap.

Comment by Thirunarayanan Balathandayuthapani [ 2022-05-19 ]
  • Patch is in bb-10.3-thiru
Comment by Elena Stepanova [ 2022-05-19 ]

The recorded test result in your patch still shows ER_UNKOWN_ERROR. It doesn't look right. Normally in this case the query doesn't fail but ends with the warning ER_QUERY_EXCEEDED_ROWS_EXAMINED_LIMIT. Even queries from other I_S.INNODB_xx tables, as shown in the description.

Comment by Marko Mäkelä [ 2022-05-24 ]

I posted some review comments, and I think that a different fix is needed.

elenst, that a strange error code is being returned should be topic of a separate bug, for get_schema_tables_result() or schema_table_store_record(), both in sql/sql_show.cc outside InnoDB.

I just realized that there is no concurrency between the server restart and the query; the restart seems redundant to me. If the test fails to report a memory leak without it, that would be an error in mtr.

Comment by Elena Stepanova [ 2022-05-24 ]

Restart links the LeakSanitizer error to the specific test and makes the test fail, failure stored in the database etc. Without restart, the failure will only be displayed as a shutdown warning after a chain of tests.
But yes, for the regression suite the restart is probably redundant as we expect the test to pass.

For the error code being a separate problem, you would know better, please split the bug report accordingly. I cannot claim it to be outside InnoDB because I can't explain why then it would happen on one I_S InnoDB table but not on another.

Comment by Marko Mäkelä [ 2022-05-24 ]

I filed MDEV-28658 for the unexpected error code.

Comment by Roel Van de Paar [ 2023-04-01 ]

I ran into this one as well. The following reduced testcase:

SET max_statement_time=0.001;
 
SELECT sf.name,sf.pos FROM information_schema.innodb_sys_indexes si JOIN information_schema.innodb_sys_fields sf ON si.index_id=sf.index_id;
 
SHUTDOWN;

Can show the following memory leak:

11.0.2 a79abb6517f2fa68b48e61aa3354a0631e3a63f7 (Debug, UBASAN)

 
==722769==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 24 byte(s) in 1 object(s) allocated from:
 
    #0 0x55d90e073337 in __interceptor_malloc (/test/UBASAN_MD250323-mariadb-11.0.2-linux-x86_64-dbg/bin/mariadbd+0x792a337)
 
    #1 0x55d911c81767 in rec_copy_prefix_to_buf_old /test/11.0_dbg_san/storage/innobase/rem/rem0rec.cc:1940
 
    #2 0x55d911c81767 in rec_copy_prefix_to_buf(unsigned char const*, dict_index_t const*, unsigned long, unsigned char**, unsigned long*) /test/11.0_dbg_san/storage/innobase/rem/rem0rec.cc:1974
 
    #3 0x55d9121195ef in btr_pcur_store_position(btr_pcur_t*, mtr_t*) /test/11.0_dbg_san/storage/innobase/btr/btr0pcur.cc:171
 
    #4 0x55d9122ab2bc in dict_getnext_system_low /test/11.0_dbg_san/storage/innobase/dict/dict0load.cc:202
 
    #5 0x55d9122b437a in dict_startscan_system(btr_pcur_t*, mtr_t*, dict_table_t*) /test/11.0_dbg_san/storage/innobase/dict/dict0load.cc:224
 
    #6 0x55d9119d8ac3 in i_s_sys_indexes_fill_table /test/11.0_dbg_san/storage/innobase/handler/i_s.cc:5027
 
    #7 0x55d90ef4a33d in get_schema_tables_result(JOIN*, enum_schema_table_state) /test/11.0_dbg_san/sql/sql_show.cc:9060
 
    #8 0x55d90ede64c5 in JOIN::exec_inner() /test/11.0_dbg_san/sql/sql_select.cc:4852
 
    #9 0x55d90edea57a in JOIN::exec() /test/11.0_dbg_san/sql/sql_select.cc:4672
 
    #10 0x55d90edd8d38 in mysql_select(THD*, TABLE_LIST*, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /test/11.0_dbg_san/sql/sql_select.cc:5153
 
    #11 0x55d90eddd193 in handle_select(THD*, LEX*, select_result*, unsigned long long) /test/11.0_dbg_san/sql/sql_select.cc:611
 
    #12 0x55d90e95c973 in execute_sqlcom_select /test/11.0_dbg_san/sql/sql_parse.cc:6267
 
    #13 0x55d90e9bdcce in mysql_execute_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:3949
 
    #14 0x55d90e9ed5e6 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/11.0_dbg_san/sql/sql_parse.cc:7999
 
    #15 0x55d90e9fd37a in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1894
 
    #16 0x55d90ea0b17f in do_command(THD*, bool) /test/11.0_dbg_san/sql/sql_parse.cc:1407
 
    #17 0x55d90f3cf459 in do_handle_one_connection(CONNECT*, bool) /test/11.0_dbg_san/sql/sql_connect.cc:1416
 
    #18 0x55d90f3d0974 in handle_one_connection /test/11.0_dbg_san/sql/sql_connect.cc:1318
 
    #19 0x155101642b42 in start_thread nptl/pthread_create.c:442
 
 
 
SUMMARY: AddressSanitizer: 24 byte(s) leaked in 1 allocation(s).

However, it has been challenging to create a reliable reproducer.

Comment by Roel Van de Paar [ 2023-05-13 ] 

SET max_statement_time=0.001;
 
SELECT sf.name,sf.pos FROM information_schema.innodb_sys_indexes si JOIN information_schema.innodb_sys_fields sf ON si.index_id=sf.index_id;
 
SHUTDOWN;

On 10.11 now? uses malloc instead of __interceptor_malloc:

10.11.4 7c9f275ee4cd59212a85827626fbca2615d144d5

 
2023-05-13 13:00:34 0 [Note] /test/UBASAN_MD120523-mariadb-10.11.4-linux-x86_64-opt/bin/mysqld: Shutdown complete
 
 
 
=================================================================
 
==1230304==ERROR: LeakSanitizer: detected memory leaks
 
 
 
Direct leak of 24 byte(s) in 1 object(s) allocated from:
 
    #0 0x563166d96ed7 in malloc (/test/UBASAN_MD120523-mariadb-10.11.4-linux-x86_64-opt/bin/mariadbd+0x7a5bed7)
 
    #1 0x56316a63665b in rec_copy_prefix_to_buf_old /test/10.11_opt_san/storage/innobase/rem/rem0rec.cc:1945
 
    #2 0x56316a63665b in rec_copy_prefix_to_buf(unsigned char const*, dict_index_t const*, unsigned long, unsigned char**, unsigned long*) /test/10.11_opt_san/storage/innobase/rem/rem0rec.cc:1979
 
    #3 0x56316aae34e2 in btr_pcur_store_position(btr_pcur_t*, mtr_t*) /test/10.11_opt_san/storage/innobase/btr/btr0pcur.cc:177
 
    #4 0x56316ac3d9f3 in dict_getnext_system_low /test/10.11_opt_san/storage/innobase/dict/dict0load.cc:202
 
    #5 0x56316ac3d9f3 in dict_startscan_system(btr_pcur_t*, mtr_t*, dict_table_t*) /test/10.11_opt_san/storage/innobase/dict/dict0load.cc:224
 
    #6 0x56316ac3d9f3 in dict_startscan_system(btr_pcur_t*, mtr_t*, dict_table_t*) /test/10.11_opt_san/storage/innobase/dict/dict0load.cc:211
 
    #7 0x56316a356b99 in i_s_sys_indexes_fill_table /test/10.11_opt_san/storage/innobase/handler/i_s.cc:5041
 
    #8 0x563167b4d895 in get_schema_tables_result(JOIN*, enum_schema_table_state) /test/10.11_opt_san/sql/sql_show.cc:9052
 
    #9 0x563167a5ac2c in JOIN::exec_inner() /test/10.11_opt_san/sql/sql_select.cc:4797
 
    #10 0x563167a617d3 in JOIN::exec() /test/10.11_opt_san/sql/sql_select.cc:4618
 
    #11 0x563167a4f65d in mysql_select(THD*, TABLE_LIST*, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) /test/10.11_opt_san/sql/sql_select.cc:5098
 
    #12 0x563167a531c0 in handle_select(THD*, LEX*, select_result*, unsigned long long) /test/10.11_opt_san/sql/sql_select.cc:586
 
    #13 0x5631675ec260 in execute_sqlcom_select /test/10.11_opt_san/sql/sql_parse.cc:6279
 
    #14 0x5631676519e3 in mysql_execute_command(THD*, bool) /test/10.11_opt_san/sql/sql_parse.cc:3949
 
    #15 0x563167662562 in mysql_parse(THD*, char*, unsigned int, Parser_state*) /test/10.11_opt_san/sql/sql_parse.cc:8017
 
    #16 0x56316766e5d5 in dispatch_command(enum_server_command, THD*, char*, unsigned int, bool) /test/10.11_opt_san/sql/sql_parse.cc:1894
 
    #17 0x563167679840 in do_command(THD*, bool) /test/10.11_opt_san/sql/sql_parse.cc:1407
 
    #18 0x563167f6ba8c in do_handle_one_connection(CONNECT*, bool) /test/10.11_opt_san/sql/sql_connect.cc:1416
 
    #19 0x563167f6e08c in handle_one_connection /test/10.11_opt_san/sql/sql_connect.cc:1318
 
    #20 0x145c78694b42 in start_thread nptl/pthread_create.c:442
 
 
 
SUMMARY: AddressSanitizer: 24 byte(s) leaked in 1 allocation(s).
 
230513 13:00:34 [ERROR] mysqld got signal 6 ;

Very sporadic as before.

Comment by Thirunarayanan Balathandayuthapani [ 2023-11-10 ]

https://github.com/MariaDB/server/pull/2831

Comment by Marko Mäkelä [ 2023-11-14 ]

I think that there are some further memory leaks in other INFORMATION_SCHEMA.INNODB_SYS_ tables. It would be better to cover all those tables in a regression test.

Comment by Marko Mäkelä [ 2023-11-20 ]

Thank you, the fix looks good to me. Please consider disabling the output of every SELECT…LIMIT ROWS EXAMINED statement that is tested. I can imagine that they may return any amount of rows between 0 and the specified limit.

Generated at Thu Feb 08 10:02:07 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.