Sunday, August 20, 2017

Fun with Bugs #55 - On Some Public Bugs Fixed in MySQL 8.0.2

I do not care much about MySQL 8.0.x at the moment, as it's far from being GA and is work in progress. It is not yet used by customers whom I have to support. But I know about many interesting changes and improvements there that, eventually, are going to influence all main forks and kinds of MySQL. So, it would not be wise to ignore MySQL 8.0.c entirely even for me.

For this post I decided to briefly check what community reported bugs were fixed in the recent release, 8.0.2, based on release notes. For me it's a measure of community interest in MySQL 8.0.x and Oracle's interest in further working with MySQL Community. I ended up with the following, short enough list of bug fixes in the categories I usually care about (InnoDB, partitioning, replication and optimizer):
  • The very first InnoDB bug mentioned in the release notes, Bug #85043, is private. I fail to see any valid reason for a bug in the version currently under development and not declared GA to remain private after the fix is released. If only it affects GA versions, and this is the case. The bug is fixed in 5.7.19 as well, as you can see in my previous post.
  • Another bug that is related to InnoDB and optimizer, is Bug #81031. It was also fixed in MySQL 5.6.37 and 5.7.19.
  • Bug #84038 - "Errors when restarting MySQL after FLUSH TABLES FOR EXPORT, RENAME and DROP", was also fixed in MySQL 5.7.19. I am actually surprised that as this stage we still have older InnoDB internal data dictionary tables in MySQL 8.0.x.
  • Group replication related Bug #85667, Bug #85047, Bug #84728  and Bug #84733 were also listed as fixed in MySQL 5.7.19.
  • Same situation with normal async replication bugs: Bug #83184, Bug #82283, Bug #81232, Bug #77406 etc. It's expected to see fixes applied to the oldest version affected and then fixes merged to newer versions.
  • The first really unique fix in 8.0.2 that I found was Bug #85639 - "XA transactions are 'unsafe' for RPL using SBR". It was reported by João Gramacho (who probably works for Oracle) originally for MySQL 5.7 and is going to be fixed in MySQL 5.7.20 also.
  • Replication-related Bug #85739 is still private. Release notes say:
    "Issuing SHOW SLAVE STATUS FOR CHANNEL 'group_replication_recovery' following a restart of a server using group replication led to an unplanned shutdown."
  • Yet another private replication bugs fixed in 8.0.2 are: Bug #85405, Bug #85084, Bug #84646Bug #84471, Bug #82467 and Bug #80368. I do not know who reported them, what versions are affected (but I suspect .5.7.x also) and why are they remaining private after being fixed in 8.0.2.
  • The first 8.0.x specific public bug report I've found in the release notes was reported by Andrey Hristov and verified by Umesh Shastry. It is Bug #85937 - "Unchecked read after allocated buffer".
  • Bug #86120 - "Upgrading a MySQL instance with a table name of >64 chars results in breakage", was reported by Daniël van Eeden and verified by Umesh Shastry. I expect a lot of problem reports when users starts to upgrade to 8.0... See also Bug #84889 - "MYSQL 8.0.1 - MYSQLD ERRORLOG UPGRADE ERRORS AT SERVER START LIVE UPGRADE", by Susan Koerner.
  • Bug #85994 - "Out-of-bounds read in mysqld.cc fix_paths", was reported by Laurynas Biveinis and verified by Umesh Shastry. Percona seems to care a lot about improving MySQL 8.0 (as well as other Oracle MySQL GA versions). See also Bug #85678 by Laurynas and Bug #85059 by Roel Van de Paar.
  • Jon Olav Hauglid seems to care about the new data dictionary code quality, so he had reported related public bugs: Bug #85811, Bug #85800, and Bug #83473.
  • Bug #85704 - "mysql 8.0.x crashes when old-style trigger misses the "created" line in .TRG", was reported by Shane Bester. Workaround was also suggested by Jesper Krogh. Shane also reported this nice regression Bug #83019 - "queries in "show processlist" oscillate with constant times higher each day", that is now fixed in 8.0.2.
  • Bug #85614 - "alter table fails when default character set changes to utf8mb4", was reported by Tor Didriksen. He had also reported Bug #85224 - "Illegal mix of collations for time/varchar".
  • Bug #85518 - "Distinct operations on temp tables allocate too little memory for sort keys", was reported by Steinar Gunderson. He had also reported Bug #85487 - "num_tmp_files in filesort optimizer trace is nonsensical".
  • Bug #85179 - "Assert in sql/field.cc:... virtual String* Field_varstring::val_str", was reported by Matthias Leich.
I skipped several bugs that are fixed also in older versions. Many of them were already discussed in my posts. I also skipped all build/compilation/packaging bugs for now.

To summarize, while total number of public bug reports fixed in MySQL 8.0.2 is notable, many of these bugs were reported by few Oracle engineers who are still brave enough to report bugs in public. From Community, it seems only mostly Percona and Booking.com engineers do care to check MySQL 8.0.x at this early stage and report bugs. I am especially concerned with the number of private bug reports mentioned in the release notes of 8.0.2...

Saturday, August 12, 2017

More on Studying MySQL Hashes in gdb, and How P_S Code May Help

I have to get back to the topic of checking user variables in gdb to clarify few more details. In his comment Shane Bester kindly noted that calling functions defined in MySQL code is not going to work when core dump is studied. So, I ended up with a need to check what does the my_hash_element() function I've used really do, to be ready to repeat that step by step manually. Surely I could skip that and use Python and Shane himself did, but structures of HASH type are widely used in MySQL, so I'd better know how to investigate them manually than blindly use existing code.

Quick search with grep for my_hash_element shows:
[root@centos mysql-server]# grep -rn my_hash_element *
include/hash.h:94:uchar *my_hash_element(HASH *hash, ulong idx);
mysys/hash.c:734:uchar *my_hash_element(HASH *hash, ulong idx)plugin/keyring/hash_to_buffer_serializer.cc:34:      if(store_key_in_buffer(reinterpret_cast<const IKey *>(my_hash_element(keys_hash, i)),
plugin/version_token/version_token.cc:135:  while ((token_obj= (version_token_st *) my_hash_element(&version_tokens_hash, i)))
plugin/version_token/version_token.cc:879:    while ((token_obj= (version_token_st *) my_hash_element(&version_tokens_hash, i)))
sql/sql_base.cc:1051:    TABLE_SHARE *share= (TABLE_SHARE *)my_hash_element(&table_def_cache, idx);
sql/sql_base.cc:1262:        share= (TABLE_SHARE*) my_hash_element(&table_def_cache, idx);
sql/sql_udf.cc:277:    udf_func *udf=(udf_func*) my_hash_element(&udf_hash,idx);
...
sql/table_cache.cc:180:      (Table_cache_element*) my_hash_element(&m_cache, idx);
sql/rpl_gtid.h:2123:        Node *node= (Node *)my_hash_element(hash, i);
sql/rpl_gtid.h:2274:          node= (Node *)my_hash_element(hash, node_index);
sql/rpl_tblmap.cc:168:    entry *e= (entry *)my_hash_element(&m_table_ids, i);
sql/rpl_master.cc:238:    SLAVE_INFO* si = (SLAVE_INFO*) my_hash_element(&slave_list, i);
sql-common/client.c:3245:        LEX_STRING *attr= (LEX_STRING *) my_hash_element(attrs, idx);
storage/perfschema/table_uvar_by_thread.cc:76:    sql_uvar= reinterpret_cast<user_var_entry*> (my_hash_element(& thd->user_vars, index));storage/ndb/include/util/HashMap.hpp:155:    Entry* entry = (Entry*)my_hash_element(&m_hash, (ulong)i);
storage/ndb/include/util/HashMap.hpp:169:    Entry* entry = (Entry*)my_hash_element((HASH*)&m_hash, (ulong)i);
[root@centos mysql-server]#
That is, HASH structure is used everywhere in MySQL, from keyring to UDFs and table cache, to replication and NDB Cluster, with everything in between. If I can navigate to each HASH element and dump/print it, I can better understand a lot of code, if needed. If anyone cares, HASH is defined in a very simple way in include/hash.h:
typedef struct st_hash {
  size_t key_offset,key_length;         /* Length of key if const length */
  size_t blength;
  ulong records;
  uint flags;
  DYNAMIC_ARRAY array;                          /* Place for hash_keys */
  my_hash_get_key get_key;
  void (*free)(void *);
  CHARSET_INFO *charset;
  my_hash_function hash_function;
  PSI_memory_key m_psi_key;
} HASH;
It relies on DYNAMIC_ARRAY to store keys.

The code of the my_hash_element function in mysys/hash.c is very simple:
uchar *my_hash_element(HASH *hash, ulong idx)
{
  if (idx < hash->records)
    return dynamic_element(&hash->array,idx,HASH_LINK*)->data;
  return 0;
}
Quick search for dynamic_element shows that it's actually a macro:
[root@centos mysql-server]# grep -rn dynamic_element *
client/mysqldump.c:1608:    my_err= dynamic_element(&ignore_error, i, uint *);
extra/comp_err.c:471:      tmp= dynamic_element(&tmp_error->msg, i, struct message*);
extra/comp_err.c:692:    tmp= dynamic_element(&err->msg, i, struct message*);
extra/comp_err.c:803:  first= dynamic_element(&err->msg, 0, struct message*);
include/my_sys.h:769:#define dynamic_element(array,array_index,type) \mysys/hash.c:126:  HASH_LINK *data= dynamic_element(&hash->array, 0, HASH_LINK*);
...
that is defined in include/my_sys.h as follows:
#define dynamic_element(array,array_index,type) \
  ((type)((array)->buffer) +(array_index))
So, now it's clear what to do in gdb, having in mind what array do we use. Let me start the session, find a thread I am interested in and try to check elements one by one:
(gdb) thread 2
[Switching to thread 2 (Thread 0x7fc3a037b700 (LWP 3061))]#0  0x00007fc3d2cb3383 in poll () from /lib64/libc.so.6
(gdb) p do_command::thd->m_thread_id
$1 = 5
(gdb) p do_command::thd->user_vars
$2 = {key_offset = 0, key_length = 0, blength = 4, records = 3, flags = 0,
  array = {buffer = 0x7fc3ba2b3560 "\377\377\377\377", elements = 3,
    max_element = 16, alloc_increment = 32, size_of_element = 16,
    m_psi_key = 38},
  get_key = 0xc63630 <get_var_key(user_var_entry*, size_t*, my_bool)>,
  free = 0xc636c0 <free_user_var(user_var_entry*)>, charset = 0x1ded740,
  hash_function = 0xeb6990 <cset_hash_sort_adapter>, m_psi_key = 38}
(gdb) set $uvars=&(do_command::thd->user_vars)
(gdb) p $uvars
$3 = (HASH *) 0x7fc3b9fad280
...
(gdb) p &($uvars->array)
$5 = (DYNAMIC_ARRAY *) 0x7fc3b9fad2a8
(gdb) p ((HASH_LINK*)((&($uvars->array))->buffer) + (0))
$6 = (HASH_LINK *) 0x7fc3ba2b3560
(gdb) p ((HASH_LINK*)((&($uvars->array))->buffer) + (0))->data
$7 = (uchar *) 0x7fc3b9fc80e0 "H\201\374\271\303\177"
(gdb) p (user_var_entry *)(((HASH_LINK*)((&($uvars->array))->buffer) + (0))->data)
$8 = (user_var_entry *) 0x7fc3b9fc80e0
(gdb) p *(user_var_entry *)(((HASH_LINK*)((&($uvars->array))->buffer) + (0))->data)
$9 = {static extra_size = 8, m_ptr = 0x7fc3b9fc8148 "bbb", m_length = 3,
  m_type = STRING_RESULT, m_owner = 0x7fc3b9fad000, m_catalog = {
    str = 0x100000000 <Address 0x100000000 out of bounds>,
    length = 416611827727}, entry_name = {m_str = 0x7fc3b9fc8150 "a",
    m_length = 1}, collation = {collation = 0x1ded740,
    derivation = DERIVATION_IMPLICIT, repertoire = 3}, update_query_id = 25,
  used_query_id = 25, unsigned_flag = false}
...
(gdb) p *(user_var_entry *)(((HASH_LINK*)((&($uvars->array))->buffer) + (2))->data)
$11 = {static extra_size = 8, m_ptr = 0x7fc3b9e6e220 "\002", m_length = 64,
  m_type = DECIMAL_RESULT, m_owner = 0x7fc3b9fad000, m_catalog = {str = 0x0,
    length = 0}, entry_name = {m_str = 0x7fc3b9fc8290 "c", m_length = 1},
  collation = {collation = 0x1ded740, derivation = DERIVATION_IMPLICIT,
    repertoire = 3}, update_query_id = 25, used_query_id = 25,
  unsigned_flag = false}
(gdb)
I tried to highlight important details above. With gdb variables it's a matter of proper type casts and dereferencing. In general, I was printing content of item (user variable in this case) with index N as *(user_var_entry *)(((HASH_LINK*)((&($uvars->array))->buffer) + (N))->data).

Now, back to printing the variables.  Let's see how this is done in performance_schema, in storage/perfschema/table_uvar_by_thread.cc:
     74   for (;;)
     75   {
     76     sql_uvar= reinterpret_cast<user_var_entry*> (my_hash_element(& thd->user_vars, index));
     77     if (sql_uvar == NULL)
     78       break;
...
     98     /* Copy VARIABLE_NAME */
     99     const char *name= sql_uvar->entry_name.ptr();
    100     size_t name_length= sql_uvar->entry_name.length();
    101     DBUG_ASSERT(name_length <= sizeof(pfs_uvar.m_name));
    102     pfs_uvar.m_name.make_row(name, name_length);
    103
    104     /* Copy VARIABLE_VALUE */
    105     my_bool null_value;
    106     String *str_value;
    107     String str_buffer;
    108     uint decimals= 0;
    109     str_value= sql_uvar->val_str(& null_value, & str_buffer, decimals);    110     if (str_value != NULL)
    111     {
    112       pfs_uvar.m_value.make_row(str_value->ptr(), str_value->length());
    113     }
    114     else
    115     {
    116       pfs_uvar.m_value.make_row(NULL, 0);
    117     }
    118
    119     index++;    120   }

So, there we check elements by index until there is no element with such index, and apply the val_str() function of the class. While debugging live server we can do the same, but if we care to see how it works step by step, here is the code from sql/item_func.cc:
String *user_var_entry::val_str(my_bool *null_value, String *str,
                                uint decimals) const
{
  if ((*null_value= (m_ptr == 0)))
    return (String*) 0;

  switch (m_type) {
  case REAL_RESULT:
    str->set_real(*(double*) m_ptr, decimals, collation.collation);    break;
  case INT_RESULT:
    if (!unsigned_flag)
      str->set(*(longlong*) m_ptr, collation.collation);    else
      str->set(*(ulonglong*) m_ptr, collation.collation);    break;
  case DECIMAL_RESULT:
    str_set_decimal((my_decimal *) m_ptr, str, collation.collation);
    break;
  case STRING_RESULT:
    if (str->copy(m_ptr, m_length, collation.collation))
      str= 0;                                   // EOM error
  case ROW_RESULT:
    DBUG_ASSERT(1);                             // Impossible
    break;
  }
  return(str);
}
For INT_RESULT and REAL_RESULT it's all clear, and Shane did essentially the same in his Python code. For strings we have to copy proper items into a zero terminated string or use methods of String class if we debug on a live server to get the entire string data. For DECIMAL_RESULT I checked the implementation of str_set_decimal() that relies on decimal2string() eventually that... looks somewhat complicated (check yourself in strings/decimal.c). So, I'd better to just print my_decimal structure in gdb, for any practical purposes, instead of re-implementing this function in Python.

To summarize, HASH structure is widely used in MySQL and it is easy to dump any of these hashes in gdb, item by item, in the same way as, for example, Performance Schema in MySQL 5.7 does this of user variables. Getting string representation of my_decimal "manually" is complicated.

Monday, August 7, 2017

How to Find Values of User Variables With gdb

In his comment to my announcement of the previous post, Shane Bester kindly suggested to consider pretty printing the information about user variables from gdb. I tried to do this tonight, after a long working day, while working with the same Percona server 5.7.x on CentOS 6.9, and found several interesting details to share even before getting to the pretty printing part (that I'd surely try to avoid doing with Python anyway, as I am lazy and not in a mood to use that programming language for a decade already). So, I decided to share them in a separate post.

To begin with, I checked if actually using gdb for this task is needed for anyone else but those poor souls who has to study core dumps after the crash. This time I do not want Mark Leith to step in with a comment that I had better use <some cool P_S feature> (instead of attaching gdb to properly working production server), so I did my homework...

One can surely use the user_variables_by_thread table in the Performance Schema to get these details if server still works, P_S is enabled and it's possible to connect to it to run SQL queries. There is one minor problem (the type of user variable is missing there), that I was happy to report immediately as Bug #87341. By the way, I had found old feature request, Bug #20307, that I verified 11 years ago and that should be just properly closed because of this nice feature of current MySQL.

So, there is (small) reason to use gdb even before any crashes, and I did it immediately after settings values for few user variables in connection with id 16 with the following statements:
set @a := 'aaa', @b := 254, @c := sysdate();
set @e = 10.5;
I also want to show how one may use (relatively) new column in the threads table of Performance Schema while studying live server with gdb. This was also a hint from Mark Leith in a comment on my older post, to check THREAD_OS_ID column:
mysql> select * from threads\G
...
*************************** 27. row ***************************
          THREAD_ID: 42
               NAME: thread/sql/one_connection
               TYPE: FOREGROUND
     PROCESSLIST_ID: 16
   PROCESSLIST_USER: root
   PROCESSLIST_HOST: localhost
     PROCESSLIST_DB: test
PROCESSLIST_COMMAND: Sleep
   PROCESSLIST_TIME: 195
  PROCESSLIST_STATE: NULL
   PROCESSLIST_INFO: NULL
   PARENT_THREAD_ID: NULL
               ROLE: NULL
       INSTRUMENTED: YES
            HISTORY: YES
    CONNECTION_TYPE: Socket
       THREAD_OS_ID: 2224
...
My first naive attempt to check the details about user variables with gdb ended up as follows:
(gdb) thread 3
[Switching to thread 3 (Thread 0x7fc5997bc700 (LWP 2224))]#0  0x00007fc5cc299383 in poll () from /lib64/libc.so.6
(gdb) p do_command::thd->m_thread_id
$1 = 16
(gdb) p do_command::thd->user_vars
$2 = {key_offset = 0, key_length = 0, blength = 8, records = 4, flags = 0,
  array = {buffer = 0x7fc5aabf1560 "\001", elements = 4, max_element = 16,
    alloc_increment = 32, size_of_element = 16, m_psi_key = 38},
  get_key = 0xc63630 <get_var_key(user_var_entry*, size_t*, my_bool)>,
  free = 0xc636c0 <free_user_var(user_var_entry*)>, charset = 0x1ded740,
  hash_function = 0xeb6990 <cset_hash_sort_adapter>, m_psi_key = 38}
I see 4 elements for the thread I am interested in. Looks good. I also assume from the above that they are of user_var_entry type. So, given some buffer, I try to cast it to this type and check (that was stupid, especially further pointer increment attempt - if that were an array of structures imagine how long would it take to find some variable by name!):
(gdb) p do_command::thd->user_vars->array->buffer
$3 = (uchar *) 0x7fc5aabf1560 "\001"
(gdb) p (user_var_entry *)(do_command::thd->user_vars->array->buffer)
$4 = (user_var_entry *) 0x7fc5aabf1560
(gdb) p sizeof(user_var_entry)
$5 = 104
(gdb) set $vars = (user_var_entry *)(do_command::thd->user_vars->array->buffer)
(gdb) p $vars
$6 = (user_var_entry *) 0x7fc5aabf1560
(gdb) p *($vars)
$7 = {static extra_size = 8, m_ptr = 0x1 <Address 0x1 out of bounds>,
  m_length = 140486683628224, m_type = 4294967295
, m_owner = 0x7fc59adf90e0,
  m_catalog = {str = 0xffffffff <Address 0xffffffff out of bounds>,
    length = 140486683628064}, entry_name = {
    m_str = 0xffffffff <Address 0xffffffff out of bounds>,
    m_length = 140486683627904}, collation = {collation = 0x0,
    derivation = DERIVATION_EXPLICIT, repertoire = 0}, update_query_id = 0,
  used_query_id = 0, unsigned_flag = false}
(gdb) set $vars = $vars + 1
(gdb) p *($vars)
$8 = {static extra_size = 8, m_ptr = 0x0, m_length = 0,
  m_type = STRING_RESULT, m_owner = 0x0, m_catalog = {str = 0x0, length = 0},
  entry_name = {m_str = 0x0, m_length = 0}, collation = {collation = 0x0,
    derivation = DERIVATION_EXPLICIT, repertoire = 0}, update_query_id = 0,
  used_query_id = 0, unsigned_flag = false}
...
So, while eventually I've see something expected (STRING_RESULT as type) and pointer trick "worked", the content I get is obviously a bullshit - addresses are out of bounds or zero etc. This leads us nowhere at best.

I had to dig into the code to see how this structure is actually used. This is easy with grep:
[root@centos openxs]# grep -rn user_vars git/mysql-server/*
git/mysql-server/sql/item_func.cc:6017:  HASH *hash= & thd->user_vars;
...
git/mysql-server/sql/sql_prepare.cc:2182:    entry= (user_var_entry*)my_hash_search(&thd->user_vars,...
git/mysql-server/storage/perfschema/table_uvar_by_thread.cc:76:    sql_uvar= reinterpret_cast<user_var_entry*> (my_hash_element(& thd->user_vars, index));
...
git/mysql-server/sql/sql_class.cc:1209:  my_hash_init(&user_vars, system_charset_info, USER_VARS_HASH_SIZE, 0, 0,
git/mysql-server/sql/sql_class.cc:1650:  my_hash_init(&user_vars, system_charset_info, USER_VARS_HASH_SIZE, 0, 0,
...
git/mysql-server/sql/rpl_binlog_sender.cc:654:    (user_var_entry*) my_hash_search(&m_thd->user_vars, (uchar*) name.str,
...
git/mysql-server/sql/sql_class.h:1576:  HASH    user_vars;                     // hash for user variables...
git/mysql-server/storage/perfschema/table_uvar_by_thread.cc:76:    sql_uvar= reinterpret_cast<user_var_entry*> (my_hash_element(& thd->user_vars, index));[root@centos openxs]#
So, user_vars is actually a HASH, and we see functions to find the item in this hash by name, my_hash_search(), and to get item by index, my_hash_element(). I've immediately proceed to use the latter, as I wanted to see all variables:
...
(gdb) thread 10
[Switching to thread 10 (Thread 0x7fc5997bc700 (LWP 2224))]#0  0x00007fc5cc299383 in poll () from /lib64/libc.so.6
(gdb) p do_command::thd->m_thread_id
$1 = 16
(gdb) p do_command::thd->user_vars$2 = {key_offset = 0, key_length = 0, blength = 8, records = 4, flags = 0,
  array = {buffer = 0x7fc5aabf1560 "\001", elements = 4, max_element = 16,
    alloc_increment = 32, size_of_element = 16, m_psi_key = 38},
  get_key = 0xc63630 <get_var_key(user_var_entry*, size_t*, my_bool)>,
  free = 0xc636c0 <free_user_var(user_var_entry*)>, charset = 0x1ded740,
  hash_function = 0xeb6990 <cset_hash_sort_adapter>, m_psi_key = 38}
(gdb) p my_hash_element(&(do_command::thd->user_vars), 1)
$3 = (uchar *) 0x7fc59adf90e0 "H\221ъ \305\177"
(gdb) set $uvar = (user_var_entry *)(my_hash_element(&(do_command::thd->user_vars), 1))
[New Thread 0x7fc59946f700 (LWP 2447)]
[Thread 0x7fc59973a700 (LWP 2396) exited]
[New Thread 0x7fc59932a700 (LWP 2448)]
(gdb) p $uvar
$4 = (user_var_entry *) 0x7fc59adf90e0
(gdb) p *$uvar
$5 = {static extra_size = 8, m_ptr = 0x7fc59adf9148 "aaa", m_length = 3,
  m_type = STRING_RESULT
, m_owner = 0x7fc59accc000, m_catalog = {
    str = 0x41272c275441434e <Address 0x41272c275441434e out of bounds>,
    length = 6075168230325441358}, entry_name = {m_str = 0x7fc59adf9150 "a",
    m_length = 1}, collation = {collation = 0x1ded740,
    derivation = DERIVATION_IMPLICIT, repertoire = 3}, update_query_id = 430,
  used_query_id = 426, unsigned_flag = false}
...
(gdb) set $uvar = (user_var_entry *)(my_hash_element(&(do_command::thd->user_vars), 3))
[Thread 0x7fc599636700 (LWP 2400) exited]
(gdb) p *$uvar
$7 = {static extra_size = 8, m_ptr = 0x7fc59adf91e8 "\376", m_length = 8,
  m_type = INT_RESULT, m_owner = 0x7fc59accc000, m_catalog = {
    str = 0x655f79625f726573 <Address 0x655f79625f726573 out of bounds>,
    length = 7881702179129419126}, entry_name = {m_str = 0x7fc59adf91f0 "b",
    m_length = 1}, collation = {collation = 0x1ded740,
    derivation = DERIVATION_IMPLICIT, repertoire = 3}, update_query_id = 430,
  used_query_id = 426, unsigned_flag = false}
(gdb) set $uvar = (user_var_entry *)(my_hash_element(&(do_command::thd->user_vars), 4))
(gdb) p *$uvar
Cannot access memory at address 0x0
We see that this experimenting was performed on a server under some load, we see threads created and gone, we are able to get proper details by index, but should take extra case to check addresses before accessing them, and should note that items are numbered starting from zero, not 1 (there is no item 4, we get NULL pointer). If anyone cares, item with index 0 was this:
$8 = {static extra_size = 8, m_ptr = 0x7fc5b23b41c0 "\002", m_length = 64,
  m_type = DECIMAL_RESULT, m_owner = 0x7fc59accc000, m_catalog = {
    str = 0x7665602e60616d65 <Address 0x7665602e60616d65 out of bounds>,
    length = 7593481698565975653}, entry_name = {m_str = 0x7fc59adf9330 "e",
    m_length = 1}, collation = {collation = 0x1ded740,
    derivation = DERIVATION_IMPLICIT, repertoire = 3}, update_query_id = 444,
  used_query_id = 444, unsigned_flag = false}
As this was a hash table the order of items is determined by hash, not by the order of assignments to variables.

Now, if I know the name of the variable I can access it in the same way as it's done in the server code (one fo examples found by grep):
    entry= (user_var_entry*)my_hash_search(&thd->user_vars,
                                           (uchar*)lex->prepared_stmt_code.str,
                                           lex->prepared_stmt_code.length);
Basically, we need to pass variable name and the length of this name:
(gdb) set $uvar=(user_var_entry *)(my_hash_search(&(do_command::thd->user_vars), "e", strlen("e")))
[Thread 0x7fc5995b4700 (LWP 2848) exited]
(gdb) p *$uvar
$1 = {static extra_size = 8, m_ptr = 0x7fc5b23b41c0 "\002", m_length = 64,
  m_type = DECIMAL_RESULT, m_owner = 0x7fc59accc000, m_catalog = {
    str = 0x7665602e60616d65 <Address 0x7665602e60616d65 out of bounds>,
    length = 7593481698565975653}, entry_name = {m_str = 0x7fc59adf9330 "e",
    m_length = 1}, collation = {collation = 0x1ded740,
    derivation = DERIVATION_IMPLICIT, repertoire = 3}, update_query_id = 444,
  used_query_id = 444, unsigned_flag = false}

...
(gdb) p *((my_decimal *)$uvar->m_ptr)
$4 = {<st_decimal_t> = {intg = 2, frac = 1, len = 9, sign = 0 '\000',
    buf = 0x7fc5b23b41d8}, buffer = {10, 500000000, 0, 0, 0, 0, 257, 0,
    -1697445128}}
I highlighted some parts that eventually should help to pretty print decimal values. With just strings it's also not that trivial:
...
$5 = {static extra_size = 8, m_ptr = 0x7fc59adf9148 "aaa", m_length = 3,
  m_type = STRING_RESULT, m_owner = 0x7fc59accc000, m_catalog = {
    str = 0x41272c275441434e <Address 0x41272c275441434e out of bounds>,
    length = 6075168230325441358}, entry_name = {m_str = 0x7fc59adf9150 "a",
    m_length = 1}, collation = {collation = 0x1ded740,
    derivation = DERIVATION_IMPLICIT, repertoire = 3}, update_query_id = 430,
  used_query_id = 426, unsigned_flag = false}
(gdb) p *$uvar->m_ptr
$6 = 97 'a'
We can not simply print the pointer in a hope, as this is not a null-terminated string.

I am too tired to create a useful summary right now, but you can see that essentially it's easy (even if not trivial) to get all the details about the user variables defined in any session with gdb, both from working process or from core dump. Enjoy!

Saturday, August 5, 2017

How to Find Values of Session Variables With gdb

Usually I make notes while working on customer issues, reading the Slack channels or even scrolling across my Facebook news feed. Some of them are of "ToDo" kind, and this week while watching how my colleagues work on a very complicated crash/bug I noted that one of the problems they were discussing was how to find out from the core dump if the session behind the crashing thread had mrr=ON in the optimizer_switch.

I had already written more than once how to check MySQL threads one by one in gdb, depending on version and your real goal. For this post I decided to concentrate on checking the values of session variables and, specifically, individual switchable optimizations. This is actually easy, comparing to checking MySQL plugin variables...

I've used Percona 5.7.x and executed set session optimizer_switch='mrr=off'; in one of sessions. I checked threads one by one in gdb until I find the one I need, where thd variable is defined in some frame:
...
(gdb) thread 3
[Switching to thread 3 (Thread 0x7f7171fbc700 (LWP 2186))]#0  0x00007f71a4be3383 in poll () from /lib64/libc.so.6
(gdb) p do_command::thd->m_thread_id
$1 = 7
Local session variables are kept in the field called variables in the THD structure:
(gdb) p do_command::thd->variables
$2 = {dynamic_variables_version = 61,
  dynamic_variables_ptr = 0x7f717359c820 "\001", dynamic_variables_head = 384,
  dynamic_variables_size = 392, dynamic_variables_allocs = 0x7f71735f9040,
  max_heap_table_size = 16777216, tmp_table_size = 16777216,
  long_query_time = 0, end_markers_in_json = 0 '\000',
  optimizer_switch = 523711, optimizer_trace = 0,
  optimizer_trace_features = 15, optimizer_trace_offset = -1,
  optimizer_trace_limit = 1, optimizer_trace_max_mem_size = 16384,
  sql_mode = 1075838976, option_bits = 2147748608,
...

(gdb) p do_command::thd->variables->optimizer_switch
$3 = 523711
...
(gdb) p global_system_variables->optimizer_switch
$9 = 523775
Now, this is surely cool, but how to interpret the value I see, that must be some bitmask? I've printed the value of global variable also (it's in global_system_variables), so from comparing the values I can assume mrr setting is controlled by bit 64 in this bitmask. But we have to check this in the code.

Quick search with grep helps to find out that individual switches are defined in the sql/sql_const.h header file as follows:
/* @@optimizer_switch flags. These must be in sync with optimizer_switch_typelib */
#define OPTIMIZER_SWITCH_INDEX_MERGE               (1ULL << 0)
#define OPTIMIZER_SWITCH_INDEX_MERGE_UNION         (1ULL << 1)
#define OPTIMIZER_SWITCH_INDEX_MERGE_SORT_UNION    (1ULL << 2)
#define OPTIMIZER_SWITCH_INDEX_MERGE_INTERSECT     (1ULL << 3)
#define OPTIMIZER_SWITCH_ENGINE_CONDITION_PUSHDOWN (1ULL << 4)
#define OPTIMIZER_SWITCH_INDEX_CONDITION_PUSHDOWN  (1ULL << 5)
/** If this is off, MRR is never used. */
#define OPTIMIZER_SWITCH_MRR                       (1ULL << 6)/**
   If OPTIMIZER_SWITCH_MRR is on and this is on, MRR is used depending on a
   cost-based choice ("automatic"). If OPTIMIZER_SWITCH_MRR is on and this is
   off, MRR is "forced" (i.e. used as long as the storage engine is capable of
   doing it).
*/
#define OPTIMIZER_SWITCH_MRR_COST_BASED            (1ULL << 7)
#define OPTIMIZER_SWITCH_BNL                       (1ULL << 8)
#define OPTIMIZER_SWITCH_BKA                       (1ULL << 9)
#define OPTIMIZER_SWITCH_MATERIALIZATION           (1ULL << 10)
#define OPTIMIZER_SWITCH_SEMIJOIN                  (1ULL << 11)
#define OPTIMIZER_SWITCH_LOOSE_SCAN                (1ULL << 12)
#define OPTIMIZER_SWITCH_FIRSTMATCH                (1ULL << 13)
#define OPTIMIZER_SWITCH_DUPSWEEDOUT               (1ULL << 14)
#define OPTIMIZER_SWITCH_SUBQ_MAT_COST_BASED       (1ULL << 15)
#define OPTIMIZER_SWITCH_USE_INDEX_EXTENSIONS      (1ULL << 16)
#define OPTIMIZER_SWITCH_COND_FANOUT_FILTER        (1ULL << 17)
#define OPTIMIZER_SWITCH_DERIVED_MERGE             (1ULL << 18)
#define OPTIMIZER_SWITCH_LAST                      (1ULL << 19)
So, to check if at session level we have mrr set, we should do a bitwise AND with 1<<6:
(gdb) thread 7
[Switching to thread 7 (Thread 0x7f7171e77700 (LWP 2257))]#0  0x00007f71a4be3383 in poll () from /lib64/libc.so.6
(gdb) p do_command::thd->variables->optimizer_switch
$1 = 523775
(gdb) p do_command::thd->variables->optimizer_switch & (1 << 6)
$2 = 64
...
(gdb) p /t do_command::thd->variables->optimizer_switch
$6 = 1111111110111111111
Note that if you know bit positions for individual switches by heart printing with /t modifier may show you all bits set quickly.