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.