1

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
  • Another error I'm seeing (quite possibly related) is that ~20 times per day, I see PDOException: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry on various tables. It always looks as if a user is trying to register on my site multiple times in the same second. I wonder if the unique indexes I have on certain timestamp columns could be causing some of the slowness. (I only have those unique indexes as a remnant of an ETL that needed it because a 3rd party accidentally duplicated some records.) I don't have many simultaneous visitors, but I wonder if it's related. – Ryan Dec 15 '18 at 21:25
0

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.

  • I updated my question to show that I'm already using a 4-column composite index, so that isn't the root cause of the slowness. I don't think the backslashes are problematic; the query often works fine. Is there anything else you could elaborate on for your last 2 paragraphs or any other ideas? Thanks. – Ryan Dec 15 '18 at 21:06
  • (I think Laravel is appropriately handling the backslashes via parameterized query.) – Ryan Dec 15 '18 at 21:18
  • 1
    @Ryan - Turn on the slowlog in hopes of catching something useful. If you can spot the query taking a long time, do SHOW FULL PROCESSLIST; (as root) to see if you can spot some other take doing something. (I'm running out of ideas.) – Rick James Dec 16 '18 at 0:25
  • Interesting. E.g. getting alerts from stackoverflow.com/a/33253451/470749. Thanks. – Ryan Dec 16 '18 at 1:46
-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

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.