[2.2.0-*] cron_schedule forever increasing in size. Lots of pending jobs never cleared

[gwharton]

Preconditions

1. Magento 2.2.0-rc30 running on Ubunti 16.04
2. Deployed initially from zip, but updated to 2.2.0-rc30 using composer

Steps to reproduce

1. Nothing, just look at the cron_schedule table

Expected result

1. On 2.1.9 my cron_schedule table is around 180 items in size. Its size is pretty much static. A snapshot shows the vast majority of jobs are in the success state, with a couple of pending jobs about to be run in the next minute or so.

Actual result

1. On 2.2.0-rc30 which has been running for around 8 days (upgraded from previous rc) the size of the cron_schedule table is around 6500 items in size. The size is constantly increasing every minute. The majority of the jobs are in the pending state. Some are marked as success.

The cronjob steadily increases in the time taken to complete, at the moment it is taking around 30 seconds to complete, during which time, mysql and php are taking up heavy CPU usage.

A MYSQL query log shows magento churning through all the pending requests, but they are never marked as success. Hence the ever increasing list of jobs to run.

Snippet from the Mysql Query log below

90 Query	START TRANSACTION
90 Query	UPDATE "cron_schedule" SET "job_code" = "catalog_product_outdated_price_values_cleanup", "status" = "pending", "messages" = NULL, "created_at" = "2017-09-15 09:29:06", "scheduled_at" = "2017-09-15 09:48:00", "executed_at" = NULL, "finished_at" = NULL WHERE (schedule_id="189337")
90 Query	COMMIT
90 Query	UPDATE "cron_schedule" AS "current" LEFT JOIN "cron_schedule" AS "existing" ON existing.job_code = current.job_code AND existing.status = "running" SET "current"."status" = "running" WHERE (current.schedule_id = "189338") AND (current.status = "pending") AND (existing.schedule_id IS NULL)
90 Query	START TRANSACTION
90 Query	UPDATE "cron_schedule" SET "job_code" = "catalog_product_frontend_actions_flush", "status" = "pending", "messages" = NULL, "created_at" = "2017-09-15 09:29:06", "scheduled_at" = "2017-09-15 09:33:00", "executed_at" = NULL, "finished_at" = NULL WHERE (schedule_id="189338")
90 Query	COMMIT
90 Query	UPDATE "cron_schedule" AS "current" LEFT JOIN "cron_schedule" AS "existing" ON existing.job_code = current.job_code AND existing.status = "running" SET "current"."status" = "running" WHERE (current.schedule_id = "189339") AND (current.status = "pending") AND (existing.schedule_id IS NULL)
90 Query	START TRANSACTION
90 Query	UPDATE "cron_schedule" SET "job_code" = "catalog_product_frontend_actions_flush", "status" = "pending", "messages" = NULL, "created_at" = "2017-09-15 09:29:06", "scheduled_at" = "2017-09-15 09:34:00", "executed_at" = NULL, "finished_at" = NULL WHERE (schedule_id="189339")
90 Query	COMMIT
90 Query	UPDATE "cron_schedule" AS "current" LEFT JOIN "cron_schedule" AS "existing" ON existing.job_code = current.job_code AND existing.status = "running" SET "current"."status" = "running" WHERE (current.schedule_id = "189340") AND (current.status = "pending") AND (existing.schedule_id IS NULL)
90 Query	START TRANSACTION
90 Query	UPDATE "cron_schedule" SET "job_code" = "catalog_product_frontend_actions_flush", "status" = "pending", "messages" = NULL, "created_at" = "2017-09-15 09:29:06", "scheduled_at" = "2017-09-15 09:35:00", "executed_at" = NULL, "finished_at" = NULL WHERE (schedule_id="189340")
90 Query	COMMIT
90 Query	UPDATE "cron_schedule" AS "current" LEFT JOIN "cron_schedule" AS "existing" ON existing.job_code = current.job_code AND existing.status = "running" SET "current"."status" = "running" WHERE (current.schedule_id = "189341") AND (current.status = "pending") AND (existing.schedule_id IS NULL)
90 Query	START TRANSACTION
90 Query	UPDATE "cron_schedule" SET "job_code" = "catalog_product_frontend_actions_flush", "status" = "pending", "messages" = NULL, "created_at" = "2017-09-15 09:29:06", "scheduled_at" = "2017-09-15 09:36:00", "executed_at" = NULL, "finished_at" = NULL WHERE (schedule_id="189341")
90 Query	COMMIT
90 Query	UPDATE "cron_schedule" AS "current" LEFT JOIN "cron_schedule" AS "existing" ON existing.job_code = current.job_code AND existing.status = "running" SET "current"."status" = "running" WHERE (current.schedule_id = "189342") AND (current.status = "pending") AND (existing.schedule_id IS NULL)

[magento-engcom-team]

@gwharton, thank you for your report.
We were not able to reproduce this issue by following the steps you provided. If you'd like to update it, please reopen the issue.
We tested the issue on 2.2.0

[emmathepossum]

@gwharton I have been having the same problem since upgrading to 2.2.0. Have you done anything outside of clearing the cron_schedule table to fix it? I have done the same, but old entries are still not deleted. The timezone is set correctly, but that doesn't seem related.

[gwharton]

All of my installations are working as they should. The size of my cron_schedule tables are fairly static at around 1200 rows. This seems to be the correct behaviour, as the Magento settings regarding keeping cron history say to keep 1 hour, and looking at the entries in the table that is correct. The behaviour I saw in 2.1 where the cron_schedule table was only a 100 or so rows seemed to be incorrect behaviour, as it was only keeping the last minute. I suspect this was some sort of timezone problem on the timestamps.

I did have a couple of occasions where one of the cron jobs appeared to start, but had no finish time. This resulted in the table growing in size out of control as new rows for that cron job were added in the pending state, but never got run because the "stuck" job was still running as far as Magento was concerned. Clearing the table seemed to set things going again.

I have no idea why the job was stuck. Feels like Magento should have some method of detecting stuck jobs, or jobs that completed but didn't update their completed timestamp. Without this, Magento never recovers, resulting in the ramp up of CPU usage, eventually hitting 100% in a couple of weeks time as it repeatedly parses through the massive and growing amount of pending jobs every minute.

Unfortunately I haven't been able to reproduce this recently.

[gwharton]

One thought that I did have, is that I was doing a lot of development work on a module at the time these problems occurred. During some of these changes/recompiles/updates I would get emails telling me that the cron process failed, or when I restarted mysql that the database connection failed. Perhaps this is when the cron job starts but doesn't finish and then from this point on it just creates the pending jobs forever.

Since this, I now updated my cron jobs to check if Magento is in maintenance mode

* * * * * ! test -e ~/public_html/var/.maintenance.flag && php ~/public_html/bin/magento cron:run .........

This way, it makes sure that the cron jobs are never run while you are in maintenance mode. I don't know if this is recommended or not, but it feels much cleaner that cron jobs aren't run when I am carrying out magento upgrades/recompiles/development.

I have a standard shell script which I run every time I make changes or want to upgrade the store. It puts the store into maintenance mode while it updates magento to latest version, clears all static content, upgrades/recompiles/deploys static content and then clears the caches. Since religiously using this script to enforce maintenance mode, and having the cron jobs disabled while in maintenance mode I have not had any further issues.

#!/bin/sh
php bin/magento maintenance:enable
composer update
rm -rf pub/static/*
rm -rf var/view_preprocessed
rm -rf generated/code
rm -rf var/cache
rm -rf generated/metadata
rm -rf var/page_cache
php bin/magento setup:upgrade
php bin/magento setup:di:compile
php bin/magento setup:static-content:deploy --area=frontend --theme=Gw/frontend --language=en_US
php bin/magento setup:static-content:deploy --area=adminhtml --theme=Gw/backend --language=en_US
php bin/magento cache:clean
php bin/magento cache:enable
php bin/magento maintenance:disable

When updating modules, once I am happy they work on my test store, I put the production store into maintenance mode, upload the necessary updates, then run the above script to finish the deployment.

[emmathepossum]

Unfortunately the cron_schedule table kept growing even after a redeployment in maintenance mode, like you described. To fix my problem, I just wrote a cronjob that cleans old entries in cron_schedule every hour.

[cytracon]

Same problem here. @dwirt, how did you change the cronjob?

[gwharton]

My dev store went again at about 2am on the 17th. See phpmyadmin attached. The first entry in the table is marked as running. Then there are 6000 odd entries following it, all in the pending state and growing.

@magento-engcom-team I am unable to reproduce this on demand, but it feels like Magento is missing some cleanup code that detects cron jobs that are stuck in the running state. Really it should detect a stuck job, clear it and log some sort of error, allowing the future pending jobs to clear naturally. Just repeatedly adding pending jobs infinitum seems like a poor decision.

[gwharton]

I deleted the first row of the table, that was in the running state, and on the next cron run, it cleared all the pending tasks for this stuck cron, however rising to the top of the table, 3 more stuck cron jobs the following day at midday.

These DO correspond to when I was performing maintenance on the store, where there may have been code installed containing errors, or the database dropped etc or other anomoly going on.

[emmathepossum]

@cytracon I didn't change anything. I just added a new cronjob to the crontab.

0 * * * *
mysql magento-db -e "delete from cron_schedule where scheduled_at < date_sub(now(), interval 1 hour)"

Of course you could also write a magento cronjob, but I don't trust those anymore.

(Edit: see gwhartons post below)

[gwharton]

Not wanting to stray off topic but @dwirt If it's a shared server then beware of putting your mysql password in the command line like that. It can be viewed by anyone while the process is running.

The preferred method is to create a ~/.my.cnf file and specify mysql magento-db ..... on the command line. The host, username and password will be read from the file automatically.

The contents of .my.cnf should be

[mysql]
host = <hostname>
user = <username>
password = <password>

You can then secure this file with chmod 600 to keep it safe. You can also add the equivalent section for [mysqldump] if you use that command in cron jobs for database backups etc.

[emmathepossum]

@gwharton Thanks!