Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-26657

SHOW ENGINE INNODB STATUS displays uninitialized THD::real_id

Details

    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);

      Attachments

        Issue Links

          is caused by

          Bug - A problem which impairs or prevents the functions of the product. MDEV-25919 InnoDB reports misleading lock wait timeout on DDL operations

          • Major - Major loss of function.
          • Closed

          Activity

            wlad Vladislav Vaintroub added a comment - - edited

            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.

            wlad Vladislav Vaintroub added a comment - - edited 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.

            People

              wlad Vladislav Vaintroub
              marko Marko Mäkelä
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.