A little backstory, some time ago we started to experience high CPU system time on one of our MySQL databases. This database was also suffering from high disk utilization so we figured that those things are connected. And since we already had plans to migrate it to SSD we thought that it will solve both issues.

It helped… but not for long.

For a couple of weeks after migration CPU graph was like this:

But now we are back to this:

DB stats:

• MySQL version – 5.7.20
• OS – Debian
• DB size – 1.2Tb
• RAM – 700Gb
• CPU cores – 56
• Peek load – about 5kq/s read, 600q/s write (although select queries are often pretty complex)
• Threads – 50 running, 300 connected
• It has about 300 tables, all InnoDB

MySQL config:

[client] port = 3306 socket = /var/run/mysqld/mysqld.sock  [mysqld_safe] pid-file = /var/run/mysqld/mysqld.pid socket = /var/run/mysqld/mysqld.sock nice = 0  [mysqld] user = mysql pid-file = /var/run/mysqld/mysqld.pid socket = /var/run/mysqld/mysqld.sock port = 3306 basedir = /usr datadir = /opt/mysql-data tmpdir = /tmp lc-messages-dir = /usr/share/mysql explicit_defaults_for_timestamp  sql_mode = STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION  log-error = /opt/mysql-log/error.log  # Replication  server-id = 76  gtid-mode = ON enforce-gtid-consistency = true  relay-log = /opt/mysql-log/mysql-relay-bin relay-log-index = /opt/mysql-log/mysql-relay-bin.index replicate-wild-do-table = dbname.%  log-bin = /opt/mysql-log/mysql-bin.log expire_logs_days = 7 max_binlog_size = 1024M binlog-format = ROW log-bin-trust-function-creators = 1 log_slave_updates = 1  # Disabling symbolic-links is recommended to prevent assorted security risks symbolic-links=0  # * IMPORTANT: Additional settings that can override those from this file! #   The files must end with '.cnf', otherwise they'll be ignored. # !includedir /etc/mysql/conf.d/  # Here goes  skip_name_resolve = 1 general_log = 0 slow_query_log = 1 slow_query_log_file = /opt/mysql-log/slow.log long_query_time = 3  max_allowed_packet = 16M max_connections = 700 max_execution_time = 200000  open_files_limit = 32000 table_open_cache = 8000 thread_cache_size = 128 innodb_buffer_pool_size = 550G innodb_buffer_pool_instances = 28 innodb_log_file_size = 15G innodb_log_files_in_group = 2 innodb_flush_method = O_DIRECT  max_heap_table_size = 16M tmp_table_size = 128M join_buffer_size = 1M sort_buffer_size = 2M  innodb_lru_scan_depth = 256  query_cache_type = 0 query_cache_size = 0  innodb_temp_data_file_path = ibtmp1:12M:autoextend:max:30G  

Other observations

perf of mysql process during peak load:

68,31%    68,31%  mysqld  [kernel.kallsyms]    [k] _raw_spin_lock                                                                                                                                                                                                            - _raw_spin_lock                                                                                                                                                                                                                                                                 + 51,63% 0x7fd118e9dbd9                                                                                                                                                                                                                                                       + 48,37% 0x7fd118e9dbab                                                                                                                                                                                                                                                 +   37,36%     0,02%  mysqld  libc-2.19.so         [.] 0x00000000000f4bd9                                                                                                                                                                                                     +   33,83%     0,01%  mysqld  libc-2.19.so         [.] 0x00000000000f4bab                                                                                                                                                                                                     +   26,92%     0,00%  mysqld  libpthread-2.19.so   [.] start_thread                                                                                                                                                                                                           +   26,82%     0,00%  mysqld  mysqld               [.] pfs_spawn_thread                                                                                                                                                                                                       +   26,82%     0,00%  mysqld  mysqld               [.] handle_connection                                                                                                                                                                                                      +   26,81%     0,01%  mysqld  mysqld               [.] do_command(THD*)                                                                                                                                                                                                       +   26,65%     0,02%  mysqld  mysqld               [.] dispatch_command(THD*, COM_DATA const*, enum_server_command)                                                                                                                                                           +   26,29%     0,01%  mysqld  mysqld               [.] mysql_parse(THD*, Parser_state*)                                                                                                                                                                                       +   24,85%     0,01%  mysqld  mysqld               [.] mysql_execute_command(THD*, bool)                                                                                                                                                                                      +   23,61%     0,00%  mysqld  mysqld               [.] handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long)                                                                                                                                        +   23,54%     0,00%  mysqld  mysqld               [.] 0x0000000000374103                                                                                                                                                                                                     +   19,78%     0,00%  mysqld  mysqld               [.] JOIN::exec()                                                                                                                                                                                                           +   19,13%     0,15%  mysqld  mysqld               [.] sub_select(JOIN*, QEP_TAB*, bool)                                                                                                                                                                                      +   13,86%     1,48%  mysqld  mysqld               [.] row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)                                                                                                                        +    8,48%     0,25%  mysqld  mysqld               [.] ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int)                                                                                                                                                 +    7,93%     0,00%  mysqld  [unknown]            [.] 0x00007f40c4d7a6f8                                                                                                                                                                                                     +    7,57%     0,00%  mysqld  mysqld               [.] 0x0000000000828f74                                                                                                                                                                                                     +    7,25%     0,11%  mysqld  mysqld               [.] handler::ha_index_next_same(unsigned char*, unsigned char const*, unsigned int)                                                                                                                                        

It shows that mysql is spending a lot of time on spin_locks. I was hoping to get some clue on where are those locks are coming from, sadly, no luck.

Query profile during high load shows extreme amount of context switches. I used select * from MyTable where pk = 123, MyTable has about 90M rows. Profile output:

Status               Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function       Source_file          Source_line starting             0,000756 0,028000 0,012000   81                1                   0            0             0             0                 0                 0                 0                              checking permissions 0,000057 0,004000 0,000000   4                 0                   0            0             0             0                 0                 0                 0     check_access          sql_authorization.cc 810 Opening tables       0,000285 0,008000 0,004000   31                0                   0            40            0             0                 0                 0                 0     open_tables           sql_base.cc          5650 init                 0,000304 0,012000 0,004000   31                1                   0            0             0             0                 0                 0                 0     handle_query          sql_select.cc        121 System lock          0,000303 0,012000 0,004000   33                0                   0            0             0             0                 0                 0                 0     mysql_lock_tables     lock.cc              323 optimizing           0,000196 0,008000 0,004000   20                0                   0            0             0             0                 0                 0                 0     optimize              sql_optimizer.cc     151 statistics           0,000885 0,036000 0,012000   99                6                   0            0             0             0                 0                 0                 0     optimize              sql_optimizer.cc     367 preparing            0,000794 0,000000 0,096000   76                2                   32           8             0             0                 0                 0                 0     optimize              sql_optimizer.cc     475 executing            0,000067 0,000000 0,000000   10                1                   0            0             0             0                 0                 0                 0     exec                  sql_executor.cc      119 Sending data         0,000469 0,000000 0,000000   54                1                   32           0             0             0                 0                 0                 0     exec                  sql_executor.cc      195 end                  0,000609 0,000000 0,016000   64                4                   0            0             0             0                 0                 0                 0     handle_query          sql_select.cc        199 query end            0,000063 0,000000 0,000000   3                 1                   0            0             0             0                 0                 0                 0     mysql_execute_command sql_parse.cc         4968 closing tables       0,000156 0,000000 0,000000   20                4                   0            0             0             0                 0                 0                 0     mysql_execute_command sql_parse.cc         5020 freeing items        0,000071 0,000000 0,004000   7                 1                   0            0             0             0                 0                 0                 0     mysql_parse           sql_parse.cc         5596 cleaning up          0,000533 0,024000 0,008000   62                0                   0            0             0             0                 0                 0                 0     dispatch_command      sql_parse.cc         1902 

Peter Zaitsev made a post recently about context switches, where he says:

In the real world, though, I would not worry about contention being a big issue if you have less than ten context switches per query.

But it shows more than 600 switches!

What can cause these symptoms and what can be done about it? I`ll appreciate any pointers or info on the matter, everything that I come across so far is rather old and/or inconclusive.

P.S. I will gladly provide additional information, if required.