-1

I've set up slow query logging for MySQL 5.7:

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow_query_log.log
long_query_time = 10
log_queries_not_using_indexes = 0

Then to test it, I've used MySQL Workbench and ran select sleep(12); and then verified that vim /var/log/mysql/slow_query_log.log shows that query.

So I thought everything was great. However, my slow_query_log seems to work only for my test queries such as select sleep(12); and not for real queries.

Below is an example. In some spots in my Laravel PHP app, I call \DB::enableQueryLog(); and then Log::debug(\DB::getQueryLog()); after running a query, and in those logs I see extremely slow queries (241 seconds!?), but I've never seen them in the slow_query_log.log.

array (
'query' => 'select * from `automations` where (`contact_id` = ? and `job_class_name` = ? and `execute_at` = ?) and `automations`.`deleted_at` is null limit 1',
'bindings' =>
array (
  0 => 23030,
  1 => 'App\\Jobs\\SubscribeToWebinarFollowupEmailSeries',
  2 => '2018-12-30 19:13:00',
),
'time' => 241.37,
),

How can I fix this?

P.S. I don't think my question is a duplicate of this one because in my tests the logging does work.

-1

What is the value of log_output? It should be "FILE" or "FILE,TABLE".

For that particular query, do you have a composite index on these:

INDEX(contract_id, job_class_name, execute_at, deleted_at)

(Any order will do.)

long_query_time = 10 hardly catches anything; I recommend lowering it.

  • 10 seconds because I feared cluttering the logs since I already have so many queries that took 200+ seconds SELECT @@global.log_output; says FILE. And select * from mysql.slow_log; returns 0 rows. Yes, I have 2 unique indexes: 1 is a composite of those first 3 columns, and the 2nd is a composite of all 4 (including deleted_at). I've been so confused for weeks (or even months) now. – Ryan Jan 2 at 1:34
  • Check permissions on all the directories in this path: App\\Jobs\\SubscribeToWebinarFollowupEmailSeries – Rick James Jan 2 at 2:03
  • It's not a path. I have a SubscribeToWebinarFollowupEmailSeries PHP class in app\Jobs\SubscribeToWebinarFollowupEmailSeries.php with namespace App\Jobs;. So 'App\\Jobs\\SubscribeToWebinarFollowupEmailSeries' is just a string referring to that. I always appreciate your suggestions though. – Ryan Jan 2 at 2:13
  • If log_output is FILE, then mysql.slow_log could be empty. Change it to TABLE to see if the table starts receiving both SLEEPs and that slow query. – Rick James Jan 2 at 2:21
  • SET global log_output = 'table'; select sleep(11); select * from mysql.slow_log; successfully showed the sleep query. So I assume your suggestion now is to leave log_output as 'table' and wait to see what happens with my real-world production queries (see if they appear in the table). I'll probably know on Saturday when I'll have some site visitors again. Thanks. – Ryan Jan 2 at 2:37
-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.