Strange behavior with cron and laravel scheduler

September 29, 2018 7.4k views
CentOS Applications Linux Commands
danielpcharrua
By:
danielpcharrua

Hello, I have configured a cron job with plesk in my droplet to run a laravel command every minute
/opt/plesk/php/7.1/bin/php /var/www/vhosts/website/laravel/artisan schedule:run
This executes the Laravel scheduler, that is filled with tasks to run at certain time, lets say send emails at 10:00 and send SMS at 11:00

So when the cron runs the scheduler and a task is found at the same time it executes the task, eg
9.58 no tasks
9.59 no tasks
10:00 send emails
10:01 no tasks

My problem is that FOR SOME STRANGE REASON the scheduler is delayed at some times, so the problem is like this
9.58 no tasks
9.59 no tasks
10:01 no tasks
10:01 no tasks

If I run this command from command line, it runs instantly, with no delay. But for some reason when this is executed from the cron, sometimes is delayed. I have tested the cron from inside plesk, there is a button Run now and is true, for some reason sometimes it takes about 65 seconds to run the cron job or the command artisan schedule:run

Any ideas?
This only happens in the droplet I have, not in local environment.

Sign In to Comment
17 Answers
danielpcharrua October 10, 2018

The issue was caused by depleted entropy by PHP script.

To resolve the issue generate entropy by using haveged daemon:

  1. Enable EPEL repository:

    yum install epel-release

  2. Install daemon with the following command and enable it:

    yum install haveged
    chkconfig haveged on
    systemctl start haveged

Report
unixynet September 29, 2018

The delay is typically due to a high load, deep run queue, or perhaps clock drift. On a busy server, tasks that are forked will likely incur some delay at startup (versus daemons/services that are “hot”). How busy is this box (Run: uptime; sar -q; etc)? How many tasks do you typically run at the minute mark?

Also, make sure your clock is sycned up (ex: ntpdate -s time.nist.gov).

Report
danielpcharrua September 29, 2018

Hi @unixynet I don’t think is the case of a busy server, this is the only laravel app running, the app is private so not many users are at the same time.
The results of running uptime; sar -q; etc are 10:52:05 up 4:29, 1 user, load average: 0,02, 0,04, 0,05

I have no tasks at the minute mark, only 3 tasks per day on different times… The clock is synced so this is realy strange… Any more ideas for me to try?

Report
unixynet September 29, 2018

What are the timestamps of the cron runs in the logs? Does it reflect the 1sec delay you’re seeing in your app?

Report
danielpcharrua September 29, 2018

@unixynet I’m sorry but is not a 1 sec delay, is a 1 minute delay, sometimes a 3 minutes delay.
The cron is run on time by the logs, but for some reason the artisan command is not executed on the same time that the cron runs, is like it takes some time to load so when the scheduler loads is not the same time that the cron was executed eg the cron runs at 10:05:01 -> takes time to load -> scheduler loads at 10:06:11 and skips the task that needs to execute at 10:05

cron log

Sep 29 10:05:01 localhost CROND[17311]
Sep 29 10:10:01 localhost CROND[17846]
Sep 29 10:15:01 localhost CROND[18165]

Scheduler log

Received ping at Saturday, 29-Sep-2018 10:06:11 EDT
Received ping at Saturday, 29-Sep-2018 10:10:01 EDT
Received ping at Saturday, 29-Sep-2018 10:18:55 EDT

Report
unixynet September 29, 2018

Cron looks OK. How’s your DB? Can you enable the slow log to see if any queries are slowing things down and thus affecting event clearing?

Report
danielpcharrua September 30, 2018

@unixynet I can enable the slow log but I don’t think that DB is playing here as the only task on scheduler is not involving any DB query.

The only task I have is:

$schedule->call(function () {
            return true;
        })
        ->everyMinute()
        ->pingBefore('...')

I will enable the slow log and return here.

Report
danielpcharrua September 30, 2018

@unixynet Slow query log does not fill up, so no slow queries.

But I have fresh results:

I have discovered that if I execute any artisan command during the “hang up” it takes forever. Lets say you run any artisan command at 16:24 this command is not resolved until 16:27:31 (when the system is “locked out”)

I have no more ideas… Have looked in logs and all that but NO CLUE. I think is not Laravel, maybe is a server issue. Server load is really little, is a droplet for a private app with 15 users.

Cron log:

Sep 30 16:20:01 localhost CROND[28616]
Sep 30 16:21:01 localhost CROND[854]
Sep 30 16:22:02 localhost CROND[988]
Sep 30 16:23:01 localhost CROND[1062]
Sep 30 16:24:01 localhost CROND[1132]
Sep 30 16:25:01 localhost CROND[1199]
Sep 30 16:26:01 localhost CROND[1255]
Sep 30 16:27:01 localhost CROND[1315]
Sep 30 16:28:01 localhost CROND[1411]
Sep 30 16:29:01 localhost CROND[1508]
Sep 30 16:30:01 localhost CROND[1599]
Sep 30 16:31:01 localhost CROND[1670]
Sep 30 16:32:01 localhost CROND[1742]
Sep 30 16:33:01 localhost CROND[1807]
Sep 30 16:34:01 localhost CROND[1874]
Sep 30 16:35:01 localhost CROND[1936]
Sep 30 16:36:01 localhost CROND[1995]
Sep 30 16:37:01 localhost CROND[2062]

Scheduler log:

2018-09-30 16:20:12] production.INFO: schedule call  
[2018-09-30 16:21:01] production.INFO: schedule call  
[2018-09-30 16:22:02] production.INFO: schedule call  
[2018-09-30 16:23:01] production.INFO: schedule call  
[2018-09-30 16:27:31] production.INFO: schedule call  
[2018-09-30 16:27:31] production.INFO: schedule call  
[2018-09-30 16:27:31] production.INFO: schedule call  
[2018-09-30 16:27:31] production.INFO: schedule call  
[2018-09-30 16:28:01] production.INFO: schedule call  
[2018-09-30 16:29:01] production.INFO: schedule call  
[2018-09-30 16:30:01] production.INFO: schedule call  
[2018-09-30 16:31:01] production.INFO: schedule call  
[2018-09-30 16:32:02] production.INFO: schedule call  
[2018-09-30 16:33:01] production.INFO: schedule call  
[2018-09-30 16:37:53] production.INFO: schedule call  
[2018-09-30 16:37:53] production.INFO: schedule call  
[2018-09-30 16:37:53] production.INFO: schedule call  
[2018-09-30 16:37:53] production.INFO: schedule call
Report
unixynet October 1, 2018

A cron job entry like this:

  • * * * * /usr/bin/php /home/httpgun/artisan schedule:run

Will definitely make several SQL queries. But let’s just remove any doubt and repair all tables:

mysqlcheck -r db_name

With this out of the way, have you tried the elimination approach? Remove all schedule calls and add one at a time to see where delay is introduced. If there’s delay with zero cron job, there’s a big problem with core.

Report
danielpcharrua October 1, 2018

Hi @unixynet, I have disabled the Laravel scheduler cron and create a simple cron with a php file that records time of execution, and the problem seems to still be there.. I’m thinking this is more of a server issue than a laravel. See results:

Cron logs 

Oct 1 10:01:01 localhost CROND[2315] 
Oct 1 10:02:01 localhost CROND[2388] 
Oct 1 10:03:01 localhost CROND[2440] 
Oct 1 10:04:01 localhost CROND[2493] 
Oct 1 10:05:01 localhost CROND[2566] 
Oct 1 10:06:01 localhost CROND[2627] 
Oct 1 10:07:01 localhost CROND[2743]

PHP file execution logs 

Monday, 01-Oct-2018 10:00:01 EDT 
Monday, 01-Oct-2018 10:05:42 EDT 
Monday, 01-Oct-2018 10:05:42 EDT 
Monday, 01-Oct-2018 10:05:42 EDT 
Monday, 01-Oct-2018 10:05:42 EDT 
Monday, 01-Oct-2018 10:05:42 EDT 
Monday, 01-Oct-2018 10:06:01 EDT 
Monday, 01-Oct-2018 10:07:01 EDT
Report
unixynet October 1, 2018

crond reports correct timestamps but not laravel. Try clearing compiled classes (php artisan clear-compiled). Hopefully that doesn’t uncover other issues. Also clear the cache (php artisan cache:clear).

You’re not using a daemon like Memcached or Redis by any chance? I know It’s a long shot but the connection could be timing out and dragging run time if the service is down.

Report
unixynet October 1, 2018

Ah missed this part: “and create a simple cron with a php file that records time of execution, and the problem seems to still be there.”

Anything in the error_log from php? What’s your phpinfo() like?

Report
danielpcharrua October 1, 2018

@unixynet cache is cleared often, for example yesterday. No Memcached or Redis installed.
PHP error_log is not showing anything that we can link with this errors and phpinfo() is here

Report
unixynet October 2, 2018

I know this problem has dragged but perhaps if you could create a quick bash script like this this:

!/bin/bash

echo $(date);

exit 0

And then cron it:

  • * * * * /path/to/job.sh >> /tmp/date.log
Report
  • danielpcharrua October 2, 2018

    Yes sure, I have created the script, and for my surprise the logs are like the cron ones, with no delay at all nor repeated tasks. Maybe this is a PHP issue? Did you check phpinfo() for anything I’m missing?

    Tue Oct 2 04:39:01 EDT 2018
Tue Oct 2 04:40:01 EDT 2018
Tue Oct 2 04:41:01 EDT 2018
Tue Oct 2 04:42:01 EDT 2018
Tue Oct 2 04:43:01 EDT 2018
Tue Oct 2 04:44:01 EDT 2018
Tue Oct 2 04:45:01 EDT 2018
Tue Oct 2 04:46:01 EDT 2018
Tue Oct 2 04:47:01 EDT 2018
Tue Oct 2 04:48:01 EDT 2018
Tue Oct 2 04:49:01 EDT 2018
Tue Oct 2 04:50:01 EDT 2018
Tue Oct 2 04:51:01 EDT 2018
Tue Oct 2 04:52:02 EDT 2018
Tue Oct 2 04:53:01 EDT 2018
Tue Oct 2 04:54:01 EDT 2018
Tue Oct 2 04:55:01 EDT 2018
Tue Oct 2 04:56:01 EDT 2018
Tue Oct 2 04:57:01 EDT 2018
Tue Oct 2 04:58:01 EDT 2018
Tue Oct 2 04:59:01 EDT 2018
Tue Oct 2 05:00:01 EDT 2018
Tue Oct 2 05:01:01 EDT 2018
Tue Oct 2 05:02:01 EDT 2018
Tue Oct 2 05:03:01 EDT 2018
    Report
unixynet October 2, 2018

Can you try disabling opcache and also remove the opcachegetstatus from disable_functions. Also, when you created the PHP script, is it really just one line of code and in no way referencing anything from the Laravel framework?

Try switching to php 7.2 or perhaps even 5.6 to see if this is configuration related. Also try this from the command line:

/opt/plesk/php/7.1/bin/php -v

Any warnings or errors?

Report
danielpcharrua October 3, 2018

@unixynet I have fresh news:

Yesterday I have created a simple php script and named it test2.php

echo date(‘Y-m-d H:i:s’) . PHP_EOL;

As I’m using laravel and it needs PHP 7.1, my cron call php files with php 7.1 path:
/opt/plesk/php/7.1/bin/php test2.php
and not using the default 5.6 php cli:
php test2.php

The interesting thing is that if I run from console it hits a moment that the system is lagged and stops execution, then resume it after some minutes…
watch -n1 /opt/plesk/php/7.1/bin/php /var/www/vhosts/winnersmartialarts.com/adm/test2.php

But if I run with only php, never is stopped, even when the system is lagged…
watch -n1 php /var/www/vhosts/winnersmartialarts.com/adm/test2.php

I have waited to a lag window (lasts about 3-5 minutes) and when using php 7.1 the system is stopped (I cant run any php script using the 7.1 path) BUT the system let me to run using only php....

Example
watch -n1 php /var/www/vhosts/winnersmartialarts.com/adm/test2.php
runs forever as it should…

Today an engineer from Plesk have accessed the server and he told me he can’t reproduce the “watch” test, mysteriously after he has logged in to the server, the issue disappeared and now the server is running smooth as it should (for now).

I’ll update if the issue is still going on.

Thank you for your time.

Report
unixynet October 3, 2018

Interesting indeed. The strace tool would have definitely helped in pinpointing the lag. So if “php” is different from “/opt/plesk/php/7.1/bin/php”, I wonder what’s in plesk’s php that would cause such a lag. I was suspecting something was off with php hence my asking to at switch to 5.6 or 7.2 as that would imply skipping modules, ini settings, and other oddities that could be under 7.1.

I wonder what php version is the cli one:

which php
php -v

Hopefully whatever the Plesk engineer did is a good long term fix.

Cheers

Report
Have another answer? Share your knowledge.

You can type !ref in this text area to quickly search our full set of tutorials, documentation & marketplace offerings and insert the link!

Related