Mysql query is too slow for what it is, help me debug it

MySQL

I have the following query which takes about 5 seconds to complete, it used to be 0.5s, then 1s, 2s now we are at 5s despite the fact that the amount of data in database has not changed! This query makes a select to get a portion of data to process and update some columns (no new rows are added), normally it has a "limit 500" but query time with "limit 1" and "limit 500" is the same, so for the simplicity I changed this post to "limit 1".

I made a copy of production table on the same server to be able to run various tests and changes without hurting the production data, also some data was obfuscated but all the queries and their outputs are real

The table “test” has 34 million rows and 11.3GB size of which index is 3.3GB. The server is Freebsd 13.2, mysql 8.0.35 on pretty decent Samsung nvme drive, 64GB ram and innodb_buffer_pool_size = 42G. Server is not swapping and has nearly 4GB free memory. There is quite a bit of disk IO load coming from queries to other databases hosted on the same server (and probably mostly binary log because this is replication master), however if I disable all other queries and run only the query in question the execution time is exactly the same.

The slow query:

SELECT t_channel_id,login FROM test WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
+--------------+---------------+
| t_channel_id | login         |
+--------------+---------------+
| 933271419    | sunday1funday |
+--------------+---------------+
1 row in set (4.43 sec)

Index is properly used and covers all WHERE columns,
If I remove column videos_scanned_lock from the query the time is 0.35s (still slow but much faster)
if I remove ONLY column t_channel_id from the query time is 0s

I have a theory why the time was much faster at the beginning and now its around 5s. We are now processing records around 30th million row (out of 34) and in the beginning the selected rows were from a beginning of the table and now like “almost the whole table has to be scanned first in order to get to the results”. But is 34 million records a lot for mysql? I suppose not, the whole table is less than 1/4th of innodb buffer size. As a proof of this theory, in previous paragraph I wrote that if I remove column t_channel_id from the query, time is 0s – this is because if I remove this column there are shown results from the beginning of the table. Second proof, is that the query gives certain result, if I change value of t_channel_id for this result into a much smaller number the query time will be much shorter (because with lower ID it will be found earlier). I am pretty sure I answered my own question BUT why this is happening? I believe something must be misconfigured but I cannot find what it is and I hope to find an answer here. Any tips to improve this situation are appreciated 🙂

Below I provide debug data: show create table, profiler, describe analyze and my.cnf

SHOW CREATE TABLE test;

CREATE TABLE `test` (
  `channel_id` bigint NOT NULL AUTO_INCREMENT,
  `t_channel_id` varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_0900_bin DEFAULT NULL,
  `login` varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_bin NOT NULL,
  `display_name` varchar(255) CHARACTER SET utf8mb4 COLLATE utf8mb4_bin DEFAULT NULL,
  `videos_scanned` datetime DEFAULT NULL,
  `videos_scanned_lock` int NOT NULL DEFAULT '0',
  PRIMARY KEY (`channel_id`) USING BTREE,
  UNIQUE KEY `login` (`login`),
  KEY `t_channel_id_2` (`t_channel_id`,`videos_scanned`,`videos_scanned_lock`)
) ENGINE=InnoDB AUTO_INCREMENT=34626837 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin
describe SELECT t_channel_id,login FROM test WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
+----+-------------+-------+------------+-------+----------------+----------------+---------+------+----------+----------+-----------------------+
| id | select_type | table | partitions | type  | possible_keys  | key            | key_len | ref  | rows     | filtered | Extra                 |
+----+-------------+-------+------------+-------+----------------+----------------+---------+------+----------+----------+-----------------------+
|  1 | SIMPLE      | test  | NULL       | range | t_channel_id_2 | t_channel_id_2 | 1023    | NULL | 16992061 |     1.00 | Using index condition |
+----+-------------+-------+------------+-------+----------------+----------------+---------+------+----------+----------+-----------------------+
describe analyze SELECT t_channel_id,login FROM test WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit
1;
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                                                                                                                                                                                                                                                                             |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Limit: 1 row(s)  (cost=7.65e+6 rows=1) (actual time=4407..4407 rows=1 loops=1)
    -> Index range scan on test using t_channel_id_2 over (NULL < t_channel_id), with index condition: ((test.videos_scanned_lock = 0) and (test.t_channel_id is not null) and (test.videos_scanned is null))  (cost=7.65e+6 rows=17e+6) (actual time=4407..4407 rows=1 loops=1)
 |
+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (4.41 sec)
SET profiling = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

SELECT t_channel_id,login FROM test WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
+--------------+---------------+
| t_channel_id | login         |
+--------------+---------------+
| 933271419    | sunday1funday |
+--------------+---------------+
1 row in set (4.43 sec)

show profile cpu;
+--------------------------------+----------+----------+------------+
| Status                         | Duration | CPU_user | CPU_system |
+--------------------------------+----------+----------+------------+
| starting                       | 0.000142 | 0.000372 |   0.000036 |
| Executing hook on transaction  | 0.000063 | 0.000048 |   0.000004 |
| starting                       | 0.000027 | 0.000022 |   0.000002 |
| checking permissions           | 0.000028 | 0.000025 |   0.000003 |
| checking permissions           | 0.000018 | 0.000016 |   0.000001 |
| Opening tables                 | 0.000098 | 0.000094 |   0.000009 |
| init                           | 0.000025 | 0.000019 |   0.000002 |
| System lock                    | 0.000026 | 0.000024 |   0.000002 |
| optimizing                     | 0.000091 | 0.000084 |   0.000008 |
| statistics                     | 0.000284 | 0.000269 |   0.000026 |
| preparing                      | 0.000126 | 0.000119 |   0.000011 |
| executing                      | 4.426675 | 6.156588 |   0.156978 |
| end                            | 0.000016 | 0.000005 |   0.000001 |
| query end                      | 0.000004 | 0.000003 |   0.000000 |
| waiting for handler commit     | 0.000005 | 0.000005 |   0.000001 |
| closing tables                 | 0.000006 | 0.000006 |   0.000000 |
| freeing items                  | 0.000010 | 0.000014 |   0.000002 |
| logging slow query             | 0.000027 | 0.000020 |   0.000001 |
| cleaning up                    | 0.000008 | 0.000007 |   0.000001 |
+--------------------------------+----------+----------+------------+
19 rows in set, 1 warning (0.00 sec)
[mysqld]
user                            = mysql
port                            = 3306
socket                          = /tmp/mysql.sock
bind-address                    = 0.0.0.0
datadir                         = /var/db/mysql
log-output                      = FILE
relay-log-recovery              = 1
slow-query-log                  = 1
server-id                       = 29
sync_binlog                     = 1
sync_relay_log                  = 1
binlog_cache_size               = 16M
binlog_expire_logs_seconds      = 43200
default_password_lifetime       = 0
enforce-gtid-consistency        = 1
gtid-mode                       = On
safe-user-create                = 1
lower_case_table_names          = 1
explicit-defaults-for-timestamp = 1
myisam-recover-options          = BACKUP,FORCE
table_open_cache                = 16384
table_definition_cache          = 8192
net_retry_count                 = 16384
key_buffer_size                 = 256M
max_allowed_packet              = 64M
long_query_time                 = 0.2
innodb_buffer_pool_size         = 42G
innodb_data_home_dir            = /var/db/mysql
innodb_log_group_home_dir       = /var/db/mysql
innodb_data_file_path           = ibdata1:128M:autoextend
innodb_temp_data_file_path      = ibtmp1:128M:autoextend
innodb_flush_method             = O_DSYNC
innodb_log_buffer_size          = 32M
innodb_write_io_threads         = 12
innodb_read_io_threads          = 12
innodb_autoinc_lock_mode        = 2
innodb_redo_log_capacity        = 8192M
log_error                       = /var/db/mysql/mysql-error.log
slow_query_log_file             = /var/db/mysql/mysql-slow.log
skip_name_resolve
mysqlx                          = 0
tls_version                     = TLSv1.2
innodb_flush_log_at_trx_commit  = 0
replica_parallel_workers        = 1
binlog_group_commit_sync_delay  = 10000

Edit for Ergest:

...
KEY `channel_id` (`videos_scanned_lock`,`channel_id`,`t_channel_id`) USING BTREE
SELECT t_channel_id,login FROM test force index (channel_id) WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
+--------------+----------------+
| t_channel_id | login          |
+--------------+----------------+
| 921437844    | marryme2       |
+--------------+----------------+
1 row in set (50.80 sec)
describe SELECT t_channel_id,login FROM test force index (channel_id) WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
+----+-------------+-------+------------+------+---------------+------------+---------+-------+-------+----------+------------------------------------+
| id | select_type | table | partitions | type | possible_keys | key        | key_len | ref   | rows  | filtered | Extra                              |
+----+-------------+-------+------------+------+---------------+------------+---------+-------+-------+----------+------------------------------------+
|  1 | SIMPLE      | test  | NULL       | ref  | channel_id    | channel_id | 4       | const | 68378 |     9.00 | Using index condition; Using where |
+----+-------------+-------+------------+------+---------------+------------+---------+-------+-------+----------+------------------------------------+
1 row in set, 1 warning (0.00 sec)
describe format=json SELECT t_channel_id,login FROM test force index (channel_id) WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
....
 {
  "query_block": {
    "select_id": 1,
    "cost_info": {
      "query_cost": "2094461.53"
    },
    "table": {
      "table_name": "test",
      "access_type": "ref",
      "possible_keys": [
        "t_channel_id_2",
        "channel_id"
      ],
      "key": "channel_id",
      "used_key_parts": [
        "videos_scanned_lock"
      ],
      "key_length": "4",
      "ref": [
        "const"
      ],
      "rows_examined_per_scan": 16992061,
      "rows_produced_per_join": 1529285,
      "filtered": "9.00",
      "index_condition": "(`db`.`test`.`t_channel_id` is not null)",
      "cost_info": {
        "read_cost": "395255.43",
        "eval_cost": "152928.54",
        "prefix_cost": "2094461.53",
        "data_read_per_join": "4G"
      },
      "used_columns": [
        "t_channel_id",
        "login",
        "videos_scanned",
        "videos_scanned_lock"
      ],
      "attached_condition": "(`db`.`test`.`videos_scanned` is null)"
    }
  }
} |

For @Rick James

it simply does not work

show create table test;
....
KEY `t_channel_id` (`t_channel_id`,`login`,`videos_scanned`,`videos_scanned_lock`)
SELECT t_channel_id,login FROM test force index (t_channel_id) WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_loc
k=0 limit 1;
+--------------+----------------+
| t_channel_id | login          |
+--------------+----------------+
| 921437844    | blahblahcar |
+--------------+----------------+
1 row in set (9.99 sec)
describe SELECT t_channel_id,login FROM test force index (t_channel_id) WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
+----+-------------+-------+------------+-------+---------------+--------------+---------+------+----------+----------+--------------------------+
| id | select_type | table | partitions | type  | possible_keys | key          | key_len | ref  | rows     | filtered | Extra                    |
+----+-------------+-------+------------+-------+---------------+--------------+---------+------+----------+----------+--------------------------+
|  1 | SIMPLE      | test  | NULL       | range | t_channel_id  | t_channel_id | 1023    | NULL | 16992061 |     0.02 | Using where; Using index |
+----+-------------+-------+------------+-------+---------------+--------------+---------+------+----------+----------+--------------------------+
explain format=json SELECT t_channel_id,login FROM test force index (t_channel_id) WHERE t_channel_id IS NOT NULL AND videos_scanned IS NULL AND videos_scanned_lock=0 limit 1;
{
  "query_block": {
    "select_id": 1,
    "cost_info": {
      "query_cost": "4712106.82"
    },
    "table": {
      "table_name": "test",
      "access_type": "range",
      "possible_keys": [
        "t_channel_id"
      ],
      "key": "t_channel_id",
      "used_key_parts": [
        "t_channel_id"
      ],
      "key_length": "1023",
      "rows_examined_per_scan": 16992061,
      "rows_produced_per_join": 3906,
      "filtered": "0.02",
      "using_index": true,
      "cost_info": {
        "read_cost": "4711716.19",
        "eval_cost": "390.62",
        "prefix_cost": "4712106.82",
        "data_read_per_join": "11M"
      },
      "used_columns": [
        "t_channel_id",
        "login",
        "videos_scanned",
        "videos_scanned_lock"
      ],
      "attached_condition": "((`db`.`test`.`videos_scanned_lock` = 0) and (`db`.`test`.`t_channel_id` is not null) and (`db`.`test`.`videos_scanned` is null))"
    }
  }

Best Answer

PROFILE is rarely of any use.

This composite index should help

INDEX(videos_scanned, videos_scanned_lock, -- either order is OK
      t_channel_id, login)   -- to make the INDEX "covering" 

The short explanation (for your query):

  1. Start the index with columns tested with =
  2. then ranges tests (such as IS NOT NULL)
  3. finally all other columns needed (to make it "covering").

Long explanation: see my Index Cookbook