Why does this mysql query take so long?

dba.stackexchange https://dba.stackexchange.com/questions/267901

Question

I have a MySQL server (ver 5.6) that is well equipped with hardware (Linux, in AWS, 32GB RAM, 56 CPUs), and according to top and iotop, it isn't even feeling warm; yet this query takes something like 2 hours (the actual query, not the explain):

mysql> explain
    -> SELECT
    -> DATE_FORMAT(DATE('2020-04-14'), '%m/%d/%Y') AS "Gaming Day",
    -> g.name AS "Game name",
    -> u.username AS "User Id",
    -> ga.game_instance_id AS "Game Round Id",
    -> gt.user_transaction_id AS "Transaction Id",
    -> ga.type AS "Transaction Type",
    -> ga.amount AS "Transaction Amount",
    -> CONVERT_TZ(ga.created_timestamp, 'UTC', 'SYSTEM') AS "Transaction Date Time (EST)"
    -> FROM spin.game_action ga
    -> INNER JOIN spin.game_instance gi
    -> ON gi.game_instance_id = ga.game_instance_id
    -> INNER JOIN spin.game_transaction gt
    -> ON gt.game_action_id = ga.game_action_id
    -> INNER JOIN spin.user u
    -> ON ga.user_id = u.user_id
    -> INNER JOIN spin.organisation_site os
    -> ON u.organisation_site_id = os.organisation_site_id
    -> INNER JOIN spin.game g
    -> ON g.game_id = ga.game_id
    -> WHERE os.hostname = 'nyx'
    -> AND gi.end_datetime BETWEEN CONVERT_TZ('2020-04-14 00:00:00', 'SYSTEM', 'UTC') AND CONVERT_TZ('2020-04-21 23:59:59', 'SYSTEM', 'UTC')
    -> AND gi.status IN ('RESOLVED', 'AUTO_COMPLETED');
+----+-------------+-------+--------+---------------------------------+---------+---------+-----------------------------+------+-------------+
| id | select_type | table | type   | possible_keys                   | key     | key_len | ref                         | rows | Extra       |
+----+-------------+-------+--------+---------------------------------+---------+---------+-----------------------------+------+-------------+
|  1 | SIMPLE      | g     | index  | PRIMARY                         | BG_UK1  | 202     | NULL                        |   60 | Using index |
|  1 | SIMPLE      | ga    | ref    | PRIMARY,GA_IX01,GA_IX02,GA_IX03 | GA_IX01 | 4       | spin.g.game_id              |  674 | Using where |
|  1 | SIMPLE      | u     | eq_ref | PRIMARY,U_UK01,U_IX_04          | PRIMARY | 4       | spin.ga.user_id             |    1 | NULL        |
|  1 | SIMPLE      | os    | eq_ref | PRIMARY                         | PRIMARY | 4       | spin.u.organisation_site_id |    1 | Using where |
|  1 | SIMPLE      | gi    | ref    | PRIMARY                         | PRIMARY | 8       | spin.ga.game_instance_id    |    1 | Using where |
|  1 | SIMPLE      | gt    | ref    | GT_IX03                         | GT_IX03 | 9       | spin.ga.game_action_id      |    1 | Using index |
+----+-------------+-------+--------+---------------------------------+---------+---------+-----------------------------+------+-------------+
6 rows in set (0.01 sec)

I tried running it under profiling, but that is basically useless:

mysql> show profile for query 2;
+----------------------+------------+
| Status               | Duration   |
+----------------------+------------+
| starting             |   0.000160 |
| checking permissions |   0.000005 |
| checking permissions |   0.000002 |
| checking permissions |   0.000003 |
| checking permissions |   0.000003 |
| checking permissions |   0.000003 |
| checking permissions |   0.000005 |
| Opening tables       |   0.000067 |
| init                 |   0.000133 |
| System lock          |   0.000201 |
| optimizing           |   0.000049 |
| statistics           |   0.000416 |
| preparing            |   0.000050 |
| executing            |   0.000005 |
| Sending data         | 999.999999 |
| end                  |   0.000010 |
| query end            |   0.000008 |
| closing tables       |   0.010543 |
| freeing items        |   0.000062 |
| logging slow query   |   0.000002 |
| logging slow query   |   0.110968 |
| cleaning up          |   0.003693 |
+----------------------+------------+
22 rows in set, 1 warning (0.01 sec)

As I understand it, Sending data covers both the actual transmission of results to the client and a major part of the processing. I am now considering how to analyse this further with the performance_schema; it is likely to reveal more useful details?

Edit

Output of SHOW GLOBAL STATUS\G: https://pastebin.com/QejRk9RA

Output of SHOW GLOBAL VARIABLES\G: https://pastebin.com/b3B76v21

Output of SHOW FULL PROCESSLIST\G: https://pastebin.com/N85YUwFj

MySQLtuner report: https://pastebin.com/HJJsCCzL

Edit 2

$ ulimit -a
time(seconds)        unlimited
file(blocks)         unlimited
data(kbytes)         unlimited
stack(kbytes)        8192
coredump(blocks)     0
memory(kbytes)       unlimited
locked memory(kbytes) 64
process              128223
nofiles              1024
vmemory(kbytes)      unlimited
locks                unlimited
rtprio               0

db3 root = iostat -xm 5 3
Linux 4.9.0-11-amd64 (db3.spin-production.gamingrealms.org)     05/27/2020      _x86_64_        (56 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.72    0.00    0.07    0.04    0.00   99.17

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.11    11.30   20.83   17.03     3.66     0.66   233.37     0.05    1.24    1.41    1.04   0.51   1.94
dm-0              0.00     0.00    0.04    0.04     0.00     0.00     8.13     0.01   99.38    3.62  184.79   1.05   0.01
dm-1              0.00     0.00   20.88   27.29     3.66     0.66   183.42     0.05    1.05    1.42    0.76   0.40   1.94

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           3.60    0.00    0.16    0.08    0.00   96.16

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00    18.60  121.40   13.80    30.00     0.27   458.59     0.13    0.93    0.92    1.10   0.49   6.64
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-1              0.00     0.00  121.40   32.40    30.00     0.27   403.13     0.13    0.82    0.91    0.47   0.43   6.64

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           1.59    0.00    0.16    0.03    0.00   98.23

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00    15.00   49.00   17.60    12.02     0.21   375.95     0.04    0.64    0.87    0.00   0.37   2.48
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00
dm-1              0.00     0.00   49.00   32.60    12.02     0.21   306.84     0.04    0.52    0.87    0.00   0.30   2.48

db3 root = top -c
top - 04:36:25 up 167 days, 21:28,  1 user,  load average: 1.97, 2.28, 2.18
Tasks: 584 total,   2 running, 582 sleeping,   0 stopped,   0 zombie
%Cpu(s):  3.4 us,  0.2 sy,  0.0 ni, 96.4 id,  0.1 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem : 32848684 total,  5421432 free, 19970372 used,  7456880 buff/cache
KiB Swap: 66916348 total, 66844172 free,    72176 used. 12286984 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
43108 root      20   0    4440   1312   1044 R  89.2  0.0 243:45.28 /bin/gzip -
18933 root      20   0    4440   1332   1048 S  61.0  0.0 107:19.61 /bin/gzip -
43107 root      20   0  249232  40072  11788 S   9.8  0.1  24:21.13 /usr/bin/innobackupex --stream=tar --user=backupuser --password=x xxxxxx --safe-slave-backup --slave-info --databa+
18932 root      20   0  249232  40024  11740 S   7.2  0.1  10:17.08 /usr/bin/innobackupex --stream=tar --user=backupuser --password=x xxxxxx --safe-slave-backup --slave-info --databa+
18934 root      20   0 1058508 147260   9648 S   4.3  0.4   6:46.18 /usr/bin/python3 /usr/bin/aws s3 cp - s3://spin.db.backup/2020-05-27-spin.tar.gz --region us-east-1
43109 root      20   0 1069768 174488   9404 S   3.6  0.5  14:16.26 /usr/bin/python3 /usr/bin/aws s3 cp - s3://spin.db.backup/2020-05-26-spin.tar.gz --region us-east-1
54915 root      20   0   45472   4396   3240 R   1.6  0.0   0:00.29 top -c
39686 mysql     20   0 21.178g 0.018t   8980 S   1.3 58.2   2979:59 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-err+
41601 root      20   0   33196  11696   5100 S   0.7  0.0  70:42.86 /usr/share/filebeat/bin/filebeat -c /etc/filebeat/filebeat.yml -path.home /usr/share/filebeat -path.config /etc/fi+
  312 root      20   0       0      0      0 S   0.3  0.0   0:36.25 [ksoftirqd/50]
 1661 sensu     20   0 1594004  28004   5676 S   0.3  0.1 127:00.25 /opt/sensu/embedded/bin/ruby /opt/sensu/bin/sensu-client -c /etc/sensu/config.json -d /etc/sensu/conf.d -e /etc/se+
11120 root      20   0  109512    684    660 S   0.3  0.0 132:39.67 /var/ossec/bin/wazuh-modulesd
24552 sensu     20   0  135144  24696      0 S   0.3  0.1 217:07.55 /usr/sbin/sensu-agent start
    1 root      20   0   57396   5144   3668 S   0.0  0.0  11:17.41 /sbin/init
...

I have run this query both when ther server seems under no load (according to top and show processlist) and when some heavy SQL jobs push it up to about 1000% CPU, and it seems not to make a lot of difference, believe it or not. The ~2 hours is what it takes with nothing going on.

Edit3

SHOW GLOBAL STATUS: https://pastebin.com/5PeBEkz7

SHOW GLOBAL VARIABLES: https://pastebin.com/SnGS28rD

SHOW FULL PROCESSLIST: https://pastebin.com/AR2WZbnM

Edit4

db3 root = hdparm -I /dev/sda

/dev/sda:
SG_IO: bad/missing sense data, sb[]:  70 00 05 00 00 00 00 0d 00 00 00 00 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

ATA device, with non-removable media
Standards:
        Likely used: 1
Configuration:
        Logical         max     current
        cylinders       0       0
        heads           0       0
        sectors/track   0       0
        --
        Logical/Physical Sector size:           512 bytes
        device size with M = 1024*1024:           0 MBytes
        device size with M = 1000*1000:           0 MBytes
        cache/buffer size  = unknown
Capabilities:
        IORDY not likely
        Cannot perform double-word IO
        R/W multiple sector transfer: not supported
        DMA: not supported
        PIO: pio0

Edit

show create table and show table status: https://pastebin.com/s9Y61GTb

Was it helpful?

Solution

Your ulimit Open Files limit of 1024 is starving MySQL for handles. From OS command prompt, ulimit -n 36000 and press Enter will dynamically make 36000 handles available - on the next stop/start of MySQL.

To make 36000 handles available over OS restart, follow this URL 

 https://glassonionblog.wordpress.com/2013/01/27/increase-ulimit-and-file-descriptors-limit/

DO NOT use 500,000 as in their example, use 36000 to enable MySQL to use up to 20000 - your open_files_limit requested.

Rate Per Second = RPS

Suggestions to consider for your AWS Parameters group

innodb_io_capacity=1900  # from 200 - you will likely need to work with AWS to get here
innodb_buffer_pool_size=16G  # from ~5 G to reduce innodb_buffer_pool_reads RPS of 36
innodb_buffer_pool_instances=8  # from 1 to reduce mutex contention
read_rnd_buffer_size=128K  # from 256K to reduce handler_read_rnd_next RPS of 15,887
thread_cache_size=16  # from 8 to reduce threads created
innodb_open_files=512  # from 300 to match table_open_cache

Applying these changes will reduce CPU busy. Your version 5.5.62-38.14 is 18 months past End of Life. New versions have better performance and additional Global Variables to improve and better manage performance. View my profile, Network profile for contact info and free downloadable Utility Scripts to assist with performance tuning.

It looks like your slow query is missing gi combination index on end_datetime and status. If you can move the TWO AND's up about 8 rows to make the JOIN selective, it may help.

OTHER TIPS

Analysis of VARIABLES and GLOBAL STATUS:

Observations:

  • Version: 5.5.62-38.14-log
  • 32 GB of RAM
  • Uptime = 7d 21:49:20
  • You are not running on Windows.
  • Running 64-bit version
  • You appear to be running entirely (or mostly) InnoDB.

The More Important Issues:

Unless you have a small dataset or a lot of other apps on the same server, innodb_buffer_pool_size (now 5G) should be larger -- say, 22G

innodb_log_file_size (256M) is rather low for the activity that you are experiencing. 1G would be better.

Assuming you have SSD drives, innodb_io_capacity should be bigger than 200. Say, 1000.

The "Query cache" seems to be turned on, but not used. Recommend

query_cache_type = OFF
query_cache_size = 0

There seem to be a lot of slow queries. Let's investigate them (in a different Question). http://mysql.rjweb.org/doc.php/mysql_analysis#slow_queries_and_slowlog

There are lots of writes per second. Let's discuss them. There may be tricks to speed up inserts/deletes/updates -- in some cases by 10x.

Your busiest type of query is UPDATE. Let's discuss what it is doing.

Since you don't use many connections (cf Max_used_connections = 6), suggest lowering max_connections from 1000 to, say, 30.

CREATE INDEX is occurring every 15 minutes. That is quite frequent; why?

I'm not a fan of autocommit=0. We can discuss, if you like. Meanwhile, note that init_connect is ignored by 'root' and other 'SUPER' users.

Details and other observations:

( innodb_buffer_pool_size / innodb_buffer_pool_instances ) = 5120M / 1 = 5120MB -- Size of each buffer_pool instance. -- An instance should be at least 1GB. In very large RAM, have 16 instances.

( Innodb_os_log_written ) = 257,579,082,240 / 683360 = 376930 /sec -- This is an indicator of how busy InnoDB is. -- Very idle or very busy InnoDB.

( Innodb_log_writes ) = 179,367,526 / 683360 = 262 /sec

( Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group / innodb_log_file_size ) = 257,579,082,240 / (683360 / 3600) / 2 / 256M = 2.53 -- Ratio -- (see minutes)

( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 683,360 / 60 * 256M / 257579082240 = 11.9 -- Minutes between InnoDB log rotations Beginning with 5.6.8, this can be changed dynamically; be sure to also change my.cnf. -- (The recommendation of 60 minutes between rotations is somewhat arbitrary.) Adjust innodb_log_file_size (now 268435456). (Cannot change in AWS.)

( innodb_flush_method ) = innodb_flush_method = -- How InnoDB should ask the OS to write blocks. Suggest O_DIRECT or O_ALL_DIRECT (Percona) to avoid double buffering. (At least for Unix.) See chrischandler for caveat about O_ALL_DIRECT

( innodb_io_capacity ) = 200 -- I/O ops per second capable on disk . 100 for slow drives; 200 for spinning drives; 1000-2000 for SSDs; multiply by RAID factor.

( innodb_stats_on_metadata ) = innodb_stats_on_metadata = ON -- Re-analyze table when touching stats. -- ON is likely to slow down certain SHOWs and information_schema accesses.

( expand_fast_index_creation ) = expand_fast_index_creation = OFF -- ALTER and OPTIMIZE may be greatly sped up by using ON. -- Probably better to be ON.

( innodb_recovery_update_relay_log ) = innodb_recovery_update_relay_log = OFF -- Helps avoid replication errors after a crash.

( innodb_import_table_from_xtrabackup ) = 0 -- Useful for transportable tablespaces

( sync_binlog ) = 0 -- Use 1 for added security, at some cost of I/O =1 may lead to lots of "query end"; =0 may lead to "binlog at impossible position" and lose transactions in a crash, but is faster.

( innodb_print_all_deadlocks ) = innodb_print_all_deadlocks = OFF -- Whether to log all Deadlocks. -- If you are plagued with Deadlocks, turn this on. Caution: If you have lots of deadlocks, this may write a lot to disk.

( character_set_server ) = character_set_server = latin1 -- Charset problems may be helped by setting character_set_server (now latin1) to utf8mb4. That is the future default.

( local_infile ) = local_infile = ON -- local_infile (now ON) = ON is a potential security issue

( Qcache_free_memory / query_cache_size ) = 54,508,208 / 52M = 100.0% -- Pct Query Cache free -- lower query_cache_size (now 54525952) Lowering it releases RAM for other uses, but since the free space will vary over time, this one reading may fool you.

( Qcache_not_cached / (Qcache_hits + Com_select + Qcache_not_cached) ) = 252,613 / (0 + 253801 + 252613) = 49.9% -- Percent of SELECTs that were not cached in the QC. -- QC is not very useful.

( Qcache_hits / Qcache_inserts ) = 0 / 3 = 0 -- Hit to insert ratio -- high is good -- Consider turning off the query cache.

( Qcache_hits / (Qcache_hits + Com_select) ) = 0 / (0 + 253801) = 0 -- Hit ratio -- SELECTs that used QC -- Consider turning off the query cache.

( Qcache_hits / (Qcache_hits + Qcache_inserts + Qcache_not_cached) ) = 0 / (0 + 3 + 252613) = 0 -- Query cache hit rate -- Probably best to turn off the QC.

( Qcache_free_blocks / Qcache_total_blocks ) = 1 / 1 = 100.0% -- Fragmentation in Query Cache. -- Various things.

( (query_cache_size - Qcache_free_memory) / Qcache_queries_in_cache / query_alloc_block_size ) = (52M - 54508208) / 0 / 8192 = INF -- query_alloc_block_size vs formula -- Adjust query_alloc_block_size (now 8192)

( (Queries-Questions)/Queries ) = (568240759-827878)/568240759 = 99.9% -- Fraction of queries that are inside Stored Routines. -- (Not bad if high; but it impacts the validity of some other conclusions.)

( Created_tmp_disk_tables / Questions ) = 50,164 / 827878 = 6.1% -- Pct of queries that needed on-disk tmp table. -- Better indexes / No blobs / etc.

( Handler_read_rnd_next / Com_select ) = 10,856,649,505 / 253801 = 42,776 -- Avg rows scanned per SELECT. (approx) -- Consider raising read_buffer_size (now 131072)

( (Com_insert + Com_update + Com_delete + Com_replace) / Com_commit ) = (170092830 + 199370523 + 19280137 + 0) / 178617506 = 2.18 -- Statements per Commit (assuming all InnoDB) -- Low: Might help to group queries together in transactions; High: long transactions strain various things.

( Select_scan / Com_select ) = 280,730 / 253801 = 110.6% -- % of selects doing full table scan. (May be fooled by Stored Routines.) -- Add indexes / optimize queries

( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (170092830 + 19280137 + 0 + 0 + 199370523 + 0) / 683360 = 568 /sec -- writes/sec -- 50 writes/sec + log flushes will probably max out I/O write capacity of normal drives

( Com__biggest ) = Com__biggest = Com_update -- Which of the "Com_" metrics is biggest. -- Normally it is Com_select (now 253801). If something else, then it may be a sloppy platform, or may be something else.

( back_log ) = 50 -- (Autosized as of 5.6.6; based on max_connections) -- Raising to min(150, max_connections (now 1000)) may help when doing lots of connections.

( thread_cache_size / Max_used_connections ) = 8 / 6 = 133.3% -- There is no advantage in having the thread cache bigger than your likely number of connections. Wasting space is the disadvantage.

Abnormally small:

(Com_select + Qcache_hits) / (Com_insert + Com_update + Com_delete + Com_replace) = 0.00065
Open_tables = 102
Sort_scan = 0.42 /HR

Abnormally large:

Com_begin = 261 /sec
Com_commit = 261 /sec
Com_commit + Com_rollback = 261 /sec
Com_create_index = 0.27 /HR
Com_delete = 28 /sec
Com_insert = 248 /sec
Com_show_slave_status = 0.1 /sec
Com_slave_start = 0.047 /HR
Com_slave_stop = 0.084 /HR
Com_update = 291 /sec
Innodb_buffer_pool_pages_LRU_flushed = 0.49 /sec
Innodb_buffer_pool_read_ahead = 41 /sec
Innodb_buffer_pool_write_requests / Innodb_buffer_pool_pages_flushed = 182
Innodb_checkpoint_age / innodb_log_file_size = 1.15
Innodb_ibuf_merged_inserts = 6.7 /sec
Innodb_ibuf_size = 73
Innodb_rows_updated = 291 /sec
Ssl_accepts = 93
Ssl_default_timeout = 7,200
Ssl_finished_accepts = 88
Ssl_session_cache_misses = 2
Ssl_used_session_cache_entries = 8
Ssl_verify_mode = 5
Table_locks_immediate = 51245 /sec
max_prepared_stmt_count = 100,000

Abnormal strings:

Slave_heartbeat_period = 1800
Slave_running = ON
init_connect = SET autocommit=0
innodb_fast_shutdown = 1
time_zone = +00:00

Try Optimizing table of query for better performance : 

optimize table  spin.game_action ;
optimize table  spin.game_instance; 
optimize table  spin.game_transaction; 
optimize table spin.user ;
optimize table  spin.organisation_site; 
optimize table  spin.game ;
  • If you are converting from DATETIME, you can't get the right time twice a year -- during daylight savings switchover. Use TIMESTAMP.
  • If some of those tables are "many-to-many" mapping tables, follow the tips here: http://mysql.rjweb.org/doc.php/index_cookbook_mysql#many_to_many_mapping_table
  • Please provide SHOW CREATE TABLE if you need more help with the schema and so we can judge the indexes.
  • MySQL 5.5 is really old -- Is that the best AWS has to offer?

It looks like there is a huge misestimation. You wrote this query should return about 500K of rows. MySQL Server estimates it will need to check ~40K of rows (and filter them) and chooses inefficient execution plan. Your tables are large and partitioned. As you may know partitioning is not a performance feature and it complicates things. There may be different ways to improve this query performance but I suppose the first step should be aligning it with the partitions (adding corresponding conditions to reduce the number of used partitions).

Licensed under: CC-BY-SA with attribution
Not affiliated with dba.stackexchange
scroll top