Off-CPU Analysis Attempt to Find the Reason of Performance Regression in MariaDB 10.4

I did not write new blog posts for more than 2 months already. Busy days... But now I am on vacation and my Percona Live Online 2021 talk on flame graphs is coming soon, so I decided to renew my experience with bcc tools and try to get some insights for one of the bugs I've reported for MariaDB using the off-CPU flame graphs.

The idea was to check why sysbench oltp_read_write test started to work notably slower in a newer version of MariaDB 10.4.x after 10.4.15. On my good, old and slow Acer netbook with recently updated Ubuntu: 

openxs@ao756:~/git/server$ cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=20.04
DISTRIB_CODENAME=focal
DISTRIB_DESCRIPTION="Ubuntu 20.04.2 LTS"
openxs@ao756:~/git/server$ uname -a
Linux ao756 5.8.0-50-generic #56~20.04.1-Ubuntu SMP Mon Apr 12 21:46:35 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

I've compiled current MariaDB 10.4 from GitHub source following my usual way:

openxs@ao756:~/git/server$ git checkout 10.4
...
openxs@ao756:~/git/server$ git pull
...
openxs@ao756:~/git/server$ git submodule update --init --recursive
Submodule path 'extra/wolfssl/wolfssl': checked out '9c87f979a7f1d3a6d786b260653d566c1d31a1c4'
Submodule path 'libmariadb': checked out '180c543704d627a50a52aaf60e24ca14e0ec4686'
Submodule path 'wsrep-lib': checked out 'f271ad0c6e3c647df83c1d5ec9cd26d77cef2337'
Submodule path 'wsrep-lib/wsrep-API/v26': checked out '76cf223c690845bbf561cb820a46e06a18ad80d1'
openxs@ao756:~/git/server$ git branch
  10.3
* 10.4
  10.5
  10.6
openxs@ao756:~/git/server$ git log -1
commit 583b72ad0ddbc46a7aaeda1c1373b89d4bded9ea (HEAD -> 10.4, origin/bb-10.4-merge, origin/10.4)
Merge: 473e85e9316 a4139f8d68b
Author: Oleksandr Byelkin <sanja@mariadb.com>
Date:   Fri May 7 11:50:24 2021 +0200

    Merge branch 'bb-10.4-release' into 10.4
openxs@ao756:~/git/server$ rm CMakeCache.txt
openxs@ao756:~/git/server$ cmake . -DCMAKE_INSTALL_PREFIX=/home/openxs/dbs/maria10.4 -DCMAKE_BUILD_TYPE=RelWithDebInfo -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DWITH_EMBEDDED_SERVER=OFF -DPLUGIN_TOKUDB=NO -DWITH_SSL=system
...
-- Generating done
-- Build files have been written to: /home/openxs/git/server
openxs@ao756:~/git/server$ time make -j 3
...
[100%] Building C object extra/mariabackup/CMakeFiles/mariabackup.dir/__/__/libmysqld/libmysql.c.o
[100%] Linking CXX executable mariabackup
[100%] Built target mariabackup

real    74m9,550s
user    134m10,837s
sys     7m0,387s

openxs@ao756:~/git/server$ make install && make clean
...
openxs@ao756:~/git/server$ cd ~/dbs/maria10.4
openxs@ao756:~/dbs/maria10.4$ bin/mysqld_safe --no-defaults --port=3309 --socket=/tmp/mariadb.sock --innodb_buffer_pool_size=1G --innodb_flush_log_at_trx_commit=2 &
[1] 27483
openxs@ao756:~/dbs/maria10.4$ 210507 19:15:37 mysqld_safe Logging to '/home/openxs/dbs/maria10.4/data/ao756.err'.
210507 19:15:37 mysqld_safe Starting mysqld daemon with databases from /home/openxs/dbs/maria10.4/data

openxs@ao756:~/dbs/maria10.4$ bin/mysql --socket=/tmp/mariadb.sock
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 8
Server version: 10.4.19-MariaDB MariaDB Server

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

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

MariaDB [(none)]> drop database if exists sbtest;
Query OK, 5 rows affected (1.297 sec)

MariaDB [(none)]> create database sbtest;
Query OK, 1 row affected (0.001 sec)

MariaDB [(none)]> exit
Bye

and compared to 10.4.15 with the following test:

openxs@ao756:~/dbs/maria10.4$ sysbench oltp_read_write --db-driver=mysql --tables=5 --table-size=100000 --mysql-user=openxs --mysql-socket=/tmp/mariadb.sock --mysql-db=sbtest --threads=4 prepare
sysbench 1.0.18 (using system LuaJIT 2.1.0-beta3)

Initializing worker threads...

Creating table 'sbtest2'...
Creating table 'sbtest3'...
Creating table 'sbtest4'...
Creating table 'sbtest1'...
Inserting 100000 records into 'sbtest1'
Inserting 100000 records into 'sbtest4'
Inserting 100000 records into 'sbtest2'
Inserting 100000 records into 'sbtest3'
Creating a secondary index on 'sbtest1'...
Creating a secondary index on 'sbtest4'...
Creating table 'sbtest5'...
Inserting 100000 records into 'sbtest5'
Creating a secondary index on 'sbtest2'...
Creating a secondary index on 'sbtest3'...
Creating a secondary index on 'sbtest5'...

openxs@ao756:~/dbs/maria10.4$ sysbench oltp_read_write --db-driver=mysql --tables=5 --table-size=100000 --mysql-user=openxs --mysql-socket=/tmp/mariadb.sock --mysql-db=sbtest --time=300 --report-interval=10 --threads=4 run
...
    transactions:                        35630  (118.54 per sec.)
    queries:                             712600 (2370.87 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          300.5612s
    total number of events:              35630

Latency (ms):
         min:                                    3.30
         avg:                                   33.70
         max:                                 2200.17
         95th percentile:                      164.45
...

openxs@ao756:~/dbs/maria10.4.15$ sysbench oltp_read_write --db-driver=mysql --tables=5 --table-size=100000 --mysql-user=openxs --mysql-socket=/tmp/mariadb.sock --mysql-db=sbtest --time=300 --report-interval=10 --threads=4 run
...
    transactions:                        56785  (189.25 per sec.)
    queries:                             1135700 (3784.99 per sec.)
    ignored errors:                      0      (0.00 per sec.)
    reconnects:                          0      (0.00 per sec.)

General statistics:
    total time:                          300.0501s
    total number of events:              56785

Latency (ms):
         min:                                    3.15
         avg:                                   21.13
         max:                                  704.36
         95th percentile:                      108.68
...

So, basically with the same test with all tables fitting into the buffer pool (1G) and all but few default settings current MariaDB 10.4.19 demonstrate up to 60% drop in throughput and increase of 95th latency on this netbook (even more than 15% or so reported on faster quad core Fedora desktop previously).

If you read MDEV-24272 carefully, the regression was tracked up to a specific commit, but I tried to apply various tools to actually see where more time is spent now, specifically. Profiling with perf and creating on-CPU flame graphs had not given me any clear insight that would explain that increase in latency, so my next idea was to trace off-CPU time spent, that is, try to find out how long MariaDB server waits and where in the code that's mostly happen.

For this I've used the offcputime tool:

openxs@ao756:~$ /usr/share/bcc/tools/offcputime -h
usage: offcputime [-h] [-p PID | -t TID | -u | -k] [-U | -K] [-d] [-f]
                  [--stack-storage-size STACK_STORAGE_SIZE]
                  [-m MIN_BLOCK_TIME] [-M MAX_BLOCK_TIME] [--state STATE]
                  [duration]

Summarize off-CPU time by stack trace

positional arguments:
  duration              duration of trace, in seconds

optional arguments:
  -h, --help            show this help message and exit
  -p PID, --pid PID     trace this PID only
  -t TID, --tid TID     trace this TID only
  -u, --user-threads-only
                        user threads only (no kernel threads)
  -k, --kernel-threads-only
                        kernel threads only (no user threads)
  -U, --user-stacks-only
                        show stacks from user space only (no kernel space
                        stacks)
  -K, --kernel-stacks-only
                        show stacks from kernel space only (no user space
                        stacks)
  -d, --delimited       insert delimiter between kernel/user stacks
  -f, --folded          output folded format
  --stack-storage-size STACK_STORAGE_SIZE
                        the number of unique stack traces that can be stored
                        and displayed (default 1024)
  -m MIN_BLOCK_TIME, --min-block-time MIN_BLOCK_TIME
                        the amount of time in microseconds over which we store
                        traces (default 1)
  -M MAX_BLOCK_TIME, --max-block-time MAX_BLOCK_TIME
                        the amount of time in microseconds under which we
                        store traces (default U64_MAX)
  --state STATE         filter on this thread state bitmask (eg, 2 ==
                        TASK_UNINTERRUPTIBLE) see include/linux/sched.h

examples:
    ./offcputime             # trace off-CPU stack time until Ctrl-C
    ./offcputime 5           # trace for 5 seconds only
    ./offcputime -f 5        # 5 seconds, and output in folded format
    ./offcputime -m 1000     # trace only events that last more than 1000 usec
    ./offcputime -M 10000    # trace only events that last less than 10000 usec
    ./offcputime -p 185      # only trace threads for PID 185
    ./offcputime -t 188      # only trace thread 188
    ./offcputime -u          # only trace user threads (no kernel)
    ./offcputime -k          # only trace kernel threads (no user)
    ./offcputime -U          # only show user space stacks (no kernel)
    ./offcputime -K          # only show kernel space stacks (no user)

I've stored the outputs in /dev/shm to have less impact on disk I/O that I suspected as one of the reasons:

openxs@ao756:~$ ls /dev/shm
openxs@ao756:~$ mkdir /dev/shm/out
openxs@ao756:~$ ls /dev/shm
out

Basically the following commands were used to create folded (ready to use for building flame graphs) user-space only stacks and time spent off-CPU in them over 60 seconds of tracing while sysbench tests were running for clean setup on MariaDB 10.4.15 and then on current 10.4.19, and create flame graphs based on those stacks where start_thread frame is present (to clean up irrelevant details):

openxs@ao756:~$ sudo /usr/share/bcc/tools/offcputime -f -p `pidof mysqld` -U 60 > /dev/shm/out/offcpu_10415.out
WARNING: 27 stack traces lost and could not be displayed.
openxs@ao756:~$ cat /dev/shm/out/offcpu_10415.out | grep start_thread | ~/git/FlameGraph/flamegraph.pl --color=io --title="Off-CPU Time Flame Graph" --countname=us > /tmp/offcpu_10415.svg

openxs@ao756:~$ sudo /usr/share/bcc/tools/offcputime -f -p `pidof mysqld` -U 60 > /dev/shm/out/offcpu_10419.out
WARNING: 24 stack traces lost and could not be displayed.
openxs@ao756:~$ cat /dev/shm/out/offcpu_10419.out | grep start_thread | ~/git/FlameGraph/flamegraph.pl --color=io --title="Off-CPU Time Flame Graph" --countname=us > /tmp/offcpu_10419.svg

As a result I've got the following graphs (.png screenshots from real .svg files below). On 10.4.15 we spent around 43 seconds (out of 60 we monitored) off-CPU, mostly in do_command() and waiting for network I/O, and the graph was the following:

Off-CPU time for MariaDB 10.4.15

In case of 10.4.19 the graph is very different and we seem to have spent 79 seconds off-CPU, mostly in background io_handler_thread():

Off-CPU time for MariaDB 10.4.19

I was surprised to see more than 60 seconds spent off-CPU in this case. Maybe this is possible because I have 2 cores and MariaDB threads were waiting on both most of the time.

I've then tried to use differential flame graph to highlight the call stacks that the main difference is related to. I've crated it from existing folded stack traces with the following command:

openxs@ao756:~$ ~/git/FlameGraph/difffolded.pl /dev/shm/out/offcpu_10415.out /dev/shm/out/offcpu_10419.out | grep start_thread | ~/git/FlameGraph/flamegraph.pl --color=io --title="Off-CPU Time Diff Flame Graph" --countname=us > /tmp/offcpu_diff.svg

The resulting graph is presented below:

The source of increase is highlighted in red

Here we clearly see that main increase in time spent waiting in 10.4.19 is related to io_handler_thread(), but increase happened in almost all background threads.

* * *

To summarize:

• When some performance regression happens you should check not only those code paths in the application where software started to spend more time working, but also where it started to wait more.
• In case of https://jira.mariadb.org/browse/MDEV-24272 we clearly started to flush more to disk from the very beginning of sysbench oltp_read_write test in newer versions of MariaDB 10.4.x, and on my slow encrypted HDD this matters a lot. The load that was supposed to be CPU-bound (as we have large enough buffer pool) becomes disk-bound.
• Flame graphs are cool for highlighting the difference and in this post I've shown both a classical smart way to produce them without too much impact, and a way to highlight the difference in them with a differential flam graph produced by the difffolded.pl tool created by Brendan Gregg.
• Other cases when Flame Graphs may help MySQL or MariaDB DBAs are discussed during my upcoming Percona Live 2021 talk on May 12. See you there!
• I'll get back to this nice regression bug to study the test case in more details with other tools, maybe more than once. Stay tuned!
  

What about the "Fun with Bugs" series on YouTube?

My "Fun with Bugs" series of blog posts about interesting or badly handled MySQL bug reports ended more than 7 months ago. The time had come for that. But I honestly miss that media for bitching about something wrong in MySQL once in a while...

The year of COVID-19 pandemic with video conferences that replaced normal offline ones forced me to start recording videos, and I even used to like the process so much that I am working on my wife's channel content as a hobby. I've created my own channel as well, for uploading some draft/bad/long/extended videos recorded in the process of work on my online talks:

Being fluent enough with recording videos at home (using different software tools and cameras) and publishing them at YouTube, I wonder now if it makes sense to turn this activity into a regular and MySQL-concentrated one? My next talk(s) will be submitted to Percona Live 2021, but it means they may go live only in May, and I'd like to be on screens earlier than that.

So, I wonder should I maybe have a regular video recordings shared, let's say, once a week every Tuesday, up to 5 minutes long at most, and devoted to some MySQL-related topics? What topics would you like me to cover? Would you mind if it will be a five minutes talk about a recent MySQL bug report or few of them, either interesting in general or badly handled by my former Oracle colleagues? Something else to better spend megabytes of video on? Leave it to younger and more attractive and experienced speakers? Keep writing here or stop bitching about the bugs once and for good?

I am waiting for your comments in this blog post and in social media that I'll share it till March 5, 2021. Then I'll decide on how to proceed with this regular YouTube videos idea.

Fun with Bugs #98 - On MySQL Bug Reports I am Subscribed to, Part XXXII

There are many things to write about MySQL this week. It turned 25 years old, to begin with! Quite successful the first ever Percona Live ONLINE 24 hour conference also happened this week, and I've presented my talk there...

But this is a blog of former MySQL Entomologist, so when I have nothing ready to share about something exciting or immediately useful, I write about MySQL bugs. This is the case today as well. I need more time to think about MySQL history and write down the details to complement my presentation etc. Previous post in this series appeared a month ago, so let me present a yet another list of InnoDB, optimizer, replication and few other bugs reported by MySQL Community users since April 18, 2020 and before May, 2020:

• Bug #99295 - "InnoDB in-memory estimate is wrong after an index is created". As Øystein Grøvlen found out, even though the entire newly added covering index is in the buffer pool, the buf_stat_per_index_t::get() function in MySQL 8 estimates just 1 page is in memory, and as a result the index is not used.
• Bug #99326 - "undo truncation might still not be crash safe". After nice explanations of what may happen from Kevin Lewis:
  

  "After and internal discussion with Sunny Bains, I think I understand the concern better. Let's assume that a redo log is so large that it contains redo entries for all 512 Space IDs of an undo tablespace that is being truncated too often. In other words, even though each truncate removes old pages from the buffer pool and flushes newly created pages, it does not actually cause a checkpoint for each truncation like it did in 5.7. So the redo log can possibly contain records for more than 512 space IDs.
  
  There is a worklog tested and pushed to the 8.0.21 release branch that fixes this highly unlikely possibility.
  
  As part of WL#11819, we keep a count of the number of truncations that have happened between checkpoints. So if there is more than (512 / 8) truncations between checkpoints, then no more truncations can happen on that undo space until the next checkpoint happens."

  this (regression vs 5.7) bug report by Zanye Zjy was closed as "Not a Bug". This is a totally wrong status and handling for such a case. 
• Bug #99354 - "Nondeterministic stored function returns incorrect results". This interesting bug was reported by Jacob Chafik. If anyone cares, it is still repeatable on 8.0.20 (and not repeatable on MariaDB 10.4.x):
  

  mysql> SELECT IF(COUNT(t1.id) > 0, "Success", "Failure") "Result" FROM t1 WHERE 1 IN (SELECT t1_inner.id FROM t1 t1_inner INNER JOIN t2 WHERE f1(t2.id) > 0);
  +---------+
  | Result  |
  +---------+
  | Failure |
  +---------+
  1 row in set (0,04 sec)
  
  mysql> SELECT IF(COUNT(t1.id) > 0, "Success", "Failure") "Result" FROM t1 WHERE 1 IN (SELECT t1_inner.id FROM t1 t1_inner INNER JOIN t2 WHERE t2.id > 0);
  +---------+
  | Result  |
  +---------+
  | Success |
  +---------+
  1 row in set (0,00 sec)
  
  mysql> explain SELECT IF(COUNT(t1.id) > 0, "Success", "Failure") "Result" FROM t
  1 WHERE 1 IN (SELECT t1_inner.id FROM t1 t1_inner INNER JOIN t2 WHERE f1(t2.id)
  > 0);
  +----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+--------------------------------------------+
  | id | select_type | table    | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra                                      |
  +----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+--------------------------------------------+
  |  1 | SIMPLE      | t1_inner | NULL       | ALL  | NULL          | NULL | NULL    | NULL |    2 |    50.00 | Using where                                |
  |  1 | SIMPLE      | t2       | NULL       | ALL  | NULL          | NULL | NULL    | NULL |    2 |   100.00 | FirstMatch                                 |
  |  1 | SIMPLE      | t1       | NULL       | ALL  | NULL          | NULL | NULL    | NULL |    2 |   100.00 | Using where; Using join buffer (hash join) |
  +----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+--------------------------------------------+
  3 rows in set, 1 warning (0,00 sec)
  
  mysql> explain SELECT IF(COUNT(t1.id) > 0, "Success", "Failure") "Result" FROM t1 WHERE 1 IN (SELECT t1_inner.id FROM t1 t1_inner INNER JOIN t2 WHERE t2.id > 0);
  +----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+-------------------------------+
  | id | select_type | table    | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra                         |
  +----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+-------------------------------+
  |  1 | SIMPLE      | t1_inner | NULL       | ALL  | NULL          | NULL | NULL    | NULL |    2 |    50.00 | Using where                   |
  |  1 | SIMPLE      | t2       | NULL       | ALL  | NULL          | NULL | NULL    | NULL |    2 |    50.00 | Using where; FirstMatch       |
  |  1 | SIMPLE      | t1       | NULL       | ALL  | NULL          | NULL | NULL    | NULL |    2 |   100.00 | Using join buffer (hash join) |
  +----+-------------+----------+------------+------+---------------+------+---------+------+------+----------+-------------------------------+
  3 rows in set, 1 warning (0,00 sec)
  
  mysql> select version();
  +-----------+
  | version() |
  +-----------+
  | 8.0.20    |
  +-----------+
  1 row in set (0,00 sec)

  Wrong results should not be produced for logically equivalent queries, even if plans are different. Unfortunately this regression (since 5.7.5+) bug had not got the "regression" tag.
• Bug #99359 - "Order by in group_concat with prepare statement returns unexpected results". Two executions of the same statement with the user variable having the same value assigned should either both work or fail with error message, it's a matter of consistency. This is not the case in a situation described in the bug report from Feng Liyuan.
• Bug #99363 - "Innodb_data_pending_fsyncs shows incorrect value". In this bug report SeongUck Lee clearly shown that the problem happens and gave some hints based on source code review what could cause this regression in 8.0 comparing to 5.7. Moreover, after adding debug assertion he managed to show how it is hit and what wrong values are produced, in gdb. Still this report for now ended up as "Not a Bug" (until a test case is presented, reportedly. What a shame!
• Bug #99377 - "Assertion `thd->get_transaction()->is_empty(Transaction_ctx::STMT)' failed in ". Surely dropping and re-creating the mysql.general_log table is a corner case, but even in debug builds it should end up with some proper error message, not just assertion failure. This bug was reported by Roel Van de Paar.
• Bug #99381 - "ORDER_BY Index-level optimizer hint implies NO_JOIN_INDEX for second table". The bug reporter, Jesper Wisborg Krogh, my former colleague in MySQL Support, knows a lot about MySQL queries optimization. Make sure to read his last book, "MySQL 8 Query Performance Tuning: A Systematic Method for Improving Execution Speeds". This time he found a problem with hints.
• Bug #99398 - "Data in wrong row on left join". This regression bug in MySQL 8.0.20 reported by Soner Sayakci is already fixed in upcoming MySQL 8.0.21. Good news.
• Bug #99412 - "Threads_running becomes scalability bottleneck on multi-node NUMA topologies". Nice bug report from Sergey Glushchenko, with a patch contributed. perf annotate was used to demonstrate the problem. Good to know Percona engineers keep working to make MySQL perform better!
• Bug #99413 - "Constant propagation get the wrong result when mix with the different collations". Again, this bug report from Wj Huang was closed as 'Not a Bug" based mostly on the results from 8.0.21+ that is not yet released. This is either a "Duplicate" if the exact fix that helped in 8.0.21+ can be isolated, or "Can't repeat", but setting it to "Not a Bug" seems wrong to me.
• Bug #99414 - "Where exists performance 8.0.16 onwards". This optimizer regression bug in 8.0.16+ (comparing to 5.7) was reported by Jonathan Taylor. See also a comment by Øystein Grøvlen about the tool available at https://github.com/ogrovlen/opttrace to pre-process and get a condensed trace for the join optimizer, that helps to understand what's going on.

Let me stop for now. Many more interesting bugs were reported in May, so stay tuned!

Happy Birthday, MySQL and Sakila!

To summarize:

1.  Now (regression!) bugs are sometimes closed as "Not a Bug" after explanation what the problem is and statement that there is a fix in a version not yet released. Not as a "Duplicate", but "Not a Bug", after confirming the problem. This is a new level of wrong bugs handling!
2. Same with a bug where bug reporter is still working on a repeatable test case, after showing the problem happened with some evidence, "Not a Bug".
3. Oracle does a good job recently in making sure MySQL Server bugs are not hanging around without reaction and are processed fast, but looks like this is partially achieved by lowering standards of bugs processing that were established over last 15+ years. Closing reports by all means as soon as possible as "Not a Bug" is not a way to go. This is sad.

Post #200 in the Blog of Former MySQL Entomologist!

I noted that since August 2012 when I started this blog (while planning to leave my job as a MySQL Entomologist in Oracle to see some real MySQL life besides bugs) I've already published 199 posts. In this post #200 I'd like to look back and pick up one post per each year of blogging so far that I consider really good, important or useful.

I try my best to pick up posts that are mostly not about specific MySQL bugs. These posts either caused some interesting discussions or defined my interests for a log time, or just opened new directions in my public blogging efforts. I think many of them also got less public attention than they deserve (so most popular posts are not in this list). I also try to summarize my work related memories and sentiments of the year.

Here is the list:

• 2012. "New Year Wishes for Customers of Oracle's MySQL Technical Support Services".
  
  That year I considered my job roles in Oracle too boring and decided to quit and join Percona for real fun, practical experience and really good money! I also created few social media accounts and this blog, as I decided to finally share the details of my past and current work in public. I just started and published only 4 posts during that year and the one I picked up was probably created during my shift on December 31 (I still like to work on weekends and public holidays, but do this less often). Basically I wanted to encourage Oracle customers (and employees) to report MySQL bugs they found in public MySQL bugs database. Expected for the MySQL Entomologist to wish this, isn't it? I still wish the same today, even more! Unfortunately I see public MySQL bugs database is used less these days and this makes me sad.
  
  
• 2013. "How to Drop the Trigger".
  
  I had a lot of work, bugs and problems to deal with in 2013, including hard to forget snow storm in March. This year I first visited UK to speak about Performance Schema at Percona Live (it was probably my worst accepted talk ever) and enjoy London and Brighton. Who could imagine the outcomes of that very first visit... I had written a lot in public that year, 42 blog posts and so many rumblings about bugs at Facebook that I annoyed many of my former colleagues. The blog post I picked up was probably my first ever "HowTo" style post in this blog and that's why it is important. It described the real life case when due to missing .TRG file DROP TRIGGER statement just failed. One had to create the file manually to proceed, and it's easy as it's a plain text file. Surely I listed some bugs I checked in the process, including those that could explain why the file was missing.
  
  
• 2014. "On responsible bugs reporting".
  
  I was less active blogger in 2014, as I was kindly asked by both Oracle and Percona officials and colleagues to reduce my extraordinary bugs-related social media activity. This made me sad, but allowed to concentrate better on support and other job duties in Percona. I kept myself mostly silent after the blog post mentioned above, where I discussed what a responsible engineer should do when she finds some simple sequence of SQL statements that, when executed by authenticated user explicitly having all the privileges needed to execute these statements, crashes some version of her favorite MySQL fork. I was (and still is) against hiding this kind of crashes by Oracle or any other open source software vendor, and suggested to report them in public as I always did. Many MySQL Community members disagree with this approach even today, probably. In 2014 I've got my (first and only) talk (about MySQL bugs reporting) accepted to Oracle Open World 2014 somehow. I keep submitting multiple talks for this event every year, to no result since that time...
  
  
• 2015. "Using gdb to understand what locks (and when) are really set by InnoDB. Part I.".
  
  In 2015 I started to study MySQL internals with gdb on a regular basis. The blog post I picked up for this year was the first in a series of such studies that continue until today. Initially it was as simple as setting few breakpoints and checking several lines of source code here and there, but I had not stopped at that stage. As a result of that studies, in 2015 I've presented interesting and really well accepted talks at FOSDEM and another one about InnoDB locks and deadlocks at Percona Live. Who could imagine that next time I speak at any Percona conference it will be 2019! The rest of the year was hard and sad at work, where I spent most of my time fighting for my Support team values and colleagues against the upcoming changes, new leaders and new company approaches to services. Not so many blog posts as a result, just 12.
  
  
• 2016. "I'm Winston Wolf, I solve problems.".
  
  In January, 2016, my internal fights in Percona influenced content and highlights of my blog posts. One of them, my all times favorite, was aimed at explaining how Support should work and why, based on real life story with one of customer issues I resolved instantly working the way I prefer! I have to note that my feature request (Bug #76030 - "Add a way to disable rowid-ordered retrieval to optimizer_switch") that led me to the idea about the root cause is still "Open" today. Even more interesting that the issue was about MariaDB. Later I lost in all my fights for Support in Percona (fights, but not the battle, as Percona today mostly operates the way I defended back then, not the way they planned or tried to enforce) and had to quit, to end up working in MariaDB Corporation where I stay till today, and happy! In general, 2016 was my most successful year as a blogger, with up to 1000 page views per day during some months. Many of 29 blog posts published that year are worth re-reading and quoting, and became really popular, but I'd like to remind mostly about this series about MySQL Support people... Since 2016 I am less active at conferences due to my (now resolved) conflict with Percona on this topic as well, so FOSDEM was my only MySQL-related public appearance in 2016.
  
  
• 2017. "perf Basics for MySQL Profiling".
  
  By 2017 I found yet another type of tools of enormous value for my daily work in Support - profilers (not only pt-pmp, but also real ones), specifically perf in case of any modern Linux. I had found out (hard way) that proper instrumentation of source code, while useful as MySQL Performance Schema (and Oracle's wait events long before it) shown, is never 100% complete and ready to use in practice, unlike proper OS level profiling tools that Linux got since kernel 2.6.x. Profilers helped me to solve real life performance problems and my findings were later summarized in this FOSDEM 2017 talk, the best one I ever made IMHO. It was a fruitful year for blogging and it was hard to pick up one post out of 32. I continued my gdb studies of various MySQL features and ended up with a long workshop on this topic presented in Sofia to few attendees.
  
  
• 2018. "On Some Problematic Oracle MySQL Server Features".
  
  In 2018 I had crazy plans to go to Oracle Open World and speak there about problems with MySQL and Oracle's way of developing it. So, many of my numerous (37 in total) blog posts that year were explaining my views on these in details. I picked up the one above as it summarized the most problematic features of MySQL server itself (namely implementations of InnoDB data compression, FULLTEXT indexes, so called "online" DDL, automatic recalculation of InnoDB "persistent" statistics, and partitioning, as well as some details on how all these (does not) work well together). This was surely NOT a topic to be accepted for any MySQL conference! But posts from this series are still useful to review even today, as some of these features got zero improvements even in MySQL 8.0 (and just few are planned or done by other vendors, with MyRocks providing better data compression and with some ongoing changes to InnoDB that are implemented by MariaDB Corporation). I had to cancel my FOSDEM talk that year due to family issues, and had not made any public presentations.
  
  
• 2019. "Dynamic Tracing of MySQL Server With perf probe - Basic Example".
  
  
  The year of 2019 was really successful for me. In May I've got "MySQL Community Contributor of The Year" award "for bug identification and submission", that is, for activity that is the main topic of this blog. Obviously, many (of 26 in total) blog posts were about bugs, bugs reporting and bugs processing, same as my FOSDEM talk in 2019. But later I stopped exploiting "MySQL bugs" topic and switched to my current interests (dynamic tracing and profiling with perf, BPF tools and bpftrace). So, I picked up one of the key blog posts that provided additional details for my Percona Live Europe 2019 talk on the topic.
  
  I had a lot of plans for related studies and talks for 2020, but with COVID-19 breaking everything and conferences cancelled it may happen so that this blog would be the only public platform for all my MySQL-related activities this year.
  

I also checked many old photos made with Nokia dumb phone while working on this post. Who known when (and if) I ever see the West Pier in Brighton again and swim nearby...

I do not plan to stop blogging any time soon. So, stay tuned for the next 200 post :)

Dynamic Tracing of MariaDB Server With bpftrace - Basic Example

Unlike the previous post, this one is not just a comment to some slides from the "Tracing and Profiling MySQL" talk at Percona Live Europe 2019. I am going to add the details that were missing there (as I was in a hurry and had forgotten to copy/paste proper outputs while testing). I am going to show how to add dynamic probe with "latest and greatest" bpftrace tool.

The goal is the same as before - try to add dynamic probe(s) to trace query execution. More specifically, to capture text of the queries executed by clients of MySQL server. As bpftrace requires new kernel and just does not work on Ubuntu 16.04, for the demonstration I use my Fedora 29 box with kernel 5.2.x and, for a change, get queries from Fedora's own MariaDB 10.3.17 installed from rpm packages there.

I have both bcc and bpftrace installed also from packages:

[openxs@fc29 ~]$ rpm -qa | grep bcc
python3-bcc-0.8.0-1.fc29.x86_64
bcc-0.8.0-1.fc29.x86_64
bcc-tools-0.8.0-1.fc29.x86_64
[openxs@fc29 ~]$ rpm -qa | grep bpf
bpftrace-0.9-0.fc29.x86_64
[openxs@fc29 ~]$

You can check fine manual for the details, but even basic -h option provides enough to start, as long as you already know some terms and probes syntax:

[openxs@fc29 ~]$ bpftrace -h
USAGE:
    bpftrace [options] filename
    bpftrace [options] -e 'program'

OPTIONS:
    -B MODE        output buffering mode ('line', 'full', or 'none')
    -d             debug info dry run
    -dd            verbose debug info dry run
    -e 'program'   execute this program
    -h             show this help message
    -l [search]    list probes
    -p PID         enable USDT probes on PID
    -c 'CMD'       run CMD and enable USDT probes on resulting process
    -v             verbose messages
    --version      bpftrace version

ENVIRONMENT:
    BPFTRACE_STRLEN           [default: 64] bytes on BPF stack per str()
    BPFTRACE_NO_CPP_DEMANGLE  [default: 0] disable C++ symbol demangling

EXAMPLES:
bpftrace -l '*sleep*'
    list probes containing "sleep"
bpftrace -e 'kprobe:do_nanosleep { printf("PID %d sleeping...\n", pid); }'
    trace processes calling sleep
bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }'
    count syscalls by process name

In our case we need to define uprobe for proper mysqld binary and trace the dispatch_command() function. Before we start, note that parameters of dispatch_command() in MariaDB 10.3 are not the same as in Percona Server 5.7 I've used in the previous post. Basically, this function starts as follows in sql/sql_parse.cc:

   1570 bool dispatch_command(enum enum_server_command command, THD *thd,
   1571                       char* packet, uint packet_length, bool is_com_mult        i,
   1572                       bool is_next_command)

Note the third argument, packet. If the first argument, command. is SQL_QUERY, then packet contains the query text (as a zero-terminated string) for sure (it's also true for many other commands, but let me skip the details for now). That's why we'll use third argument in our uprobe to capture the SQL text.

Now, let's start the service and check the exact full path name for the mysql binary:

[openxs@fc29 ~]$ sudo service mariadb start
[sudo] password for openxs:
Redirecting to /bin/systemctl start mariadb.service
[openxs@fc29 ~]$ ps aux | grep mysqldmysql     9109  6.2  1.2 1699252 104108 ?      Ssl  09:30   0:00 /usr/libexec/mysqld --basedir=/usr
openxs    9175  0.0  0.0 215744   892 pts/0    S+   09:30   0:00 grep --color=auto mysqld

The first naive attempt to add the probe after cursory reading the documentation and checking few examples may look like this:

 [openxs@fc29 ~]$ sudo bpftrace -e 'uprobe:/usr/libexec/mysqld:dispatch_command { printf("%s\n", str(arg2)); }'
Attaching 1 probe...
Could not resolve symbol: /usr/libexec/mysqld:dispatch_command

It seems in my case, unlike perf, bpftrace is not "aware" of C++ names or symbolic information in a separate -debuginfo package. So, I need mangled name:

[openxs@fc29 ~]$ nm -na /usr/libexec/mysqld | grep dispatch_command
nm: /usr/libexec/mysqld: no symbols
[openxs@fc29 ~]$ nm -na /home/openxs/dbs/maria10.3/bin/mysqld | grep dispatch_command
00000000004a1eef t _Z16dispatch_command19enum_server_commandP3THDPcjbb.cold.344
00000000005c5190 T _Z16dispatch_command19enum_server_commandP3THDPcjbb
00000000005c5190 t _Z16dispatch_command19enum_server_commandP3THDPcjbb.localalias.256

Surely there is no symbols in the binary from Fedora package, so I checked the binary (of the same version) that I've built myself (as usual) and assumed that neither parameters nor mangling approach could be different. So, the next attempt to add dynamic probe would look as follows:

[openxs@fc29 ~]$ sudo bpftrace -e 'uprobe:/usr/libexec/mysqld:_Z16dispatch_command19enum_server_commandP3THDPcjbb { printf("%s\n", str(arg2)); }'
Attaching 1 probe...
show databases
show tables
t1
select @@version_comment limit 1
select user, host from mysql.user
^C

It worked and you see above the output I've got for the following session:

[openxs@fc29 ~]$ mysql -uroot testReading 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 19
Server version: 10.3.17-MariaDB MariaDB Server

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

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

MariaDB [test]> select user, host from mysql.user;
+------+-----------+
| user | host      |
+------+-----------+
| root | 127.0.0.1 |
| root | ::1       |
| root | fc29      |
| root | localhost |
+------+-----------+
4 rows in set (0.000 sec)

You can see some SQL statements generated when mysql command line connects, as well as packet value in some other packet ("t1") than COM_QUERY, probably. My probe had not even tried to check other parameters besides the supposed query text.

Now, the probe is defined on uprobe:/usr/libexec/mysqld:_Z16dispatch_command19enum_server_commandP3THDPcjbb - I've just used long, mangled version of the function name and full path name to the binary, and defined a dynamic probe (uprobe). There is no filter and the action for the probe is defined as { printf("%s\n", str(arg2)); } - that is, I print third argument (they are numbered starting from zero, arg0, arg1, arg2, ...) as a zero-terminated string. Without str() built in function I'd get just a pointer that could be printed as (unsigned) long integer, u64.

Basically, that's all. We have a quick and dirty way to capture all queries. No timing or anything, but it all depends on probe action that can use numerous built in variables and functions.

More "advanced" use of bpftrace, a lame attempt to capture time to execute query, may look like this:

[openxs@fc29 ~]$ sudo bpftrace -e 'uprobe:/usr/libexec/mysqld:_Z16dispatch_command19enum_server_commandP3THDPcjbb { @sql = str(arg2); @start[@sql] = nsecs; }
uretprobe:/usr/libexec/mysqld:_Z16dispatch_command19enum_server_commandP3THDPcjbb /@start[@sql] != 0/ { printf("%s : %u64 ms\n", @sql, (nsecs - @start[@sql])/1000000); } '
Attaching 2 probes...
select sleep(3) : 300064 ms
select sleep(1) : 100064 ms
^C

@sql: select sleep(1)


@start[select sleep(3)]: 10666558704666
@start[select sleep(1)]: 10685614895675


[openxs@fc29 ~]$

In this case I try to store time since probe start into the associative array with query text as an "index" and start time (in nanoseconds) as a value.Then I calculate the difference from current nsecs value upon function return, in a separate uretprobe. I've used global variables, @sql for the query text, and @start[] for the array. It even seems to work well for a single threaded load based on the above. But as soon as I try to use multiple concurrent threads:

[openxs@fc29 ~]$ for i in `seq 1 4`; do mysql -uroot test -e"select sleep($i)" & done

it becomes clear that global variables are really global and my outputs are all wrong.

A bit better version may look like this:

[openxs@fc29 ~]$ sudo bpftrace -e 'uprobe:/usr/libexec/mysqld:_Z16dispatch_command19enum_server_commandP3THDPcjbb { @sql[tid] = str(arg2); @start[tid] = nsecs; }                                                                               uretprobe:/usr/libexec/mysqld:_Z16dispatch_command19enum_server_commandP3THDPcjbb /@start[tid] != 0/ { printf("%s : %u64 %u64 ms\n", @sql[tid], tid, (nsecs - @start[tid])/1000000); } '
Attaching 2 probes...
select sleep(1) : 1120764 100064 ms
 : 1120764 064 ms
select sleep(2) : 949064 200064 ms
 : 949064 064 ms
select sleep(3) : 1120864 300064 ms
 : 1120864 064 ms
select sleep(4) : 1120664 400064 ms
 : 1120664 064 ms
select sleep(1) : 1120764 100064 ms
 : 1120764 064 ms
select sleep(2) : 949064 200064 ms
 : 949064 064 ms
select sleep(3) : 1120664 300064 ms
 : 1120664 064 ms
select sleep(4) : 1120864 400064 ms
 : 1120864 064 ms
^C

@sql[9490]:
@sql[11206]:
@sql[11207]:
@sql[11208]:


@start[11207]: 13609305005933
@start[9490]: 13610305621499
@start[11206]: 13611305753596
@start[11208]: 13612305235313


[openxs@fc29 ~]$

The output is for both sequential and concurrent execution of queries. I've used two associative arrays, @sql[] for queries and @start[] for start times, both indexed by tid - built in variable for thread id, that should not change, at least until we use pool-of-threads... You can also see that the tool by default outputs the content of all global associate arrays at the end, unless we free them explicitly.

* * *

This image of bpftrace internals is taken from the Brendan Gregg's post

bpftrace commands may be much more complicated and it may make sense to to store them in a separate file. The tool is near ideal of "quick and dirty" tests, and one day I'll write a way more complete posts with much better examples. But having a way to capture, filter and summarize queries in kernel space and send only the relevant results to a user space, all that in a safe manner, is really cool!

Dynamic Tracing of MySQL Server With perf probe - Basic Example

I am going to write a series of blog posts based on my talks and experiences at Percona Live Europe 2019. The first one would be a kind of extended comment for a couple of slides from the "Tracing and Profiling MySQL" talk.

We can surely wait until Performance Schema instruments every other line of code or at least every important stage and wait in every storage engine we care about, but there is no real need for that. If you run any version of MySQL under Linux with more or less recent kernel (anything newer than 4.1 is good enough, in general), you can easily use dynamic tracing for any application (at least if there is symbolic information for the binaries), any time. As Brendan Gregg put it here:

"One benefit of dynamic tracing is that it can be enabled on a live system without restarting anything. You can take an already-running kernel or application and then begin dynamic instrumentation, which (safely) patches instructions in memory to add instrumentation. That means there is zero overhead or tax for this feature until you begin using it. One moment your binary is running unmodified and at full speed, and the next, it's running some extra instrumentation instructions that you dynamically added. Those instructions should eventually be removed once you've finished using your session of dynamic tracing."

One of the ways to use dynamic tracing (that is supported for a long time) is a perf profiler and its probe command. In the simplest case that I am going to illustrate here, probe is defined for a function defined in the code and refers to it by name. You can refer to the name of local variable, function parameter, local data structure member in the probe etc, and record the values of them with other probe data.

For a simple example let me consider recent Percona Server 5.7.x running on recent Ubuntu 16.04 with kernel 4.4.x. Let's assume I want to trace all calls to the dispatch_command() function and record every query every connection processes that way.

Skipping the details for now, let's assume I've found out (with gdb in my case, but it can be code review as well) that when this function is called I can see the query user wants to execute in the com_data structure passed via a pointer to the function:

(gdb) p com_data->com_query.query
$4 = 0x7fb0dba8d021 "select 2"

Based on this information and having -dbg package also installed for Percona Server I can add a probe dynamically any time using the following simple command (--add option is assumed by default):

openxs@ao756:~$ sudo perf probe -x /usr/sbin/mysqld 'dispatch_command com_data->com_query.query:string'
Added new event:
  probe_mysqld:dispatch_command (on dispatch_command in /usr/sbin/mysqld with query=com_data->com_query.query:string)

You can now use it in all perf tools, such as:

        perf record -e probe_mysqld:dispatch_command -aR sleep 1

In this probe I refer to the specific binary with -x option and full path name, and the function in that binary by name, and I say that I'd like to record the value of com_data->com_query.query as a zero-terminated string. Now I can use any variation of perf record command (with -F option to define sampling frequency, -g option to capture stack traces etc, see more here) and my probe will be one of the events captured.

For this simple example of tracing I'll use -e option to capture only the events related to the probe I defined. Probe name for this simple case by default consists of the binary name, colon (':') separator and function name. I'll use -R option to collect raw sample records and . I've also added -a option to collect samples on all CPUs. You can see the hint for possible command in the output above. 

So, I can record related events with default frequency as follows:

openxs@ao756:~$ sudo perf record -e 'probe_mysqld:dispatch_command*' -aR
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.676 MB perf.data (3 samples) ]

I let it work for some time in the foreground and then pressed Ctrl-C to stop collecting. Now I can check raw sample records with perf script command:

openxs@ao756:~$ sudo perf script >/tmp/queries.txt
openxs@ao756:~$ cat /tmp/queries.txt
          mysqld 31340 [001]  3888.849079: probe_mysqld:dispatch_command: (be9250) query="select 100"
          mysqld 31340 [001]  3891.648739: probe_mysqld:dispatch_command: (be9250) query="select user, host from mysql.user"
          mysqld 31340 [001]  3895.890141: probe_mysqld:dispatch_command: (be9250) query="select 2"

This is the detailed trace, with additional information (exact text of the query executed) added as requested. Output also included PID of the binary, CPU the sample was taken from and a timestamp.

When I am done with tracing, I can delete the probe with --del option referring it by name:

openxs@ao756:~$ sudo perf probe --del dispatch_commandRemoved event: probe_mysqld:dispatch_command

The (small, more on that later) overhead for tracing was added dynamically, only for the exact information I needed and only for the period of tracing. After the dynamic probe is removed we have exactly the same binary as originally started running with zero extra overhead. Now do this with Performance Schema :)

* * *

Slides are available at https://www.slideshare.net/valeriikravchuk1/

More details on the way other tools mentioned during the talk can be used by MySQL DBAs are coming soon in this blog. Stay tuned!

Fun with Bugs #89 - On MySQL Bug Reports I am Subscribed to, Part XXIII

I have to celebrate the anniversary of my last day in Oracle (that was 7 years ago!) somehow, and I think writing yet another blog post about Oracle MySQL bugs is a good way to do this. I am actually surprised (and happy) that public bugs database is still alive, maintained and considered important in Oracle, and I know who in Oracle was working hard all these years for this to happen!

In my previous post in this series I've stopped on Bug #95954 and had not completed review of interesting MySQL bug reports that I've subscribed to in June 2019. So, below I start with the next bug in my list, complete review for June and cover some bugs reported in July. There were many.

• Bug #95957 - "IN operator issue when comparing signed column and the column cast to unsigned". This bug was reported by Manuel Rigger. As far as I can see, MariaDB 10.3 is not affected:
  

  MariaDB [test]> CREATE TABLE t0(c0 INT);
  Query OK, 0 rows affected (0.518 sec)
  
  MariaDB [test]> INSERT INTO t0(c0) VALUES(-1);
  Query OK, 1 row affected (0.196 sec)
  
  MariaDB [test]> SELECT t0.c0 IN (1, CAST(t0.c0 AS UNSIGNED)) from t0;
  +---------------------------------------+
  | t0.c0 IN (1, CAST(t0.c0 AS UNSIGNED)) |
  +---------------------------------------+
  |                                     0 |
  +---------------------------------------+
  1 row in set, 1 warning (0.207 sec)
  
  MariaDB [test]> show warnings\G
  *************************** 1. row ***************************
    Level: Note
     Code: 1105
  Message: Cast to unsigned converted negative integer to it's positive complement
  
  1 row in set (0.013 sec)

• Bug #96001 - "No warning when creating foreign key in MyISAM tables". I am really surprised that this "documented feature" was accepted as a S3 bug when reported by Przemyslaw Malkowski from Percona. But this happened. I also prefer NOT to have unsupported syntax just ignored silently and would like to see a warning (or error in strict mode).
• Bug #96002 - "'variable log_bin_trust_function_creators' -variable is "hidden"." Consistency is important, as well as correct documentation. So I was happy to see this bug report from Peter Laursen. 75(!) of his bug reports are still active, by the way, some were reported more than 10 years ago. I wonder if anyone is going to check (if not fix) them any time soon.
• Bug #96079 - "large_tests.innodb_innochecksum_3gb test failing with debug build." Yet another MTR test failure reported by Lalit Choudhary from Percona.
• Bug #96100 - "Generated column cause a heap-use-after-free error". Probably ASan builds are not tested as carefully in Oracle as they are by some community members, like Zkong Kong who reported this bug. Otherwise they would mark this bug report as a duplicate of some known internal bug.
• Bug #96108 - "To run mtr "innodb.log_flush_order" MySql Server would be always core down". I've listed the bug as an example that even though code modification is needed to reproduce the crash (reported by Juncai Meng) literally, it was accepted and "Verified". In other reports this sometimes not happen, and the point is that it is surely not a rule carved in stone in Oracle to NOT accept bugs if test case involves code modification. Remember that and fight for your reports if needed.
• Bug #96128 - "Doc: documentation is inaccurate when InnoDB starts with innodb_read_only". Correct manual matters a lot, so nice to have it corrected in this case by Calvin Sun.
• Bug #96134 - "Please provide control functions for the IO Thread." I'd be also happy to see a way to control replication I/O thread progress and read logs only up to some position or GTID, per channel. Thanks Jean-François Gagné for this nice feature request.
• Bug #96142 - "Inconsistent error on slave for Update event on table with non-exists partition". Yet another by report from by Lalit Choudhary. Good to see multiple versions check.
• Bug #96148 - "using Invisible Index when slave apply EVENT". This bug was reported by Songlei Wang. Consistency matters, so if the index is invisible it should remain invisible for replication SQL thread as well. See also his another Bug #96150 - "'show slave status' show the Inaccurate Last_IO_Error message".
• Bug #96167 - "Many header files now missing from devel package". As noted by Manuel Ung, now it is impossible to build plugins and UDFs unless users download the source tree, and then copy the headers to the appropriate places. Packaging in hard.
• Bug #96178 - "mysqldump leaks memory when selected tables are dumped with --order-by-primary". Abhinav Sharma proposed a simple MTR test case to run on ASan build, and suggested a fix. Very nice bug report. Unfortunately I do not see any statements about the results of checking MySQL 8.0.x.
• Bug #96192 - "Possible race condition with binlog-transaction-dependency-tracking". Bug reporter, Herman Lee, complained about one place in the code where race condition may happen even after the fix for one MySQL bug. Does it really matter for bug verification if he found more places? I fail to see a reason to keep he bug in "Need Feedback" status, when code review is enough to confirm there is a problem in that one part of the code clearly identified.
• Bug #96196 - "performance_schema_accounts_size and p_s_hosts_size limited by 16384", Nice bug that can be confirmed by code review or just opening many connections was reported by Nikolai Ikhalainen from Percona. Autoscaling is broken/limited in this case.
• Bug #96340 - "Slow startup for mysql 8.0 with many tables due to the tablespace files scan". This is actually a regression comparing to 5.7, but it's visible on slow disks. It's nice to see useful discussion, explanations and patch suggested (by Sunny Bains) in this bug report created by Lalit Choudhary.

I started this summer in a beautiful Barcelona. This blog posts ends it for me. One of the good changes leaving Oracle seven years ago introduced in my life is a real freedom to work from anywhere and travel as often as I really want, both for work and for fun.

To summarize:

1. I am happy to see MySQL public bugs database still up and widely used, even though I do not work on it directly for 7 years already. It's a key service and media for cooperation for the entire MySQL Community! Just check how it happens in Bug #96340.
2. Consistency matters.
3. I still see cases when the time is wasted at bugs verification stage.
4. MySQL fine manual still have details explained incorrectly, and this is unfortunate.
5. Sometime I wonder why Percona engineers and other MySQL Community users manage to find even MTR test failures faster than anyone in Oracle cares to report and fix them. They all know magic (like actually running all tests on debug builds and checking the results, maybe). Or, maybe, they care?

* * *

Shameless self-promotion at the end. First time since 2015 I am going to attend Percona Live conference and speak there. Ticket prices increase on September 1, so using code CMESPEAK-VALERII you’ll get the best deal right now.

Magic deadlock: what locks are really set by InnoDB?

Megabytes of text had been written already on InnoDB locking and deadlocks. Still, even very simple cases of deadlocks while working with a table having only one row sometimes make people wonder what happened and why.

Today I want to check if this topic is explained well in the manual and existing blog posts and understood properly. So, it's an exercise for my dear readers and those who like to report bugs as much as I do.

Let's consider a very simple example. In session #1 with default transaction isolation level execute the following:

CREATE TABLE `tt` (
  `id` int(11) NOT NULL,
  `c1` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `c1` (`c1`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;
insert into tt values(1,1); -- insert a row there
select * from tt; -- check that we have row (1,1)
begin work;
select * from tt where c1=1 for update; -- we see a row (1,1) and now it's locked for us
update tt set id=id+1 where c1=1; -- and we safely increment the id

So, just a table with one row and two columns. One of columns is a PRIMARY KEY, other is UNIQUE. Why one may need a table like this? Some people (not me) may think this is a good way to create sequences and get globally unique ids generated for a set of rows, with sequence identifier being stored in column I've named c1. This happens, that's why...

Now, in session #2 execute the following:

select * from tt; -- we have row (1,1) there
select * from tt where c1=1 for update; -- let's try to use the sequence...

At this moment session #2 hangs waiting for a lock. It's expected - we actually updated the same row in an yet uncommitted transaction in session #1. This is clear.

Now, in session #1, try to do the following:

select * from tt where c1=1 for update; -- you'll see a row (2,1), as you've already incremented counter

But interesting thing happens in session #2 in the meantime:

ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

If you do not trust me, just try this with the following isolation level for both sessions:

mysql> select @@tx_isolation;
+-----------------+
| @@tx_isolation  |
+-----------------+
| REPEATABLE-READ |
+-----------------+
1 row in set (0.00 sec)

At this moment you can take a break in reading, and check the output of SHOW ENGINE INNODB STATUS from session #2. On MySQL 5.6.16 here I see the following (details of report may depend on server version and settings):

------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-02-15 18:09:20 16a8
*** (1) TRANSACTION:
TRANSACTION 36657, ACTIVE 4 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 3, OS thread handle 0x1884, query id 55 localhost ::1 root statistics
select * from tt where c1=1 for update
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 242 page no 4 n bits 72 index `c1` of table `test`.`tt` trx id 36657 lock_mode X waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 32

 0: len 4; hex 80000001; asc     ;;
 1: len 4; hex 80000001; asc     ;;

*** (2) TRANSACTION:
TRANSACTION 36656, ACTIVE 10 sec starting index read, thread declared inside InnoDB 5000
mysql tables in use 1, locked 1
6 lock struct(s), heap size 1184, 6 row lock(s), undo log entries 2
MySQL thread id 5, OS thread handle 0x16a8, query id 56 localhost ::1 root statistics
select * from tt where c1=1 for update
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 242 page no 4 n bits 72 index `c1` of table `test`.`tt` trx id 36656 lock_mode X locks rec but not gap
Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 32

 0: len 4; hex 80000001; asc     ;;
 1: len 4; hex 80000001; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 242 page no 4 n bits 72 index `c1` of table `test`.`tt` trx id 36656 lock_mode X waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 2; compact format; info bits 32

 0: len 4; hex 80000001; asc     ;;
 1: len 4; hex 80000001; asc     ;;

*** WE ROLL BACK TRANSACTION (1)


This is your problem statement: can you explain the deadlock above based on the output of INNODB STATUS or some other sources of information? Do you know what exact locks are really set by each session?

Take your time to write down your exact explanation, in a comment here or in separate blog post. I wonder if your explanation mentions "intention" locks of any kind, "gap" locks, "next key" locks and so on. I've read very creative texts on similar topic, and would not mind to read some more in the comments... I also wonder to know how you are going to prove your points.

We see one record lock that session holds and two lock waits in the above. All of them are obviously related to poor record with values (1,1) in the unique index named c1... You surely know that primary key value is a part of any secondary key in InnoDB, so this is all clear. But why session that already got X lock on this record has to wait to get X lock on the same(?) record? Note also 6 row locks for one of transactions in the report above...

You can surely try to rely on the manual in explaining this. But there I fail to see even clear explanation of what exact locks are set by SELECT ... FOR UPDATE in cases like this. All it says is the following:

"For SELECT ... FOR UPDATE or SELECT ... LOCK IN SHARE MODE, locks are acquired for scanned rows, and expected to be released for rows that do not qualify for inclusion in the result set (for example, if they do not meet the criteria given in the WHERE clause). However, in some cases, rows might not be unlocked immediately because the relationship between a result row and its original source is lost during query execution."

and later:

"For index records the search encounters, SELECT ... FROM ... FOR UPDATE blocks other sessions from doing SELECT ... FROM ... LOCK IN SHARE MODE or from reading in certain transaction isolation levels."

I've already reported some documentation requests while trying to explain this deadlock based on the manual. I'll list them all eventually. I hope you'll report several more bugs while trying to solve and discussing this exercise.

Now, why should you care? Because I am going to buy a beer (or any drink you prefer) for everybody who will post good (even if not entirely correct) explanation of this deadlock and make me aware of it, and/or report new valid bug based on this test case! I may be able to do this during PLMCE 2014 (still not sure if I go there, waiting for the decisions on 2 BOF sessions I've submitted) or during some conference later.

So, let's fun begin! You can expect summary post about this exercise (with a list of winners, my own explanation of this case, if still needed, and some ways to study the details) before April 1, 2014 :)