[MDEV-26657] SHOW ENGINE INNODB STATUS displays uninitialized THD::real_id Created: 2021-09-21  Updated: 2021-09-21  Resolved: 2021-09-21

Status: Closed
Project: MariaDB Server
Component/s: Server, Storage Engine - InnoDB
Affects Version/s: 10.6, 10.7
Fix Version/s: 10.5.13, 10.6.5, 10.7.0

Type: Bug Priority: Critical
Reporter: Marko Mäkelä Assignee: Vladislav Vaintroub
Resolution: Fixed Votes: 0
Labels: MSAN, regression

Issue Links:
Problem/Incident
is caused by MDEV-25919 InnoDB reports misleading lock wait t... Closed

 Description   

The following error was observed in https://buildbot.mariadb.org/#/builders/195/builds/3048/steps/7/logs/stdio and is nondeterministically repeatable locally. I got it replayed under rr after setting -DPLUGIN_PERFSCHEMA=NO:

10.6 b740b2356d539a27f8a7a9e9b6455f31bc6c9196

Version: '10.6.5-MariaDB-debug-log'  socket: '/dev/shm/10.6msan/mysql-test/var/tmp/mysqld.1.sock'  port: 16060  Source distribution
==1210070==WARNING: MemorySanitizer: use-of-uninitialized-value
    #0 0x56542be6fbff in int10_to_str /mariadb/10.6/strings/int2str.c:168:3
    #1 0x56542be77b1a in process_int_arg /mariadb/10.6/strings/my_vsnprintf.c
    #2 0x56542be7256f in my_vsnprintf_ex /mariadb/10.6/strings/my_vsnprintf.c:764:11
    #3 0x56542be783d3 in my_vsnprintf /mariadb/10.6/strings/my_vsnprintf.c:815:10
    #4 0x56542be783d3 in my_snprintf /mariadb/10.6/strings/my_vsnprintf.c:824:11
    #5 0x565429507e96 in thd_get_error_context_description /mariadb/10.6/sql/sql_show.cc:10190:8
    #6 0x56542ac3bb84 in innobase_mysql_print_thd(_IO_FILE*, THD*, unsigned int) /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:2333:8
    #7 0x56542aebb2b9 in lock_trx_print_wait_and_mvcc_state(_IO_FILE*, trx_t const*, my_hrtime_t) /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4185:2

Here is a better stack trace from my rr replay session:

10.6 b740b2356d539a27f8a7a9e9b6455f31bc6c9196

(rr) set print frame-arguments scalars 
(rr) bt
#0  innobase_mysql_print_thd (f=0x714000000a00, f@entry=0x7fe86a231318, thd=0x72b00007e018, max_query_len=600) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:2330
#1  0x000056542b4a1d4d in trx_print_low (f=<optimized out>, f@entry=0x38, trx=trx@entry=0xfffffffffffff290, max_query_len=56, max_query_len@entry=140636058381456, n_rec_locks=80, 
    n_rec_locks@entry=124519691848192, n_trx_locks=n_trx_locks@entry=6269010687742184054, heap_size=<optimized out>) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1744
#2  0x000056542b4a20ba in trx_print_latched (f=0x38, f@entry=0x7fe86a231318, trx=<optimized out>, trx@entry=0x7fe86a231318, max_query_len=140636058381456, max_query_len@entry=600)
    at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:1763
#3  0x000056542aebb2ba in lock_trx_print_wait_and_mvcc_state (file=0x714000000a00, trx=0x7fe86a231318, now=...) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4185
#4  0x000056542aeed8b5 in lock_print_info::operator() (this=this@entry=0x7fe8624d7068, trx=...) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4251
#5  0x000056542aee5ff6 in thread_safe_trx_ilist_t::for_each<lock_print_info> (this=0x56542cdf6d40 <trx_sys+128>, callback=...) at /mariadb/10.6/storage/innobase/include/trx0sys.h:828
#6  0x000056542aebdf6f in lock_print_info_all_transactions (file=<optimized out>) at /mariadb/10.6/storage/innobase/lock/lock0lock.cc:4272
#7  0x000056542b3aec49 in srv_printf_innodb_monitor (file=0x714000000a00, nowait=nowait@entry=0, trx_start_pos=trx_start_pos@entry=0x7fe8624d7970, trx_end=trx_end@entry=0x7fe8624d7968)
    at /mariadb/10.6/storage/innobase/srv/srv0srv.cc:830
#8  0x000056542acd1d2c in innodb_show_status (hton=<optimized out>, thd=0x72b000070018, 
    stat_print=0x565429ea61a0 <stat_print(THD*, char const*, unsigned long, char const*, unsigned long, char const*, unsigned long)>) at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:16109
#9  innobase_show_status (hton=<optimized out>, hton@entry=0x714000000818, thd=thd@entry=0x72b000070018, 
    stat_print=0x565429ea61a0 <stat_print(THD*, char const*, unsigned long, char const*, unsigned long, char const*, unsigned long)>, stat_type=<optimized out>)
    at /mariadb/10.6/storage/innobase/handler/ha_innodb.cc:16191
#10 0x0000565429ea59c3 in ha_show_status (thd=thd@entry=0x72b000070018, db_type=0x714000000818, stat=stat@entry=HA_ENGINE_STATUS) at /mariadb/10.6/sql/handler.cc:6898

The transaction had been created here:

Thread 5 hit Hardware watchpoint 2: -location trx.id
 
Old value = 0
New value = 88
trx_sys_t::register_rw (this=0x56542cdf6cc0 <trx_sys>, trx=0x7fe86a231318) at /mariadb/10.6/storage/innobase/include/trx0sys.h:1102
1102	    rw_trx_hash.insert(trx);
(rr) bt
#0  trx_sys_t::register_rw (this=0x56542cdf6cc0 <trx_sys>, trx=0x7fe86a231318) at /mariadb/10.6/storage/innobase/include/trx0sys.h:1102
#1  trx_start_low (trx=<optimized out>, read_write=true) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:947
#2  0x000056542b4a5e62 in trx_start_internal_low (trx=0x0, trx@entry=0x7fe86a231318, read_write=<optimized out>) at /mariadb/10.6/storage/innobase/trx/trx0trx.cc:2100
#3  0x000056542b7ff1b5 in dict_stats_save (table_orig=0x719000020398, table_orig@entry=0x716000041d88, only_for_index=only_for_index@entry=0x0) at /mariadb/10.6/storage/innobase/dict/dict0stats.cc:3106
#4  0x000056542b80c4a1 in dict_stats_update (table=<optimized out>, table@entry=0x716000041d88, stats_upd_option=stats_upd_option@entry=DICT_STATS_RECALC_PERSISTENT)
    at /mariadb/10.6/storage/innobase/dict/dict0stats.cc:3854
#5  0x000056542b82db1a in dict_stats_process_entry_from_recalc_pool (thd=0x72b00007e018) at /mariadb/10.6/storage/innobase/dict/dict0stats_bg.cc:340
#6  dict_stats_func () at /mariadb/10.6/storage/innobase/dict/dict0stats_bg.cc:393
#7  0x000056542ba63910 in tpool::thread_pool_generic::timer_generic::run (this=0x711000014640) at /mariadb/10.6/tpool/tpool_generic.cc:313

Starting with the fix of MDEV-25919, background THDs may wait for MDL or InnoDB locks.

The problem appears to be that thd->real_id is not initialized. Its value consists of 0xa5 bytes, and the MSAN shadow bits for it are all set.

10190	  len= my_snprintf(header, sizeof(header),
10191	                   "MariaDB thread id %u, OS thread handle %lu, query id %llu",
10192	                   (uint)thd->thread_id, (ulong) thd->real_id, (ulonglong) thd->query_id);



 Comments   
Comment by Vladislav Vaintroub [ 2021-09-21 ]

I initialize all of these things with 0 now.marko, if you like real_id to refer to something meaningful (I doubt this is useful, outside of debug session), then you'd need to set it yourself, in a thread that uses a background THD.

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