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).

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?

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

@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

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?

@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.

@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  

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.

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