Simple indexed select query takes 350 seconds (?!) even though Filtered 100.00 “Using index condition”

Question

My logs show that the query being explained here took 352.19 seconds (and similar times for other similar queries where the contact_id and execute_at were different).

EXPLAIN SELECT 
    *
FROM
    `automations`
WHERE
    (`contact_id` = 22638
        AND `job_class_name` = 'App\Jobs\MyJob'
        AND `execute_at` = '2018-12-15 16:43:00')
        AND `automations`.`deleted_at` IS NULL
LIMIT 1

Result of EXPLAIN:

| id | select_type | table       | partitions | type | possible_keys                  | key                            | key_len | ref                     | rows | filtered | Extra                 |
|----|-------------|-------------|------------|------|--------------------------------|--------------------------------|---------|-------------------------|------|----------|-----------------------|
| 1  | SIMPLE      | automations | NULL       | ref  | cId_job_executeAt_delAt_unique | cId_job_executeAt_delAt_unique | 780     | const,const,const,const | 1    | 100.00   | Using index condition |

I am inexperienced at optimizing MySql, but my guess would be that the Explain looks great, right?

Why on earth would queries like this be taking 350+ seconds? How can I diagnose and fix?

P.S. This is related to the E_WARNING: Error while sending STMT_PREPARE packet. PID=* error I frequently see.

CREATE TABLE `automations` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `contact_id` int(10) unsigned NOT NULL,
  `job_class_name` varchar(191) COLLATE utf8mb4_unicode_ci NOT NULL,
  `execute_at` datetime NOT NULL,
  `created_at` timestamp NULL DEFAULT NULL,
  `updated_at` timestamp NULL DEFAULT NULL,
  `deleted_at` timestamp NULL DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `cId_job_executeAt_delAt_unique` (`contact_id`,`job_class_name`,`execute_at`,`deleted_at`),
  CONSTRAINT `automations_contact_id_foreign` FOREIGN KEY (`contact_id`) REFERENCES `contacts` (`id`) ON DELETE CASCADE
) ENGINE=InnoDB AUTO_INCREMENT=1519 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci

Answer 1

My queries that I thought took 352 seconds really only took 0.352 seconds! 🤦‍♂️

https://laravel.io/forum/03-04-2014-what-time-format-does-dbgetquerylog-return showed me that Laravel's DB::getQueryLog() shows "time" as milliseconds (microseconds multiplied by 1000), not seconds.

What an embarrassing mistake (poor assumption). So I need to edit my 500-point bounty question: https://stackoverflow.com/questions/53469793/e-warning-error-while-sending-stmt-prepare-packet-pid/54374937?noredirect=1#comment95579631_53469793

Answer 2

The optimal index for this query would be a composite index with 4 columns, in any order:

INDEX(contact_id, job_class_name, execute_at, deleted_at)

And, depending on the order you pick, you can get rid of one of the existing KEYs.

Watch out for backslashes. 'App\Jobs\MyJob' may be treated as App[LF]obs[CR]yJob or AppJobsMyJob.

352 seconds is really unreasonable. Perhaps something else was going on, and blocking access to the rows and/or the table? (The 352s was bogus.)

"Using index condition" is not the same as "Using index". The latter indicates a "covering index", which is not practical for this query and table.