Scheduler running with delay (not on time)

break it down even further and just log the time in Laravel log (without any schedule command)

    protected function schedule(Schedule $schedule)
    {
        Log::info('schedule call');
    }

Hi @Snapey 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. Mysql queries are not slow (I have activate the slow query log)

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  

have you tried your own cron outside of laravel like a simple php script and see what happens? you could also get another droplet and see if the issue is present there to know if its load or something else causing this

@shez1983 I have tested with another cron job, independent of laravel. And the cron is also delayed when the system is "locked", for some moments it seems more of a server failure or php failure than a Laravel issue. The strange is that I can't find any errors related. Or maybe as laravel is "locking" the system all other tasks are also locked.

what is your hosting environment?

@Snapey CentOS 7.4 x64, 1vcpu, 2gbRAM, using Plesk and PHP-FPM 7.1

I think this is more of a server miss-config than a Laravel issue at this moment.

when you say system is locked what do you mean? increased resources/server is doing too much so cant cope? if this is the case then you need to identify why this is happening and either refactor the code (if applicable) or increase your server size OR put all cronjobs/schedule/commands to run in a seaprate server so they are not impacted by this..

web server?

@shez1983 When I say system is locked, I mean that if I run an any artisan command at 16:34:34, it will be queued and run at 16:37:53 (see the scheduler log I posted before). The server does not show any high load or any errors that I can relate to the times that this happens.

@Snapey web server is a Digital Ocean Droplet (if this is your question)

I don't even know if this is a php or more of a server issue... Because cron are executed on time but the artisan commands are like queued. Or maybe cron are queued too..

@Charrua could you maybe try to add this line to your bootstrap/app.php file?

file_put_contents(__DIR__ .'/../storage/logs/laravel.log', date('Y-m-d H:i:s') .' app.php', FILE_APPEND);

To see if the delay you see is in the Laravel app or is somewhere before Laravel is hit.

Btw, is it a coincidence that after every 3rd minute you see a delay? Based on your example it happens twice between the 3rd and 7th minute. Do you see this every time around this time?

[2018-09-30 16:23:01] production.INFO: schedule call  
[2018-09-30 16:27:31] production.INFO: schedule call  // 16.24
[2018-09-30 16:27:31] production.INFO: schedule call  // 16.25
[2018-09-30 16:27:31] production.INFO: schedule call  // 16.26
[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  // 16.34
[2018-09-30 16:37:53] production.INFO: schedule call  // 16.35
[2018-09-30 16:37:53] production.INFO: schedule call  // 16.36
[2018-09-30 16:37:53] production.INFO: schedule call  

@click is not always at the same time, is like the artisan commands are put on a queue and then dispatched all at once.

2018-10-01 13:16:01 app.php
[2018-10-01 09:16:01] production.INFO: schedule call  
2018-10-01 13:17:01 app.php
[2018-10-01 09:17:01] production.INFO: schedule call  
2018-10-01 13:18:01 app.php
[2018-10-01 09:18:01] production.INFO: schedule call  
2018-10-01 13:19:01 app.php
[2018-10-01 09:19:02] production.INFO: schedule call  
2018-10-01 13:20:01 app.php
[2018-10-01 09:20:01] production.INFO: schedule call  
2018-10-01 13:23:22 app.php
2018-10-01 13:23:22 app.php
2018-10-01 13:23:22 app.php
[2018-10-01 09:23:22] production.INFO: schedule call  
[2018-10-01 09:23:22] production.INFO: schedule call  
[2018-10-01 09:23:22] production.INFO: schedule call  
2018-10-01 13:24:01 app.php
[2018-10-01 09:24:01] production.INFO: schedule call  
2018-10-01 13:25:01 app.php
[2018-10-01 09:25:01] production.INFO: schedule call  
2018-10-01 13:26:01 app.php
[2018-10-01 09:26:01] production.INFO: schedule call 

That is odd, but this shows that the app.php isn't even hit at the right time. So the delay or "queue" is not in the Laravel app I think.

Did you try running a cron without laravel? Just a plain .php file that logs the timestamp? Just to make 100% sure that laravel has nothing to do with it.

* * * * * php /path/to/test/file.php

@click I have disabled the laravel cron and setup another cron to log as you said timestamps, the same happens

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

Ok, at least we know it is not Laravel related now. I've never seen this behavior. And my linux knowledge stops here to figure out what is going on I am afraid.

Always when something odd is going on with cronjobs it had something todo with incorrect time(zones). But I don't think that is the case here because it only happens every x'th minute. It really does look like your system is busy with something and just executes the cron jobs at a later moment. But I do not know how you are able to debug/verify that.

Only thing that comes to my mind would be the famous words: "have you tried turning it off and on again?" in other words, try rebooting your machine.

@click my understanding of Linux stops here too, I have tried to restart the server but the same happens. This issue is driving me crazy. Thank you for your help.

Yes strange, I am interested in the culprit and solution when you find it. Maybe you can ask your question on www.serverfault.com, there are more linux experts than here I suppose. Explain what you see and show the examples of the cron log and the log file that is created when the single php file is executed.

@click thank you, I will post there too.

I meant apache / nginx ?

@snapey I use apache with nginx, this is by default what comes with plesk, but I can disable nginx... you can see here: https://docs.plesk.com/en-US/onyx/administrator-guide/web-servers/apache-and-nginx-web-servers-linux/apache-with-nginx.70837/

Well, thats a new one on me!

I can disable nginx if you have an idea of what can be causing this.

regardless of if you are using nginx/apache, you should have some logs which tells you what your server is doing... syslogs/access_logs etc to see whats happening

@shez1983 in the logs there is nothing related to what is happening. But I discovered something, someone else told me to create a bash script and test it with cron:

Bash script:

#!/bin/bash
echo $(date);
exit 0

Crontab:

* * * * * /var/www/vhosts/domain***/test.sh >> /var/www/vhosts/domain***/logs/date.log

But the results surprised me, they are great:

Tue Oct 2 05:08:01 EDT 2018
Tue Oct 2 05:09:01 EDT 2018
Tue Oct 2 05:10:01 EDT 2018
Tue Oct 2 05:11:01 EDT 2018
Tue Oct 2 05:12:01 EDT 2018
Tue Oct 2 05:13:01 EDT 2018
Tue Oct 2 05:14:01 EDT 2018
Tue Oct 2 05:15:01 EDT 2018
Tue Oct 2 05:16:01 EDT 2018
Tue Oct 2 05:17:01 EDT 2018
Tue Oct 2 05:18:01 EDT 2018
Tue Oct 2 05:19:02 EDT 2018
Tue Oct 2 05:20:01 EDT 2018
Tue Oct 2 05:21:01 EDT 2018
Tue Oct 2 05:22:01 EDT 2018
Tue Oct 2 05:23:01 EDT 2018
Tue Oct 2 05:24:01 EDT 2018
Tue Oct 2 05:25:01 EDT 2018
Tue Oct 2 05:26:01 EDT 2018
Tue Oct 2 05:27:01 EDT 2018
Tue Oct 2 05:28:01 EDT 2018
Tue Oct 2 05:29:01 EDT 2018
Tue Oct 2 05:30:01 EDT 2018
Tue Oct 2 05:31:01 EDT 2018
Tue Oct 2 05:32:01 EDT 2018
Tue Oct 2 05:33:01 EDT 2018
Tue Oct 2 05:34:01 EDT 2018
Tue Oct 2 05:35:01 EDT 2018
Tue Oct 2 05:36:02 EDT 2018
Tue Oct 2 05:37:01 EDT 2018
Tue Oct 2 05:38:01 EDT 2018

So what do you think? this could be an Apache or PHP issue?

Yes it has something todo with php/apache/nginx. You have the proof here. Plain PHP file does not work as expected. Non php cron job works as expected. But no clue what it could be though. Maybe something related to a maximum amount of requests / child processes of PHP.

Is your app running smooth when you run it via the browser? No sudden delays sometimes?

@click, yes that's what I'm thinking, something related with php/apache/nginx as you said. The app runs smooth via browser, even when the php scripts that came from cron are delayed, the app runs as usual...

Is it only cron then that is delayed? Regular calls to your app load quickly?

What if you run that test php file created earlier without a cron but via the console (so it runs via PHP CLI instead of PHP FPM). And run it a few times manually. Do you also see the same delay? It is not resolving your issue but it will give you some extra information on when this is happening.

File:

<?php
echo date('Y-m-d H:i:s') . PHP_EOL;

Run in console as:

php /path/to/file.php

or execute every second with the watch command. This will echo the time every second to your screen. This should give you an almost continuous updating timestamp on your screen.

watch -n1 php test.php

@click I think you have discovered some light...

If I run php -v the output is

PHP 5.4.16 (cli) (built: Apr 12 2018 19:02:01) 
Copyright (c) 1997-2013 The PHP Group
Zend Engine v2.4.0, Copyright (c) 1998-2013 Zend Technologies
    with the ionCube PHP Loader (enabled) + Intrusion Protection from ioncube24.com (unconfigured) v10.0.3, Copyright (c) 2002-2017, by ionCube Ltd.

So for my app I needed to use 7.1 so I searched and use /opt/plesk/php/7.1/bin/php so for example my cron's php path is /opt/plesk/php/7.1/bin/php /path/to/file.php and not php /path/to/file.php

Observation: 2 different versions here....

The light comes in when running watch -n1 php test.php or watch -n1 /opt/plesk/php/7.1/bin/php test.php

If I run the one with the php 7.1 path it hangs as cron do, but the other one does not hang...

While the system is lagged, seems that using php instead of /opt/plesk/php/7.1/bin/php keeps running. Hope this helps you to send some light to the solution

Laravel 5.5 requires PHP >= 7.0 so running it with php only should not be a good solution.

But you say that running it with the php 7.1 it hangs, right? How do you run your artisan command? Also with php artisan schedule:run right?

Can you somehow remove PHP 5.4 from your plesk server? And make 7.1 the default? php -v should give you the same PHP version as when you run phpinfo() in the browser.

@click Yes, Laravel needs PHP >= 7.0, so I can't run it only with php (I have tried to run scheduler but it shows an error)

php /var/www/vhosts/domain***/laravel/artisan schedule:run

PHP Parse error:  syntax error, unexpected 'class' (T_CLASS), expecting identifier (T_STRING) or variable (T_VARIABLE) or '{' or '$' in /var/www/vhosts/winnersmartialarts.com/laravel/artisan on line 33

I'm talking with the plesk support team so I let them finish their investigations and try to remove PHP 5.4 and make 7.1 the default and see what happens. Hope this solves the issue...