perf Basics for MySQL Profiling

Oprofile was widely used for MySQL profiling on Linux in the past. But since 2010 and 2.6.31 Linux kernels another profiler, perf, gets increasing popularity. It uses performance counters (CPU hardware registers that count hardware events such as instructions executed) subsystem in Linux. perf is capable of lightweight profiling. It is included in the Linux kernel, under tools/perf (so features available depends on kernel version), and is frequently updated and enhanced.

So, probably perf is the future of profiling on Linux and it makes sense to discuss its basic usage for profiling MySQL servers. For detailed discussions of features provided, numerous examples (not related to MySQL) and links I suggest to read great posts by Brendan Gregg, starting from this one.

I am going to use Ubuntu 14.04 for this basic Howto, with the following perf version provided by the linux-tools-common package:

openxs@ao756:~/dbs/maria10.1$ perf --version
perf version 3.13.11-ckt39
openxs@ao756:~/dbs/maria10.1$ dpkg -S `which perf`
linux-tools-common: /usr/bin/perf

On RPM-based systems package name is just perf. I plan to discuss and show details of (other versions of) perf usage on CentOS 6.8 and Fedora 25 later.

I'll work with a bit outdated MariaDB 10.1.x (built from source) I have at hand up and running. In case of standard vendor's packages, make sure that you have debug symbols installed (perf will inform you if some are missing anyway), to get useful results:

openxs@ao756:~$ dpkg -l | grep -i percona | grep dbg
ii  percona-server-5.7-dbg                                5.7.16-10-1.trusty                                  amd64        Debugging package for Percona Server

Also, ideally binaries that you are profiling should be built with  -fno-omit-frame-pointer option.

As in the previous post about basic oprofile usage, I'll try to start with a primitive test case based on  Bug #39630, for simplicity and to establish basic trust in the tool's outputs, but this time I also want to try profiling some concurrent load more close to a real life, along the lines of Bug #83912.

Basic two(!) steps to use perf for studying some problematic period of MySQL server are the following:

1. Assuming the we want to get a profile of mysqld process during some problematic period, let's say in some script, we start recording samples for, let's say, 30 seconds, as a root user or via sudo:
   

   openxs@ao756:~/dbs/maria10.1$ sudo perf record -p `pidof mysqld` sleep 30
   [ perf record: Woken up 1 times to write data ]
   [ perf record: Captured and wrote 0.052 MB perf.data (~2257 samples) ]

2. Samples are collected in the perf.data file in the current directory by default:
   

   openxs@ao756:~/dbs/maria10.1$ ls -l perf.data-rw------- 1 root root 56768 січ 29 13:53 perf.data

   When collection completes we can get profiling information using perf report command. If you want to save the result into some file or just review it, add --stdio option. otherwise you end up in a text-based "interactive" user interface of perf, that, while can be useful, may be misleading and weird for beginners. For the 'select benchmark(500000000, 2*2) case I've got:
   

   openxs@ao756:~/dbs/maria10.1$ sudo perf report --stdio
   # ========
   # captured on: Sun Jan 29 14:01:24 2017
   # hostname : ao756
   # os release : 3.13.0-100-generic
   # perf version : 3.13.11-ckt39
   # arch : x86_64
   # nrcpus online : 2
   # nrcpus avail : 2
   # cpudesc : Intel(R) Pentium(R) CPU 987 @ 1.50GHz
   # cpuid : GenuineIntel,6,42,7
   # total memory : 3861452 kB
   # cmdline : /usr/lib/linux-tools-3.13.0-100/perf record -p 4270 sleep 30
   # event : name = cycles, type = 0, config = 0x0, config1 = 0x0, config2 = 0x0, e
   # HEADER_CPU_TOPOLOGY info available, use -I to display
   # HEADER_NUMA_TOPOLOGY info available, use -I to display
   # pmu mappings: cpu = 4, software = 1, tracepoint = 2, uncore_cbox_0 = 6, uncore
   # ========
   #
   # Samples: 248  of event 'cycles'
   # Event count (approx.): 24811349
   #
   # Overhead  Command       Shared Object
   # ........  .......  ..................  .......................................
   #
       11.60%   mysqld  [kernel.kallsyms]   [k] update_blocked_averages
        8.12%   mysqld  [kernel.kallsyms]   [k] update_cfs_rq_blocked_load
        6.98%   mysqld  [kernel.kallsyms]   [k] find_busiest_group
        5.76%   mysqld  [kernel.kallsyms]   [k] sys_io_getevents
        4.40%   mysqld  libc-2.19.so        [.] memset
        3.21%   mysqld  [kernel.kallsyms]   [k] update_curr
        3.03%   mysqld  [kernel.kallsyms]   [k] __calc_delta
        2.96%   mysqld  [kernel.kallsyms]   [k] put_prev_task_fair
        2.46%   mysqld  [kernel.kallsyms]   [k] timerqueue_add
        2.12%   mysqld  [kernel.kallsyms]   [k] cpumask_next_and
        2.11%   mysqld  libpthread-2.19.so  [.] __pthread_mutex_cond_lock     2.10%   mysqld  mysqld              [.] os_aio_linux_handle(unsigned long,
   ...
        1.09%   mysqld  mysqld              [.] buf_flush_lru_manager_thread
   ...

Now, the result above looks similar to and as suspicious as the result I've got with operf (that is also based on perf_events internally) on the same system and MariaDB version in the previous post. Everyone wonders where is the time spent on multiplication etc in the above? For operf (see my comment) I had found out that system-wide profiling gives expected results. It seems perf record -p pid also collects samples for single CPU (the one it runs on, or the one running that process actively, or just some one), and this is a problem for multi-threaded programs like mysqld if they are executed on multiple-core hardware (almost all hardware are like that these days, maybe some virtual machines aside). The solution is simple, add -a option for perf record:

       -a, --all-cpus
           System-wide collection from all CPUs.

and do not refer to mysqld, you can filter out related results later (for example, with  sudo perf report --stdio | grep mysqld | head -10, or interactively when --stdio option is not used). Like this:

openxs@ao756:~/dbs/maria10.1$ sudo perf record -a sleep 30
[ perf record: Woken up 15 times to write data ]
[ perf record: Captured and wrote 4.411 MB perf.data (~192717 samples) ]
openxs@ao756:~/dbs/maria10.1$ sudo perf report --stdio
# ========
# captured on: Sun Jan 29 14:27:31 2017
# hostname : ao756
# os release : 3.13.0-100-generic
# perf version : 3.13.11-ckt39
# arch : x86_64
# nrcpus online : 2
...
# Samples: 83K of event 'cycles'
# Event count (approx.): 30621323147
#
# Overhead          Command                  Shared Object
# ........  ...............  .............................  ............................................................................................................
#
    31.22%           mysqld  mysqld                         [.] Item_func_mul::int_op()    16.57%           mysqld  mysqld                         [.] Item_func_hybrid_field_type::val_int()
    16.51%           mysqld  mysqld                         [.] Item_hybrid_func::result_type() const
    16.11%           mysqld  mysqld                         [.] Item_func_benchmark::val_int()     9.92%           mysqld  mysqld                         [.] Item_int::val_int()
     3.27%           mysqld  mysqld                         [.] Type_handler_int_result::cmp_type() const
     3.25%           mysqld  mysqld                         [.] Type_handler_int_result::result_type() const
     0.27%      kworker/0:2  [kernel.kallsyms]              [k] aes_encrypt
     0.18%           compiz  i965_dri.so                    [.] 0x00000000000def10
     0.14%          swapper  [kernel.kallsyms]              [k] intel_idle
...

So, system-wide profile provides the information we can trust, even on multi-core systems for multi-threaded programs. If you know some other way, less intrusive way to get profiles that do not miss the details from threads running on other cores, please, tell me. I was NOT able to find it quickly.

By the way, nice interactive perf top command shows expected results as well when this primitive test runs (it is still a system-wide profile):

Samples: 17K of event 'cycles', Event count (approx.): 5061557268
 28,29%  mysqld                         [.] Item_func_mul::int_op()
 15,05%  mysqld                         [.] Item_func_benchmark::val_int()
 15,01%  mysqld                         [.] Item_hybrid_func::result_type() cons
 15,01%  mysqld                         [.] Item_func_hybrid_field_type::val_int
  9,12%  mysqld                         [.] Item_int::val_int()
  3,34%  perf                           [.] 0x00000000000564db
  3,18%  mysqld                         [.] Type_handler_int_result::cmp_type()
  2,93%  mysqld                         [.] Type_handler_int_result::result_type
  0,96%  libc-2.19.so                   [.] __strstr_sse2
  0,61%  libc-2.19.so                   [.] __GI___strcmp_ssse3
  0,24%  [kernel]                       [k] kallsyms_expand_symbol.constprop.1
  0,21%  [kernel]                       [k] module_get_kallsym
  0,20%  libc-2.19.so                   [.] _int_malloc
  0,20%  libharfbuzz.so.0.927.0         [.] 0x0000000000028051
  0,19%  i965_dri.so                    [.] 0x000000000010a9a0
  0,18%  [kernel]                       [k] format_decode
  0,16%  [kernel]                       [k] vsnprintf
  0,15%  libc-2.19.so                   [.] memchr
  0,15%  libc-2.19.so                   [.] __strchr_sse2
  0,14%  [kernel]                       [k] number.isra.1
  0,13%  [kernel]                       [k] memcpy
  0,09%  libc-2.19.so                   [.] strlen
Press '?' for help on key bindings

Press 'q' to get out of that screen.

perf record may be also used the same way as operf, run in foreground and be interrupted with Ctrl-C (examples are from my last night's session on CentOS):

[root@centos ~]# perf record -ag
^C[ perf record: Woken up 63 times to write data ]
[ perf record: Captured and wrote 15.702 MB perf.data (226643 samples) ]

or it can be started in the background and then interrupted with -SIGINT signal sent to the process:

[root@centos ~]# perf record -ag &[1] 2353
[root@centos ~]# mysql -uroot -e'select benchmark(500000000,2*2);' test
+--------------------------+
| benchmark(500000000,2*2) |
+--------------------------+
|                        0 |
+--------------------------+
[root@centos ~]# kill -sigint  2353[ perf record: Woken up 90 times to write data ]
[root@centos ~]# [ perf record: Captured and wrote 22.366 MB perf.data (322362 samples) ]

[1]+  Interrupt               perf record -ag
[root@centos ~]# ps aux | grep perf
root      2358  0.0  0.0 103312   864 pts/0    S+   22:16   0:00 grep perf

You've probably noted additional -g option in the examples above (explanation pasted from perf help record/man perf-record output):

       -g
           Enables call-graph (stack chain/backtrace) recording.

Another option often used is -F (like -F99 or -F1000):

       -F, --freq=
           Profile at this frequency.

For select benchmark(500000000, 2*2) case -g does not show anything really unexpected or enlightening:

openxs@ao756:~/dbs/maria10.1$ sudo perf record -ag sleep 30
[sudo] password for openxs:
[ perf record: Woken up 64 times to write data ]
[ perf record: Captured and wrote 16.496 MB perf.data (~720730 samples) ]
openxs@ao756:~/dbs/maria10.1$ sudo perf report --stdio
...
# Overhead          Command                  Shared Object
# ........  ...............  .............................  ............................................................................................................
#
    31.02%           mysqld  mysqld                         [.] Item_func_mul::int_op()
                     |
                     --- Item_func_mul::int_op()
                        |
                        |--94.56%-- Item_func_hybrid_field_type::val_int()
                        |          Item_func_benchmark::val_int()
                        |          Item::send(Protocol*, String*)
                        |          Protocol::send_result_set_row(List<Item>*)
                        |          select_send::send_data(List<Item>&)
                        |          JOIN::exec_inner()
                        |          JOIN::exec()
                        |          mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsi
                        |          handle_select(THD*, LEX*, select_result*, unsigned long)
                        |          execute_sqlcom_select(THD*, TABLE_LIST*)
                        |          mysql_execute_command(THD*)
                        |          mysql_parse(THD*, char*, unsigned int, Parser_state*)
                        |          dispatch_command(enum_server_command, THD*, char*, unsigned int)
                        |          do_command(THD*)
                        |          do_handle_one_connection(THD*)
                        |          handle_one_connection
                        |          start_thread
                        |
                         --5.44%-- Item_func_benchmark::val_int()
                                   Item::send(Protocol*, String*)
                                   Protocol::send_result_set_row(List<Item>*)
                                   select_send::send_data(List<Item>&)
                                   JOIN::exec_inner()
                                   JOIN::exec()
                                   mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsi
                                   handle_select(THD*, LEX*, select_result*, unsigned long)
                                   execute_sqlcom_select(THD*, TABLE_LIST*)
                                   mysql_execute_command(THD*)
                                   mysql_parse(THD*, char*, unsigned int, Parser_state*)
                                   dispatch_command(enum_server_command, THD*, char*, unsigned int)
                                   do_command(THD*)
                                   do_handle_one_connection(THD*)
                                   handle_one_connection
                                   start_thread
...

But we clearly see backtraces/callgraphs.

Note that this tree starts with the on-CPU functions and works back through the ancestry. This approach is called a "callee based call graph". This can be flipped by using -G for an "inverted call graph", or by using the caller option to -g/--call-graph, instead of the callee default. The hottest (most frequent) stack trace in this perf call graph occurred in 29.33% of samples, which is the product of the overhead percentage and top stack leaf (31.02%*94.56%, which are relative rates). perf report can also be run with "-g graph" to show absolute overhead rates

I'd like to conclude this blog post with profiling system running test load presented in Bug #83912 (that, in turn, is just one of the observations based on a very complex real life performance problem I am still working on). There we run N+2 long running UPDATEs on N+2 different tables on a system with N cores. While UPDATEs run, sometimes SELECT asking for a single record by PRIMARY KEY for a different table may sometimes run slow, for fractions of second to many seconds.

So, with table to select from, t0, and other 4 (N+2, N=2 on my netbook used for testing) tables to update, t1 ... t4, created:

openxs@ao756:~/dbs/maria10.1$ bin/mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 21
Server version: 10.1.18-MariaDB MariaDB Server

Copyright (c) 2000, 2016, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [test]> select count(*) from t0;
+----------+
| count(*) |
+----------+
|  2097152 |
+----------+
1 row in set (9.33 sec)

MariaDB [test]> select * from t0 where id = 13;
+----+------+----------------------+
| id | c1   | c2                   |
+----+------+----------------------+
| 13 |  269 | 0.008545639932663777 |
+----+------+----------------------+
1 row in set (0.00 sec)

MariaDB [test]> show table status like 't1'\G
*************************** 1. row ***************************
           Name: t1
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 2079632
 Avg_row_length: 139
    Data_length: 289177600
Max_data_length: 0
   Index_length: 0
      Data_free: 6291456
 Auto_increment: 2424797
    Create_time: 2017-01-29 12:31:57
    Update_time: NULL
     Check_time: NULL
      Collation: latin1_swedish_ci
       Checksum: NULL
 Create_options: stats_persistent=1
        Comment:
1 row in set (0.11 sec)

MariaDB [test]> explain select * from t0 where id = 13;
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------+
| id   | select_type | table | type  | possible_keys | key     | key_len | ref   | rows | Extra |
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------+
|    1 | SIMPLE      | t0    | const | PRIMARY       | PRIMARY | 4       | const |    1 |       |
+------+-------------+-------+-------+---------------+---------+---------+-------+------+-------+
1 row in set (0.00 sec)

MariaDB [test]> explain update t1 set c2 = rand() where id between 2000 and 300000;
+------+-------------+-------+-------+---------------+---------+---------+------+--------+-------------+
| id   | select_type | table | type  | possible_keys | key     | key_len | ref  | rows   | Extra       |
+------+-------------+-------+-------+---------------+---------+---------+------+--------+-------------+
|    1 | SIMPLE      | t1    | range | PRIMARY       | PRIMARY | 4       | NULL | 339246 | Using where |
+------+-------------+-------+-------+---------------+---------+---------+------+--------+-------------+
1 row in set (0.00 sec)

I've started 4 (N+2) threads each updating large part of one of the tables:

openxs@ao756:~/dbs/maria10.1$ for i in `seq 1 4`; do bin/mysqlslap -uroot --no-drop --create-schema=test --number-of-queries=1000 iternations=10 --concurrency=1 --query="update t$i set c2 = rand() where id between 2000 and 300000;" & done
[1] 15513
[2] 15514
[3] 15515
[4] 15516

In the SHOW PROCESSLIST we see:

...

| 26 | root | localhost | test | Query   |   10 | updating | update t2 set c2 = rand() where id between 2000 and 300000 |    0.000 |
| 27 | root | localhost | test | Query   |   32 | updating | update t1 set c2 = rand() where id between 2000 and 300000 |    0.000 |
| 28 | root | localhost | test | Query   |    5 | updating | update t4 set c2 = rand() where id between 2000 and 300000 |    0.000 |
| 29 | root | localhost | test | Query   |   11 | updating | update t3 set c2 = rand() where id between 2000 and 300000 |    0.000 |
...

Let's see with perf what these threads are doing, so they spend 29 seconds in updating status. First without -g:

openxs@ao756:~/dbs/maria10.1$ sudo perf record -a sleep 30[sudo] password for openxs:
[ perf record: Woken up 15 times to write data ]
[ perf record: Captured and wrote 4.260 MB perf.data (~186128 samples) ]
openxs@ao756:~/dbs/maria10.1$ sudo perf report --stdio
...
# Overhead          Command                  Shared Object
# ........  ...............  .............................  ............................................................................................................
#
    12.50%      kworker/0:1  [kernel.kallsyms]              [k] aes_encrypt    10.54%      kworker/1:1  [kernel.kallsyms]              [k] aes_encrypt
     9.77%      kworker/1:2  [kernel.kallsyms]              [k] aes_encrypt
     4.81%      kworker/0:0  [kernel.kallsyms]              [k] aes_encrypt
     4.52%           mysqld  mysqld                         [.] buf_calc_page_new_checksum(unsigned char const*)     3.64%           mysqld  mysqld                         [.] log_block_calc_checksum_innodb(unsigned char const*)
     2.22%           mysqld  mysqld                         [.] dtoa.constprop.6
     2.15%           mysqld  mysqld                         [.] trx_undo_report_row_operation(unsigned long, unsigned long, que_thr_t*, dict_index_t*, dtuple_t const*,
     2.10%           mysqld  mysqld                         [.] quorem
     1.78%           mysqld  mysqld                         [.] mtr_commit(mtr_t*)
     1.41%           mysqld  mysqld                         [.] ha_innobase::update_row(unsigned char const*, unsigned char*)
     1.15%           mysqld  mysqld                         [.] buf_page_optimistic_get(unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*)
     1.15%           mysqld  mysqld                         [.] buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long
     1.11%           mysqld  mysqld                         [.] row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
     1.10%           mysqld  mysqld                         [.] multadd
...

I am not surprised to see aes_encrypt in kernel on top of this system-wide profile, as encrupted HDD is used on this netbook (one of Percona security requirements for any hardware ever used for work, even personal) and upodates are surely I/O bound with mysqld --no-defaults and 128M of buffer pool.

We may want to study some of mysqld-related entries further with callgraphs generated (-g):

openxs@ao756:~/dbs/maria10.1$ sudo perf record -ag sleep 20
[ perf record: Woken up 31 times to write data ]
[ perf record: Captured and wrote 8.313 MB perf.data (~363186 samples) ]
openxs@ao756:~/dbs/maria10.1$ sudo perf report --stdio
...
     4.29%           mysqld  mysqld                         [.] buf_calc_page_new_checksum(unsigned char const*)
                     |
                     --- buf_calc_page_new_checksum(unsigned char const*)
                        |
                        |--67.15%-- buf_flush_init_for_writing(unsigned char*, void*, unsigned long)
                        |          buf_flush_page(buf_pool_t*, buf_page_t*, buf_flush_t, bool)
                        |          buf_flush_try_neighbors(unsigned long, unsigned long, buf_flush_t, unsigned long, unsigned long)
                        |          |
                        |          |--52.15%-- buf_do_flush_list_batch(buf_pool_t*, unsigned long, unsigned long)
                        |          |          buf_flush_list(unsigned long, unsigned long, unsigned long*)
                        |          |          buf_flush_page_cleaner_thread
                        |          |          start_thread
                        |          |
                        |           --47.85%-- buf_flush_LRU_list_batch(buf_pool_t*, unsigned long, bool, flush_counters_t*)
                        |                     buf_flush_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, bool, flush_counters_t*)
                        |                     buf_flush_LRU_tail()
                        |                     buf_flush_lru_manager_thread
                        |                     start_thread
                        |
                         --32.85%-- buf_page_is_corrupted(bool, unsigned char const*, unsigned long)
                                   buf_page_io_complete(buf_page_t*)
                                   |
                                   |--82.17%-- fil_aio_wait(unsigned long)
                                   |          io_handler_thread
                                   |          start_thread
                                   |
                                    --17.83%-- buf_read_page(unsigned long, unsigned long, unsigned long, trx_t*, buf_page_t**)
                                              buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, uns
                                              |
                                              |--92.31%-- btr_pcur_move_to_next_page(btr_pcur_t*, mtr_t*)
                                              |          btr_pcur_move_to_next(btr_pcur_t*, mtr_t*)
                                              |          row_search_for_mysql(unsigned char*, unsigned long, row_prebuilt_t*, unsigned long, unsigned long)
                                              |          ha_innobase::index_next(unsigned char*)
                                              |          handler::ha_index_next(unsigned char*)
                                              |          handler::read_range_next()
                                              |          handler::multi_range_read_next(void**)
                                              |          Mrr_simple_index_reader::get_next(void**)
                                              |          DsMrr_impl::dsmrr_next(void**)
                                              |          QUICK_RANGE_SELECT::get_next()
                                              |          rr_quick(READ_RECORD*)
                                              |          mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, e
                                              |          mysql_execute_command(THD*)
                                              |          mysql_parse(THD*, char*, unsigned int, Parser_state*)
                                              |          dispatch_command(enum_server_command, THD*, char*, unsigned int)
                                              |          do_command(THD*)
                                              |          do_handle_one_connection(THD*)
                                              |          handle_one_connection
                                              |          start_thread
                                              |
                                              |--5.37%-- btr_estimate_n_rows_in_range(dict_index_t*, dtuple_t const*, unsigned long, dtuple_t const*, unsigned long, trx
                                              |          ha_innobase::records_in_range(unsigned int, st_key_range*, st_key_range*)
                                              |          handler::multi_range_read_info_const(unsigned int, st_range_seq_if*, void*, unsigned int, unsigned int*, unsign
                                              |          DsMrr_impl::dsmrr_info_const(unsigned int, st_range_seq_if*, void*, unsigned int, unsigned int*, unsigned int*,
                                              |          check_quick_select(PARAM*, unsigned int, bool, SEL_ARG*, bool, unsigned int*, unsigned int*, Cost_estimate*)
                                              |          get_key_scans_params(PARAM*, SEL_TREE*, bool, bool, double)
                                              |          SQL_SELECT::test_quick_select(THD*, Bitmap<64u>, unsigned long long, unsigned long long, bool, bool, bool)
                                              |          mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, e
                                              |          mysql_execute_command(THD*)
                                              |          mysql_parse(THD*, char*, unsigned int, Parser_state*)
                                              |          dispatch_command(enum_server_command, THD*, char*, unsigned int)
                                              |          do_command(THD*)
                                              |          do_handle_one_connection(THD*)
                                              |          handle_one_connection
                                              |          start_thread
...
     1.28%           mysqld  mysqld                         [.] ha_innobase::update_row(unsigned char const*, unsigned char*)
                     |
                     --- ha_innobase::update_row(unsigned char const*, unsigned char*)
                        |
                        |--97.71%-- handler::ha_update_row(unsigned char const*, unsigned char*)
                        |          mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, enum_duplicates, bool,
                        |          mysql_execute_command(THD*)
                        |          mysql_parse(THD*, char*, unsigned int, Parser_state*)
                        |          dispatch_command(enum_server_command, THD*, char*, unsigned int)
                        |          do_command(THD*)
                        |          do_handle_one_connection(THD*)
                        |          handle_one_connection
                        |          start_thread                        |
                         --2.29%-- mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned int, st_order*, unsigned long long, enum_duplicates, bool,
                                   mysql_execute_command(THD*)
                                   mysql_parse(THD*, char*, unsigned int, Parser_state*)
                                   dispatch_command(enum_server_command, THD*, char*, unsigned int)
                                   do_command(THD*)
                                   do_handle_one_connection(THD*)
                                   handle_one_connection
                                   start_thread
...

Now to the interesting part (slow UPDATEs when I/O bound are expected). Usually (but not always, in original real life case!) simple SELECT runs fast, but if we limit innodb_thread_concurrency to, say, 4, it may start to run slow:

MariaDB [test]> select * from t0 where id = 13;
+----+------+----------------------+
| id | c1   | c2                   |
+----+------+----------------------+
| 13 |  269 | 0.008545639932663777 |
+----+------+----------------------+
1 row in set (0.00 sec)

MariaDB [test]> select @@innodb_thread_concurrency;
+-----------------------------+
| @@innodb_thread_concurrency |
+-----------------------------+
|                           0 |
+-----------------------------+
1 row in set (0.05 sec)

MariaDB [test]> set global innodb_thread_concurrency=4;
Query OK, 0 rows affected (0.25 sec)

MariaDB [test]> select * from t0 where id = 13;
+----+------+----------------------+
| id | c1   | c2                   |
+----+------+----------------------+
| 13 |  269 | 0.008545639932663777 |
+----+------+----------------------+
1 row in set (2.92 sec)

MariaDB [test]> select * from t0 where id = 13;
+----+------+----------------------+
| id | c1   | c2                   |
+----+------+----------------------+
| 13 |  269 | 0.008545639932663777 |
+----+------+----------------------+
1 row in set (12.16 sec)

Profile with callgraph may help to find out why this happens:

openxs@ao756:~/dbs/maria10.1$ sudo perf record -ag sleep 20
[ perf record: Woken up 32 times to write data ]
[ perf record: Captured and wrote 8.503 MB perf.data (~371488 samples) ]
openxs@ao756:~/dbs/maria10.1$ sudo perf report --stdio
...

                        |--1.40%-- sys_select
                        |          system_call_fastpath
                        |          __select
                        |          |
                        |          |--71.70%-- srv_conc_enter_innodb(trx_t*)
                        |          |          ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)
                        |          |          handler::index_read_idx_map(unsigned char*, unsigned int, unsigned char const*, unsigned long, ha_rkey_function)
                        |          |          handler::ha_index_read_idx_map(unsigned char*, unsigned int, unsigned char const*, unsigned long, ha_rkey_function)
                        |          |          join_read_const(st_join_table*)
                        |          |          join_read_const_table(THD*, st_join_table*, st_position*) [clone .isra.301]
                        |          |          make_join_statistics(JOIN*, List<TABLE_LIST>&, st_dynamic_array*)
                        |          |          JOIN::optimize_inner()
                        |          |          JOIN::optimize()
                        |          |          mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_o                        |          |          handle_select(THD*, LEX*, select_result*, unsigned long)
                        |          |          execute_sqlcom_select(THD*, TABLE_LIST*)
                        |          |          mysql_execute_command(THD*)
                        |          |          mysql_parse(THD*, char*, unsigned int, Parser_state*)
                        |          |          dispatch_command(enum_server_command, THD*, char*, unsigned int)
                        |          |          do_command(THD*)
                        |          |          do_handle_one_connection(THD*)
                        |          |          handle_one_connection
                        |          |          start_thread
...

It spends 71.7% of time waiting to join InnoDB queue (in this limited InnoDB concurrency case) while diving into the index while optimizing the query... This time is spent on "statistics" stage, for single row SELECT by PRIMARY KEY. Now, go conclude this without a backtrace of calls or some profiler.

oprofile Basics for MySQL Profiling

In my previous post I've presented a list of bugs reported by famous MySQL developers, DBAs, users and support engineers who used oprofile to find the problem or root cause of the problem they studied. I assume that some of my readers would like to follow their steps and try to use this tool while working on MySQL performance problems. Bug reports I mentioned contain outputs and, rarely, just some commands used. That's why I decided to write a kind of a basic "Howto" document. The tool does have a detailed enough manual, but few basic steps for quick use of oprofile to study MySQL-related problems should still help. At least I had always considered this old post by Oli a useful reference for myself and Googled for it more than once.

These days users of oprofile may need an updated quick reference or Howto guide, as starting from version 0.9.8 the tool started to change, new commands were introduced and, starting from version 1.0.0, familiar commands like opcontrol are not only deprecated, but removed from the tool (and it means that pt-stalk's --collect-oprofile option just does not work any more). For this post I decided to use version 0.9.9 on my good old Ubuntu 14.04 netbook. This should, theoretically, allow me to demonstrate both "old" and "new" way to use the tool.

So, I am using the following system for the purposes of this blog post:

openxs@ao756:~/dbs/maria10.1$ uname -a
Linux ao756 3.13.0-100-generic #147-Ubuntu SMP Tue Oct 18 16:48:51 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
openxs@ao756:~/dbs/maria10.1$ cat /etc/issueUbuntu 14.04.5 LTS \n \l

openxs@ao756:~/dbs/maria10.1$ dpkg -l | grep -i oprofile
ii  oprofile                                              0.9.9-0ubuntu8                                      amd64        system-wide profiler for Linux systems
openxs@ao756:~/dbs/maria10.1$ bin/mysql -uroot -e"show variables like '%version%'"
+-------------------------+------------------+
| Variable_name           | Value            |
+-------------------------+------------------+
| innodb_version          | 5.6.31-77.0      |
| protocol_version        | 10               |
| slave_type_conversions  |                  |
| version                 | 10.1.18-MariaDB  |
| version_comment         | MariaDB Server   |
| version_compile_machine | x86_64           |
| version_compile_os      | Linux            |
| version_malloc_library  | bundled jemalloc |
| version_ssl_library     | YaSSL 2.3.9b     |
| wsrep_patch_version     | wsrep_25.16      |
+-------------------------+------------------+
openxs@ao756:~/dbs/maria10.1$ ps aux | grep mysqld
openxs   25568  0.0  0.0   4440   784 pts/10   S    19:00   0:00 /bin/sh bin/mysqld_safe --no-defaults
openxs   25631  1.1  2.4 751552 93596 pts/10   Sl   19:00   0:22 /home/openxs/dbs/maria10.1/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/maria10.1 --datadir=/home/openxs/dbs/maria10.1/data --plugin-dir=/home/openxs/dbs/maria10.1/lib/plugin --log-error=/home/openxs/dbs/maria10.1/data/ao756.err --pid-file=ao756.pid
openxs   26158  0.0  0.0  14636   968 pts/10   S+   19:31   0:00 grep --color=auto mysqld

I assume you already have the oprofile package installed. I use MariaDB 10.1.18 built from source on this box (I work for MariaDB after all).

Basic steps to use the tool for studying some problematic period of MySQL server are the following:

1. We check version used and, if we want to use older version of the tool and daemon-based approach, we initiate and start the process of samples collection using opcontrol tool:
   
   openxs@ao756:~/dbs/maria10.1$ opcontrol --version
   opcontrol: oprofile 0.9.9 compiled on Apr  4 2014 23:34:07
   openxs@ao756:~/dbs/maria10.1$ opcontrol --init
   Kernel support not available, missing opcontrol --init as root ?
   openxs@ao756:~/dbs/maria10.1$ sudo opcontrol --init
   [sudo] password for openxs:
   openxs@ao756:~/dbs/maria10.1$ sudo opcontrol --start --no-vmlinux
   ATTENTION: Use of opcontrol is discouraged.  Please see the man page for operf.
   Using default event: CPU_CLK_UNHALTED:100000:0:1:1
   Using 2.6+ OProfile kernel interface.
   Using log file /var/lib/oprofile/samples/oprofiled.log
   Daemon started.
   Profiler running.
   
   Note that superuser permissions are needed for most opcontrol commands. I've added --no-vmlinux command as I do not want to profile the kernel itself.
   
2. Now we can run with samples collection activated for some time, until the period we want to study ends. For this post I use a primitive single thread "benchmark" test from the Bug #39630 I once reported and worked on for a long time:
   
   openxs@ao756:~/dbs/maria10.1$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)'
   +---------------------------+
   | benchmark(500000000, 2*2) |
   +---------------------------+
   |                         0 |
   +---------------------------+
   
   real    0m20.209s
   user    0m0.009s
   sys     0m0.004s
   
   This was a deliberately very simple use case to study, just to check that we get meaningful and expected outputs.
   
3. When the period we want to study ends, we should stop collecting samples and dump the results:
   
   openxs@ao756:~/dbs/maria10.1$ sudo opcontrol --stop
   Stopping profiling.
   openxs@ao756:~/dbs/maria10.1$ sudo opcontrol --dump
   openxs@ao756:~/dbs/maria10.1$
   
   Theoretically we can have several sample-collecting "sessions" that we can save under unique "names" etc, but for now I want to concentrate on the most basic usage.
   
4. Now we have to use opreport tool to check the results:
   
   openxs@ao756:~/dbs/maria10.1$ sudo opreport --demangle=smart --symbols --merge tgid `pwd`/bin/mysqld | head -12
   Using /var/lib/oprofile/samples/ for samples directory.
   warning: /no-vmlinux could not be found.
   warning: [vdso] (tgid:25631 range:0x7ffc6fac3000-0x7ffc6fac5000) could not be found.
   CPU: Intel Sandy Bridge microarchitecture, speed 1.5e+06 MHz (estimated)
   Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
   samples  %        image name               symbol name
   83358    28.0632  mysqld                   Item_func_mul::int_op()
   58838    19.8083  mysqld                   Item_func_benchmark::val_int()
   55420    18.6576  mysqld                   Item_hybrid_func::result_type() const
   52001    17.5066  mysqld                   Item_func_hybrid_field_type::val_int()
   25931     8.7299  mysqld                   Item_int::val_int()
   10861     3.6564  mysqld                   Type_handler_int_result::cmp_type() const
   10104     3.4016  mysqld                   Type_handler_int_result::result_type() const
   460       0.1549  no-vmlinux               /no-vmlinux
   12        0.0040  mysqld                   sync_array_print_long_waits(unsigned long*, void const**)
   openxs@ao756:~/dbs/maria10.1$
   
   We provided --symbols option to list per-symbol information instead of a binary image summary, --demangle=smart option to get readable names of C++ functions, and --merge tgid option to merge profiles by thread group ID (for all threads of the same multi-threaded process, like mysqld). We also had to provide a full path to the mysqld binary to restrict symbol summary only to the specific executable image, mysqld process from MariaDB 10.1.18.When mysqld from PATH or just from some standard package is used, $(which mysqld) is used instead in the command line.

Basically that's all, we clearly see that most of the time was spent on integers multiplication (as one had to expect). We may have to use --deinit, --reset or --shutdown options of opcontrol if we do not plan any further profiling.

Now, what if we use oprofile version 1.0.0 or newer (as it happened to me on Fedora 25 or Ubuntu 16.04)? opcontrol tool just does not exist then, as well as oprofiled daemon I see running now:


openxs@ao756:~/dbs/maria10.1$ ps aux | grep oprofiled
root     27281  0.0  0.2  14036  7852 ?        S    20:22   0:00 /usr/bin/oprofiled --session-dir=/var/lib/oprofile --separate-lib=1 --separate-kernel=1 --separate-thread=1 --separate-cpu=0 --events=CPU_CLK_UNHALTED:60:0:100000:0:1:1, --no-vmlinux
openxs   27446  0.0  0.0  14636   972 pts/10   S+   20:41   0:00 grep --color=auto oprofiled
openxs@ao756:~/dbs/maria10.1$


Basic steps are the following, based on operf tool (surely without oprofiled running):

openxs@ao756:~/dbs/maria10.1$ operf -p `pidof mysqld` &
[2] 4359
openxs@ao756:~/dbs/maria10.1$ operf: Press Ctl-c or 'kill -SIGINT 4359' to stop profiling
operf: Profiler started

openxs@ao756:~/dbs/maria10.1$ time bin/mysql -uroot -e'select benchmark(500000000, 2*2)'
+---------------------------+
| benchmark(500000000, 2*2) |
+---------------------------+
|                         0 |
+---------------------------+

real    0m19.772s
user    0m0.006s
sys     0m0.005s
openxs@ao756:~/dbs/maria10.1$ kill -SIGINT 4359
openxs@ao756:~/dbs/maria10.1$
Profiling done.

[2]+  Done                    operf -p `pidof mysqld`
openxs@ao756:~/dbs/maria10.1$ opreport --demangle=smart --symbols --merge tgid /home/openxs/dbs/maria10.1/bin/mysqld
Using /home/openxs/dbs/maria10.1/oprofile_data/samples/ for samples directory.
warning: /no-vmlinux could not be found.
warning: [vdso] (tgid:4270 range:0x7ffebbf38000-0x7ffebbf39fff) could not be found.
CPU: Intel Sandy Bridge microarchitecture, speed 1.5e+06 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted) with a unit mask of 0x00 (No unit mask) count 100000
samples  %        image name               symbol name
132      70.5882  no-vmlinux               /no-vmlinux
13        6.9519  libc-2.19.so             memset
10        5.3476  mysqld                   os_aio_linux_handle(unsigned long, fil_node_t**, void**, unsigned long*, unsigned long*)
9         4.8128  mysqld                   sync_array_print_long_waits(unsigned long*, void const**)
3         1.6043  libpthread-2.19.so       __pthread_mutex_cond_lock
2         1.0695  libpthread-2.19.so       pthread_self
2         1.0695  mysqld                   btr_defragment_thread
2         1.0695  mysqld                   srv_error_monitor_thread
1         0.5348  [vdso] (tgid:4270 range:0x7ffebbf38000-0x7ffebbf39fff) [vdso] (tgid:4270 range:0x7ffebbf38000-0x7ffebbf39fff)
1         0.5348  libaio.so.1.0.1          /lib/x86_64-linux-gnu/libaio.so.1.0.1
1         0.5348  libc-2.19.so             __libc_disable_asynccancel
1         0.5348  libc-2.19.so             __select_nocancel
1         0.5348  libc-2.19.so             fflush
1         0.5348  libpthread-2.19.so       pthread_cond_timedwait@@GLIBC_2.3.2
1         0.5348  mysqld                   buf_flush_page_cleaner_thread
1         0.5348  mysqld                   buf_pool_get_oldest_modification()
1         0.5348  mysqld                   log_checkpoint(unsigned long, unsigned long, unsigned long)
1         0.5348  mysqld                   mutex_enter_nowait_func(ib_mutex_t*, char const*, unsigned long)
1         0.5348  mysqld                   srv_check_activity(unsigned long, unsigned long)
1         0.5348  mysqld                   srv_master_evict_from_table_cache(unsigned long)
1         0.5348  mysqld                   srv_master_thread
1         0.5348  mysqld                   ut_delay(unsigned long)
openxs@ao756:~/dbs/maria10.1$

Note that, theoretically, operf allows to profile separate commands or user's own process (as I did with -p `pidof mysqld` option) as non-privileged user. I had not used sudo above. Also, we just need one command now and running operf is stopped with -SIGINT signal when we are done with profiling.

The results I've got from opreport in this case, though, do not look 100% trustful to me though. Not because of that warning from [vdso], we had similar (although for other addresses) with classic approach as well (and you can find some related information in the FAQ), but because I see totally different profile than before under basically the same load. I see activity by background functions, but nothing related to multiplication of integers or benhcmark() function. This is suspicious and, until further tests on Fedora 25, I'd prefer NOT to trust to operf from oprofile version 0.9.9 on Ubuntu 14.04...

Next I plan to check how operf in the latest oprofile version works on Fedora 25 and (maybe) Ubuntu 16.04, apply profiler to a more interesting use case(s), show more options including --callgraph option, and try to compare recent oprofile to perf profiler (that I currently trust more and find somewhat easier to use for MySQL-related tasks). Stay tuned!

Fun with Bugs #47 - On Some Bugs Found Using oprofile

Users had to identify the reasons for MySQL performance problems somehow well before famous Performance Schema appeared in MySQL 5.5.3, and even before Domas invented his Poor Man's Profiler. Poor users had to use some OS-level tools, and among these tools the most important one was, probably, oprofile.

oprofile is a system-wide statistical profiling tool for Linux available since 2001 and 2.4.x kernels. It was applied to MySQL for many years and allowed to find and explain many performance problems. We even have the --collect-oprofile option for pt-stalk tool, and it's a common knowledge that Percona Toolkit includes tools and options that are proved to be useful for real life problems more than once... So, we can safely assume that oprofile is (or, at least, was) an essential tool for MySQL performance problem solving.

For this post I decided to check and pick up some of MySQL bugs identified or verified with a little help from oprofile. Here is the list of most important ones (from my point of view), starting from the oldest:

• Bug #29921 - "MYSQLparse uses 3X more CPU in MySQL 5.0 than yyparse in MySQL 4.0". It was reported by Mark Callaghan and eventually fixed (to large extent) in versions 5.0.50 and 5.1.23. While gprof was used by developers for further analysis, the reason for performance repression was demonstrated and proved with oprofile.
• Bug #31551 - "MyISAM poor performance with multiple queries running concurrently". Reported by Vadim Tkachenko back in 2007, this bug (that is essentially about key cache mutex contention problem, that was demonstrated using oprofile) is still "Verified". Nobody seems to care to fix it, and as a workaround one may have to use multiple key caches in concurrent environment.
• Bug #33948 - "performance issue when using sysbench benchmark on a multiple-core system". It was reported by Terry Tao, who found it using oprofile:
  

  "Used oprofile to trace it then found it spended more time on searching a free table entry from open_cache. "

  and suggested a patch, but the real solution based on the patch was made in frames of work on several worklogs in 5.4 (and 5.5.x) related to LOCK_open and Metadata Locks.
• Bug #43161 - "buf_calc_page_new_checksum and ut_2_power_up use a lot of CPU on busy IO loads". It was reported by Mark Callaghan and later claimed a duplicate of his Bug #54814. Sveta Smirnova verified it using oprofile. The fix was contributed by Laurynas Biveinis for 5.6 and appeared only in MySQL 5.7.4.
• Bug #44723 - "Larger read_buffer_size values can cause performance decrease for INSERTs", was reported by Harrison Fisk, who used oprofile on Linux to demonstrate the problem. The bug is fixed since MySQL 5.0.86, 5.1.39, and 5.4.4.
• Bug #49047 - "InnoDB deadlock detection is CPU intensive with many locks on a single row". It was reported by Harrison Fisk and was partially fixed based on the patch he suggested in the InnoDB Plugin for MySQL 5.1 (available after 5.1.50 or so), and in MySQL 5.5. But note that innodb_deadlock_detect server variable was added recently (in MySQL 5.7.15!) to disable deadlock detection entirely. oprofile (along with DTrace) was used to identify the bug.
• Bug #49169 - "read_view_open_now is inefficient with many concurrent sessions", was reported by Mark Callaghan. oprofile helped to find out that a lot of time is spent in this function. The bug is closed as "It was fixed as part of the kernel mutex split in 5.6.", but check last comments for some discussion of what was and was not fixed.
• Bug #49177 - "MyISAM share list scalability problems". This bug was reported by Sergei Golubchik. Alexey Stroganov later posted a detailed analysis based on oprofile outputs, among other things. The bug was completely fixed only recently, in MySQL 5.7.9+ and MySQL 8.0.
• Bug #53825 - "Removing locks from queue is very CPU intensive with many locks", was reported by Harrison Fisk. It is still "Verified" and thus, probably is not fixed. Note that it may become serious bottleneck in 5.7.15+ with deadlock detection disabled. I plan to double check this assumption with profilers soon.
• Bug #56332 - "Performance regression in DROP TABLE performance post 5.0.77", was reported by Justin Swanhart. The problem is definitely fixed in recent 5.5.x and 5.6.x versions (but not in the older ones probably, there were more regressions later in the progress). This bug report contains some useful examples of opreport commands.
• Bug #58037 - "LOCK_open contention from the table cache". This bug was reported by Mark Callaghan. The problem was well known in the past. Alexey Stroganov proved (with oprofile and scalability testing) that the problem was resolved with introduction of metadata locks in 5.5.x.
• Bug #61401 - "UPDATE performance degrades gradually if a trigger exists", was reported by Aurimas Mikalauskas. He used oprofile to prove that initial implementation of MDL led to clear performance regression comparing to 5.1.x.
• Bug #64304 - "assemble to implement procedure of transforming between big-end and little-end", was reported by Xiaobin Lin, who suggested a patch and proved with oprofile that it helps. The bug is still "Verified". Probably I have to talk to Marko Mäkelä (who is now my colleague in MariaDB!) about it soon...
• Bug #68818 - "Large Value List in WHERE Clause Spends Too Much Time in 'statistics' State", was reported by Jervin Real. He used oprofile to prove his point and show where exactly in the code (as opposed to just "statistics" stage) the time was spent. Eventually this was declared a duplicate of Bug #68046 that is fixed since 5.6.11.
• Bug #72115 - "Very slow create/alter table with partitions and STATS_PERSISTENT=1", was reported by my colleague Jan Lindstrom in 2014. It seems that even with other tools already around, including SHOW PROFILE, Performance Schema and perf profiler, oprofile is still sometimes used to show where the time is spent. After several problems and regressions identified, it seems the problem is mostly resolved in 5.6.17+. I plan to double check this some day.

We clearly see that famous MySQL developers, users, DBAs and support engineers had used oprofile successfully while working on performance related problems. In one of the upcoming posts (while preparing for my FOSDEM 2017 talk) I plan to explain how to use it, both older versions and 1.x.y ones, that rely on the same kernel features as perf profiler now and changed approaches/commands available a lot.

Fun with Bugs #46 - On Some Bugs I've Reported During the Year of 2016

It's time to summarize the year of 2016. As a kind of a weird summary, in this post I'd like to share a list of MySQL bug reports I've created in 2016 that are still remaining "Verified" today:

• Bug #79831 - "Unexpected error message on crash-safe slave with max_relay_log_size set". According to Umesh this is not repeatable with 5.7. The fact that I've reported the bug on January 4 probably means I was working at that time. I should not repeat this mistake again next year.
• Bug #80067 - "Index on BIT column is NOT used when column name only is used in WHERE clause". People say the same problem happens with INT and, what may be even less expected, BOOLEAN columns.
• Bug #80424 - "EXPLAIN output depends on binlog_format setting". Who could expect that?
• Bug #80619 - "Allow slave to filter replication events based on GTID". In this feature request I've suggested to implement filtering by GTID pattern, so that we can skip all events originating from specific master on some slave in a complex replication chain.
• Bug #82127 - "Deadlock with 3 concurrent DELETEs by UNIQUE key". It's clear that manual is not even close to explaining how the locks are really set "by design" in this weird case. See comments in MDEV-10962 for some explanations. Nobody from Oracle event tried to really explain how things are designed to work.
• Bug #82212 - "mysqlbinlog can produce events larger than max_allowed_packet for mysql". This happens for encoded row-based events. There should be some way to take this overhead into account while creating binary log, IMHO.
• Bug #83024 - "Internals manual does not explain COM_SLEEP in details". One day you'll see Sleep for some 17 seconds logged into the slow query log, and may start to wonder why...
• Bug #83248 - "Partition pruning is not working with LEFT JOIN". You may find some interesting related ideas in MDEV-10946.
• Bug #83640 - "Locks set by DELETE statement on already deleted record". This case shows that design of locking in InnoDB does produce really weird outcomes sometimes. This is not about "missing manual", this is about extra lock set that is absolutely NOT needed (a gap X lock on a record in the secondary unique index is set when the same transaction transaction already has the next key lock on it). As a side note, I keep finding, explaining and reporting weird or undocumented details in InnoDB locking for years, still my talk about InnoDB locks was not accepted by Oracle once again for OOW in 2016. What do I know about the subject and who even cares about those locks... 
• Bug #83708 - "uint expression is used for the value that is passed as my_off_t for DDL log". I was really shocked by this finding. I assumed that all uint vs unsigned long long improper casts are already found. It seems I was mistaking.
• Bug #83912 - "Time spent sleeping before entering InnoDB is not measured/reported separately". The use case that led me to reporting this bug is way more interesting than the fact that some wait is not instrumented in performance_schema. You may see more related bug reports from me next year.
• Bug #83950 - "LOAD DATA INFILE fails with an escape character followed by a multi-byte one". This single bug (and related bugs and stories) were original topic for issue #46 of my "Fun With Bugs" series. I was not able to write everything I want properly over last 3 weeks, but trust me: it's a great story, of "Let's Make America Great Again" style. With the goal for LOAD DATA to behave exactly as INSERT when wrong utf8 data are inserted, Oracle changed the way LOAD DATA works back and forth, with the last change (back) happened in 5.7.17:
  

   "Incompatible Change: A change made in MySQL 5.7.8 for handling of multibyte character sets by LOAD DATA was reverted due to the replication incompatibility (Bug #24487120, Bug #82641)"

  I just can not keep up with all the related fun people have in replication environments thanks to these ongoing changes... It's incredible.
• Bug #84004 - "Manual misses details on MDL locks set and released for online ALTER TABLE". Nothing new: locks in MySQL are not properly/completely documented, metadata locks included. yes, they are documented better now, after 11+ years of my continuous efforts (of a kind), but we are "not there yet". I am still waiting for a job offer to join MySQL Documentation Team, by the way :)
• Bug #84173 - "mysqld_safe --no-defaults & silently does NOT work any more". Recent MySQL 5.7.17 release had not only given us new Group Replication plugin and introduced incompatible changes. In a hope to fix security issues it comes with pure regression - for the first time in last 11 years mysqld_safe --no-defaults stopped working for me! By the way, mysqld_safe is still NOT safe in a sense that 5.7.17 tried to enforce, and one day (really soon) you will find out why.
• Bug #84185 - "Not all "Statements writing to a table with an auto-increment..." are unsafe". If you do something like DELETE FROM `table` WHERE some_col IN (SELECT some_id FROM `other_table`) where `table` has auto_increment column, why should anyone care about it? We do not generate the value, we delete rows...
  This bug report was actually created by Hartmut Holzgraefe and test case comes from Elena Stepanova (see MDEV-10170). I want to take this opportunity to thank them and other colleagues from MariaDB for their hard work and cooperation during the year of 2016. Thanks to Umesh (who processed most of my bug reports),  Sinisa Milivojevic and Miguel Solorzano for their verifications of my bug reports this year.

In conclusion I should say that, no matter how pointless you may consider this activity, I still suggest you to report each and every problem that you have with MySQL and can not understand after reading the manual, as a public MySQL bug. Now, re-read my 4 years old post on this topic and have a Happy and Fruitful New Year 2017!

MySQL Support Engineer's Chronicles, Issue #4

This week I had to deal with some unusual problems. But let me start with Percona's xtrabackup, software that I consider a key component of many current production MySQL setups and use regularly. Recently new minor versions of XtraBackup were released, check the details on 2.4.5, for example. It made a step towards support of MariaDB 10.2, but it's still a long way to go, see this pull request #200.

My main problem with xtrabackup, though, is not with lack of support of MariaDB 10,2-specific features. Why should they care, after all... The problem is that old well known bugs and problems are not resolved, those that may affect all MySQL versions, forks and environments. Check lp:1272329 , "innobackupex dies if a directory is not readable. i.e.: lost+found", for example. Why not to read and take into account ignore_db_dir option (as server does) and let those poor souls who used mount point as a datadir to make backups? Check even older problem, passwords that are not hidden in the command lines, see lp:907280, "innobackupex script shows the password in the ps output, when its passed as a command line argument". My colleague Hartmut even suggested the fix recently, see pull request #289.

Because of these old, known problems (some of them being low hanging fruits) that are not fixed users still suffer while using xtrabackup way more often than they would like to. One day, as a result, they'll have to switch to some other online backup tools or approaches. One may dream about extended myrocks_hotbackup to cover InnoDB one day (when MyRocks and InnoDB will work together in one instance), or just use Percona TokuBackup (after adding script to go SST for Galera with it, maybe), or try something totally different. Anyway, I feel that if more bugs (including low hanging fruits) in xtrabackup are not getting fixed and pull requests are not actively accepted, the tool may become much less relevant and used soon.

I had to deal with MaxScale-related issues this week, so I'd like to remind those who use Docker for testing about https://github.com/asosso/maxscale-docker/blob/master/Dockerfile. Personally I prefer to build from source. In any case, I'd like us all to remember that in older versions one may have to set strip_db_esc option explicitly for service to deal with database names containing underscore (_). Recent 2.0.x versions have it enabled by default (see MXS-801).

I also had to explain how online ALTER TABLE works, specifically, when it sets exclusive metadata locks in the process. I still do not see this topic properly explained in the manual, so I had to report Bug #84004, "Manual misses details on MDL locks set and released for online ALTER TABLE".


By no means I am a developer for 11 years already, even less one should expect writing Java code from me. Anyway, I had to explain how to replace Oracle's ref_cursors (a.k.a cursor variables) in MySQL, both in stored procedures and in Java code that calls them. If you are wondering what is this about, check this fine manual. Note that this feature is missing in MySQL, even though it was suggested to implement it here. In general, MySQL allows just to run SELECTs in stored procedures and then in Java you can process each of the result sets returned any way you want. Things may get more complicated when more than one result set is produced, and they are even more complicated in Oracle with nested cursor expressions. So, I plan to devote a separate blog post to this topic one day. Stay tuned.

I answer questions coming not only from customers. Old friends, community users out of nowhere and, even more, colleagues are welcomed to discuss whatever MySQL- or MariaDB-related  problem they may have. If I know how to help, I'll do this, otherwise I'll quickly explain that I am of no good use. This is how I ended up testing MariaDB's CONNECT storage engine quickly as a replacement for the Federated engine, that is, to link table to a remote MySQL table. Basic instructions on how to set it up and use MySQL type looked simple, but when I tried to test on Fedora 23 and hit a problem of missing libodbc.so.1:

MariaDB [(none)]> INSTALL SONAME 'ha_connect';
ERROR 1126 (HY000): Can't open shared library '/home/openxs/dbs/mariadb10.1/lib/plugin/ha_connect.so'
  (errno: 2, libodbc.so.1: cannot open shared object file: No such file or directory)

the solution was not really straightforward. First of all I had to install unixODBC.x86_64 2.3.4-1.fc23 RPM, but it also does not provide libodbc.so.1:

[openxs@fc23 node2]$ find / -name libodbc.* 2>/dev/null
/usr/lib64/libodbc.so.2
/usr/lib64/libodbc.so
/usr/lib64/libodbc.so.2.0.0

So, I had to apply a quick and dirty hack:

[openxs@fc23 node2]$ sudo ln -s /usr/lib64/libodbc.so.2.0.0  /usr/lib64/libodbc.so.1

As a result CONNECT engine worked as expected, as long as proper account and IP-address where used:

MariaDB [test]> INSTALL SONAME 'ha_connect';
Query OK, 0 rows affected (0.27 sec)

MariaDB [test]> create table r_t2(id int primary key, c1 int) engine=connect table_type=mysql connection='mysql://msandbox:msandbox@127.0.0.1:23532/test/t';
Query OK, 0 rows affected (0.04 sec)

MariaDB [test]> select * from r_t2;                     

+----+------+
| id | c1   |
+----+------+
|  1 |    2 |
|  2 |    3 |
+----+------+
2 rows in set (0.00 sec)

From configuring MaxScale to work with database having underscore in the name to re-writing Java code that used to work with Oracle RDBMS for MySQL, with many missing details in the manuals and software bugs identified or reported in between, and all that with ongoing studies of performance problems and lost quorums, rolling upgrades and failed SSTs in Galera clusters - this is what support engineers here in MariaDB have to deal with during a typical working week.

Upstart Basics for Automatic Restarts of MaxScale After Crash

Historically I do not care much about MariaDB's MaxScale, at least since I know how to build it from source when needed. But, as a support engineer who work at MariaDB, sometimes I have to deal with problems related to MaxScale, and this week it happened so that I had to explain what to do to implement automatic restarts of MaxScale "daemon" in case of crashes on RHEL 6.x.

In the process I had found out that two of my most often used Linux distributions, CentOS 6.x and Ubuntu 14.04, actually use Upstart, so good old System V's init tricks and scripts work there only partially and only because somebody cared to integrate them into this "new" approach to starting of tasks and services during boot, stopping them during shutdown and supervising them while the system is running. I had to do this years ago, but customer's question finally forced me to check and study some details on how this system actually works.

So, unfortunately, there is no script like mysqld_safe to start and restart MaxScale after installing official RPM from MariaDB (in this case it was maxscale-2.0.1-2.x86_64). My first idea was to write one, but then I asked myself why it is not there yet, decided to check what's already provided and take a closer look at /etc/init.d/maxscale I have on my CentOS 6.8 VM (the closest to what customer used). It's a typical classic shell script to start service and it starts MaxScale like this:

start() {
    echo -n $"Starting MaxScale: "
...
    ulimit -HSn 65535
    daemon --pidfile $MAXSCALE_PIDFILE /usr/bin/maxscale --user=maxscale $MAXSCALE_OPTIONS >& /dev/null

    RETVAL=$?
    [ $RETVAL -eq 0 ] && touch /var/lock/subsys/$servicename
...
    # Return right code
    if [ $RETVAL -ne 0 ]; then
       failure
       RETVAL=$_RETVAL_NOT_RUNNING
    fi

    echo

    return $RETVAL
}

Basically, it runs /usr/bin/maxscale --user=maxscale, the rest are details (like location of PID file the rest of the script then relies on). There is no advanced script to monitor status of this process with this PID (like mysqld_safe) or anything to care about automatic restarts. It is supposed that I just execute chkconfig maxscale on and then service starts when system enters proper runlevel.

Simple test shows that when maxscale process is killed it's gone and is not restarted. At good old times I'd just add something like this:

mx:2345:respawn:/usr/bin/maxscale --user=maxscale

to /etc/inittab (as nice articles like this suggests), but quick check and then further reading proves that it's not going to work on CentOS 6.8, as it uses Upstart.

So, either I had to write something similar to mysqld_safe for MaxScale, or (having in mind size of code and number of bugs we had in the past in that script) I had better to find out what is the supposed way to respawn processes in Upstart. Basic ideas are, again, simple. One has to create /etc/init/service_name.conf file and put something like this there (real code quote from one of Ubuntu files for MySQL):

start on runlevel [2345]
stop on starting rc RUNLEVEL=[016]

respawn
respawn limit 2 5
...
pre-start script
...
end script

exec /usr/sbin/mysqld

post-start script
...
end script

The file is easy to understand even without reading the manual. One has to set when service starts and stops, add respawn clause if we want to restart it in case of unexpected crashes or kills of the process, optionally limit the number of restarts and intervals between restarts etc, and, optionally, do something before and after start.

I quickly created /etc/init/maxscale.conf based on the above and it did a great job in starting it automatically upon system startup. I've just used exec /usr/bin/maxscale --user=maxscale basically and decided to deal with options and other details later if needed. But what was strange for the very beginning is that in /var/log/messages I've seen what looked like repeated attempts to start maxscale process, that failed:

Nov 26 17:44:45 centos maxscale[20229]: MaxScale started with 1 server threads.
Nov 26 17:44:45 centos init: maxscale main process ended, respawning
Nov 26 17:44:45 centos maxscale[20229]: Started MaxScale log flusher.
Nov 26 17:44:45 centos maxscale[20235]: Working directory: /var/log/maxscale
Nov 26 17:44:45 centos maxscale[20235]: MariaDB MaxScale 2.0.1 started
Nov 26 17:44:45 centos maxscale[20235]: MaxScale is running in process 20235
...

Nov 26 17:44:45 centos maxscale[20235]: Loaded module qc_sqlite: V1.0.0 from /usr/lib64/maxscale/libqc_sqlite.so
Nov 26 17:44:45 centos maxscale[20235]: MaxScale is already running. Process id: 20229. Use another location for the PID file to run multiple instances of MaxScale on the same machine.
Nov 26 17:44:45 centos init: maxscale main process (20234) terminated with status 4
Nov 26 17:44:45 centos init: maxscale main process ended, respawning

Moreover, when proper maxscale process was killed, it was NOT respawned as expected.

It was just a proper time to read the manual more carefully, this part about expect stanza (that I noted in some of official Upstart scripts):

"To allow Upstart to determine the final process ID for a job, it needs to know how many times that process will call fork(2). Upstart itself cannot know the answer to this question since once a daemon is running, it could then fork a number of "worker" processes which could themselves fork any number of times. Upstart cannot be expected to know which PID is the "master" in this case, considering it does not know if worker processes will be created at all, let alone how many times, or how many times the process will fork initially. As such, it is necessary to tell Upstart which PID is the "master" or parent PID. This is achieved using the expect stanza.
The syntax is simple, but you do need to know how many times your service forks."

Let's check quickly how many times fork() is called in maxscale (I'd know it better if I ever cared to study the source code in details, but I had not checked most part of it yet). Test based on that cookbook gives unexpected results:

[root@centos ~]# strace -o /tmp/strace.log -fFv maxscale &
[1] 2369
[root@centos ~]# sleep 10
[root@centos ~]# ps aux | grep strace
root      2369  2.6  0.0   4476   888 pts/0    S    20:28   0:00 strace -o /tmp/strace.log -fFv maxscale
root      2382  0.0  0.0 103312   868 pts/0    S+   20:28   0:00 grep strace
[root@centos ~]# pkill -9 strace
[1]+  Killed                  strace -o /tmp/strace.log -fFv maxscale
[root@centos ~]# ps aux | grep maxscale
root      2375  1.3  0.2 276168  3896 ?        Ssl  20:28   0:00 maxscale
root      2385  0.0  0.0 103312   868 pts/0    S+   20:28   0:00 grep maxscale
[root@centos ~]# egrep "\<(fork|clone)\>\(" /tmp/strace.log | wc | awk '{print $1}'
5

How comes we have 5 fork calls? Here they are:

[root@centos ~]# egrep "\<(fork|clone)\>\(" /tmp/strace.log
2374  clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7fb024c08ab0) = 2375
2375  clone(child_stack=0x7fb01f819f10, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb01f81a9d0, tls=0x7fb01f81a700, child_tidptr=0x7fb01f81a9d0) = 2376
2375  clone(child_stack=0x7fb01e118f10, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb01e1199d0, tls=0x7fb01e119700, child_tidptr=0x7fb01e1199d0) = 2377
2375  clone(child_stack=0x7fb01d10af10, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb01d10b9d0, tls=0x7fb01d10b700, child_tidptr=0x7fb01d10b9d0) = 2378
2375  clone(child_stack=0x7fb017ffef10, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb017fff9d0, tls=0x7fb017fff700, child_tidptr=0x7fb017fff9d0) = 2379

It seems process with PID 2374 actually forked just once, to produce PID 2375, and then several threads were started by that process. We can see them:

[root@centos ~]# ps -T -p `pidof maxscale`
  PID  SPID TTY          TIME CMD
 2375  2375 ?        00:00:00 maxscale
 2375  2376 ?        00:00:00 maxscale
 2375  2377 ?        00:00:00 maxscale
 2375  2378 ?        00:00:00 maxscale
 2375  2379 ?        00:00:00 maxscale
[root@centos ~]#

So, it was really one fork() (and I could notify that even from studying /var/log/messages before) and I have to add expect fork stanza to my Upstart configuration file:

[root@centos ~]# cat /etc/init/maxscale.conf
# MaxScale service

description "MaxScale"

start on stopped rc RUNLEVEL=[2345]
stop on starting rc runlevel [!2345]

respawn
respawn limit 2 5

expect fork

exec /usr/bin/maxscale --user=maxscale

This way it works as expected, as one may easily check:

[root@centos ~]# initctl status maxscale
maxscale start/running, process 6600
[root@centos ~]# maxadmin
MaxScale> show servers
Server 0x19e47a0 (server1)
        Server:                              127.0.0.1
        Status:                              Master, Running
        Protocol:                            MySQLBackend
        Port:                                3306
        Server Version:                      5.7.15-9-log
        Node Id:                             1
        Master Id:                           -1
        Slave Ids:
        Repl Depth:                          0
        Number of connections:               0
        Current no. of conns:                0
        Current no. of operations:           0
MaxScale> quit
[root@centos ~]# kill -9 6600
[root@centos ~]# ps aux | grep maxscale
maxscale  6627  2.0  0.2 276168  3884 ?        Ssl  20:41   0:00 /usr/bin/maxscale --user=maxscale
root      6633  0.0  0.0 103312   872 pts/0    S+   20:41   0:00 grep maxscale
[root@centos ~]# initctl status maxscale
maxscale start/running, process 6627

In the /var/log/messages we clearly see that the process is respawned by init:

...
Nov 26 20:38:15 centos maxscale[6600]: Started MaxScale log flusher.
Nov 26 20:40:33 centos maxscale[6600]: Loaded module MaxAdminAuth: V2.0.0 from /usr/lib64/maxscale/libMaxAdminAuth.so
Nov 26 20:41:52 centos init: maxscale main process (6600) killed by KILL signal
Nov 26 20:41:52 centos init: maxscale main process ended, respawning
Nov 26 20:41:52 centos maxscale[6627]: Working directory: /var/log/maxscale
Nov 26 20:42:07 centos maxscale[6627]: Loaded module MaxAdminAuth: V2.0.0 from /usr/lib64/maxscale/libMaxAdminAuth.so
...

After few more checks I asked to implement this officially in packages for the Linux distributions that use Upstart, see MXS-1027.

To summarize, I wish I care more to find out how Upstart works long time ago. Now it's time to study systemd probably :) Anyway, after some reading and testing one can use it efficiently to provide automated service starts and restarts for MySQL server and services used with it.

MySQL Support Engineer's Chronicles, Issue #3

The original idea of this series was to publish one post per week, but it seems every other week I have some special topic that well deserves a dedicated post. Last week I had no time to complete my writing because of long (and, I hope, useful) Howto post on replacing corrupted partition using non-corrupted one from other server in replication setup. But I had links and notes collected in a draft that I am going to complete now.

First of all, during the previous week I had time to submit two more talks for the  "MySQL and Friends Devroom" at FOSDEM 2017, "Applying profilers to MySQL" and "Background Story of a MySQL Bug". Call for papers is still open, as far as I understand, so I may come up with few more ideas on what to talk about.

Strange to admit this, but sometimes I can be excited with something MySQL-related. Two weeks ago I've added a note to myself about great, detailed changelogs that MariaDB publishes, with proper links to GitHub commits. Check this one for 10.0.28, for example. I wish Oracle provides the same level of details for MySQL releases as a part of their official release notes.

Still, sometimes important changes happen in upstream MySQL, get merged, and details about inherited incompatible change (and its real impact) are still missing in any release notes of any kind. Let's consider recent example. Historically MySQL treated incorrect utf8 bytes sequences differently for INSERT than for LOAD DATA. INSERT failed, LOAD DATA just had the value truncated on the first incorrect character and continued. Eventually (in MySQL 5.6.32) this was fixed by upstream MySQL (it was also fixed in a wider context in MariaDB 10.2 in frames of MDEV-9823). MySQL 5.6.32 release notes says about the incompatible change:

• "Incompatible Change: For multibyte character sets, LOAD DATA could fail to allocate space correctly and ignore input rows as a result. (Bug #76237, Bug #20683959, Bug #23080148)
  References: This issue is a regression of: Bug #14653594."
  

But it surely says nothing about the impact for replication or another Bug #78758 that is fixed in 5.6.32 (by making LOAD DATA fail with error). It costed me some time to figure out all the details. Read MDEV-11217 for the historical details, nice test case and different views on the decisions made. Note also that now error message about the bad utf8 character from LOAD DATA looks (IMHO) weird enough, as it contains actually only a valid part of the string. See my MDEV-11216 about this.

I am still having fun with InnoDB locks. This week I checked what locks are set when the same DELETE (for the table with the primary key and unique secondary index) is executed twice in the same transaction. Check Bug #83640 and tell me how this sequence of locks set in one transaction may make any sense:

---TRANSACTION 636201, ACTIVE 202 sec
5 lock struct(s), heap size 1184, 4 row lock(s), undo log entries 1
MySQL thread id 1, OS thread handle 0x7f9e513a7700, query id 92 localhost root init
show engine innodb status
TABLE LOCK table `test`.`tu` trx id 636201 lock mode IX
RECORD LOCKS space id 11 page no 4 n bits 72 index `u` of table `test`.`tu` trx id 636201 lock_mode X locks rec but not gap
RECORD LOCKS space id 11 page no 3 n bits 72 index `PRIMARY` of table `test`.`tu` trx id 636201 lock_mode X locks rec but not gap
RECORD LOCKS space id 11 page no 4 n bits 72 index `u` of table `test`.`tu` trx id 636201 lock_mode X
RECORD LOCKS space id 11 page no 4 n bits 72 index `u` of table `test`.`tu` trx id 636201 lock_mode X locks gap before rec

My colleague Jan Lindström was also surprised, so we have MDEV-11215 as well, and a chance to see this studies and maybe changed by MariaDB engineers. Related problems were discussed in the past, see Bug #19762 and Bug #55717.

Some days I keep wondering what happens to XtraBackup these days in Percona. As far as I remember I was not able to reproduce lp:1461833 while working there, but the fact that the bug is still open and got no comments since I re-opened it gives me no additional confidence.

I report bugs and missing details in MySQL way too often even for my own liking. But MySQL manual really misses many details to explain results that users see in production. This week I'd like to remind about one of my bug reports about missing details in MySQL documentation, Bug #77390, and my request there:

"Please, explain all metadata and InnoDB locks set by online ALTER, with examples and details enough to explain non-trivial cases..."

Honestly, until this month I never noted that DDL log exists in MySQL. This is a ddl_log.log binary file that can be "dumped" into a somewhat readable form using a script by Mattias Jonsson from Bug #47343:

[openxs@fc23 5.7]$ perl ~/ddl_log_dump.pl data/ddl_log.log
Header: Num entries: 4 Name length: 512 Block length 4096
Entry 1 type i action s next 0
  name ./test/trange2
not 'e' entry (i)
Entry 2 type l action d next 0
  name ./test/#sql-trange2
not 'e' entry (l)
Entry 3 type l action d next 2
  name ./test/trange2#P#pmax
not 'e' entry (l)

This file may grow until MySQL server restart completes, but what's worse, when it grows over 4GB in size it becomes unusable and effectively blocks any further concurrent DDL until we get rid of it. I had a lot of fun reading the code and reporting related Bug #83708. Unlucky users who do a lot of partitioning-related DDL may find the situation less funny when they hit this bug.


I plan to describe what I had to work on this week soon, while I still remember all the relevant details and feelings. So, stay tuned!