WordPress.org

Resolved mjvito
(@mjvito)

1 year, 5 months ago

My issue seems similar to these reports about cache files either not being created, or being created but shortly thereafter deleted:

https://wordpress.org/support/topic/preload-mode-enabled-but-cache-files-disappear/

https://github.com/Automattic/jetpack/issues/25467

https://wordpress.org/support/topic/preload-only-caching-1-3-or-posts/

I’m on WordPress 6.1.1 with PHP 8.2 FastCGI.

In my case, starting with an empty cache, preload mode skips some pages, sometimes large groups of pages, while working. It continues to skip some of these even on subsequent runs.

Furthermore, with preload mode on, the plugin seems to have a mind of its own. It deletes pages that are supposed to be supercached, seemingly at random. The number of pages that disappear at one time can be anywhere from tens to nearly the entire cache (about 1000 pages for me). This seems to happen most often right after a preload cycle completes.

As has been suggested, I removed the bots from Rejected User Agents to help get missing files cached more quickly, but this is not a solution to the underlying problem.

I also tried disabling garbage collection (setting Cache Timeout to 0), even though my understanding is that in preload mode this setting should be irrelevant. This seems to have no effect.

I came across reports of two unrelated edge case bugs, both resulting from the Yoast SEO plugin, which potentially explain the behavior I see.

The first edge case is Yoast triggering a complete cache purge when Yoast updates to a new version, reported here: https://wordpress.org/support/topic/cache-flushing-on-update/

This behavior is not supposed to happen, but I observed it multiple times, including the previous two updates on March 1 and 3. Apparently, Yoast includes triggers for a full purge specifically for WP Super Cache and W3 Total Cache, but this is only supposed to occur when Yoast is activated or deactivated, or potentially when changing some settings.

The second edge case is more pernicious, and will definitely need a debug review. Someone reported that an interaction between Yoast’s use of an organization image in creating schema markup was causing Super Cache to purge individual pages immediately after they were cached: https://wordpress.org/support/topic/wp-super-cache-and-yoast-seo-incompatible/

I had no image set. (For my schema, I am a person, not an organization, but I assume it works the same way.) After I set one, the problem appears to be less pronounced, but this is only from anecdotal observation. Before the change, I would see the cached page count in the WP Super Cache UI drop between 20-50% immediately after a preload completed, when the “Cleaning up old supercache files.” email is sent. After the change, the count only drops 10-20%.

TO DO:

Run debug mode during preload and report findings.

Viewing 15 replies - 1 through 15 (of 31 total)

1 2 3 →

Thread Starter mjvito
(@mjvito)

1 year, 5 months ago
Questions for the developer:
1. Does the “Preload tags, categories and other taxonomies” option include date archives? My assumption is it does not.
2. What is actually happening when the plugin is “Cleaning up old supercache files.” at the end of the preload cycle? How does it decide what should be deleted?
Context:

My site is currently under DDoS attack. One of the application layer attacks is to call a large number of date archives. This forces the site spin up PHP processes to make these. Super Cache appears to be caching the generated pages.

Additionally, they are requesting malformed links, which either trigger a 404 page, or in some cases still manage to load something with content. These also appear to be getting cached.

I am wondering if these all get deleted at the end of a preload cycle. This could potentially explain the recurring 10-20% drops in cached page count.
- This reply was modified 1 year, 5 months ago by mjvito.
Thread Starter mjvito
(@mjvito)

1 year, 5 months ago
I think I’ve isolated the post skipping issue to FastCGI. When preload begins, it first processes a batch of tags (though not all of them), then categories (I only have a few), then fetches 100 posts, and runs everything all in one process. On my site, based on how fast it runs through what it can do before the process ends prematurely, this would take about 4-5 minutes. But this process times out after exactly 120 seconds from the start of the first tag URL.

Exactly one hour later, the cycle repeats. However, preload does not seem to be tracking what was successfully cached in the previous batch, because it begins at a new position that presumes everything prior worked as intended. The new batch of tags, which were successfully cached before the timeout in the previous cycle, begin where they left off. The new batch of posts, which were not completed when the timeout occurred, begin where the plugin assumed it should start, which creates the gap of skipped posts. The caching of posts does not complete before the timeout in subsequent cycles, either.

Although I increased PHP max_execution_time to 600 seconds, the 120 second timeout still occurs, because mod_fcgid also has a read data timeout, set by FcgidIOTimeout, which kills the process. My host has this set to 120 seconds. I don’t have access to fcgid.conf and can’t override this with .htaccess.

I can try asking the host if they will increase the FcgidIOTimeout limit, but 120 seconds already seems generous. Maybe it would make more sense for Super Cache to break the fetches into smaller batches?
- This reply was modified 1 year, 5 months ago by mjvito.
Plugin Contributor Adnan Haque (a11n)
(@adnan007)

1 year, 4 months ago

Hi @mjvito

Thank you for going on to the details and narrowing down the issue. It was really helpful. It looks like you are right about how preload can skip posts. Unfortunately, there is currently no way to control how many posts are processed in a batch.

So, I am afraid you have to talk to the host and request them to increase the timeout. I have logged an issue so we can try to fix it. However, be aware that there is currently no timeline on when this can be addressed.

Thread Starter mjvito
(@mjvito)

1 year, 4 months ago

Hi,

Thanks for logging. Understand about timeline.

As a workaround, I am manually running preload refreshes, alternating between default (post/page only), which gets through most of the posts before the timeout, and with “Preload tags, categories and other taxonomies.” checked. In older versions, the UI on the Preload tab used to report “Currently caching from post” in increments of 50. But I do not know if this was because the fetch batch size was 50, or this was just the progress reporting increment.

There are two additional bugs related to this. One is small, the other is significant.

The small bug is that preload mode deletes child categories. It looks like this was known and addressed in version 1.5.5, but seems to have returned. Preload mode creates the child categories first. Then when it creates the parent category, it deletes the children. I observed this directly in the debug log.

The significant bug is a behavior that occurs at the end of a preload refresh cycle, but ONLY when preload is on a schedule. When preload is run manually (“Refresh preloaded cache files” set to 0 minutes), everything appears to function as intended. The total cached pages indicated in the UI is close to what I expect. It stays approximately at that level through subsequent manually started preload cycles. However, when preload refresh is set to run on a schedule, it deletes a large number of cached pages at the moment the cycle finishes. This can be up to 50% of the pages. This happens both with “Preload tags, categories and other taxonomies.” checked and unchecked. I observed this only through the UI.

TO DO:

Run debug mode to capture the end of a scheduled preload refresh cycle and report observations.

Plugin Support Stef (a11n)
(@erania-pinnera)

1 year, 4 months ago

Hi there, @mjvito,

Just want to let you know that we have asked our developers to check on this to have a better idea on how to help you. We’ll circle back to you as soon as we have info to share.

Thanks for your patience!
Plugin Contributor Mark (a11n)
(@thingalon)

1 year, 4 months ago
Hi @mjvito,

Thanks for investigating and reporting the strange behaviour you’ve experienced. I’ve just tried to recreate both issues in my test sites, and have not been able to so far.

I’d be happy to check over any debug logs you have. Please be sure to redact your site url from the debug logs if you would like to keep it private.

Preload mode creates the child categories first. Then when it creates the parent category, it deletes the children

On my test site, I created categories Brie and Cheddar, both of which are children of Cheese. I ensured that Brie contained posts, but Cheddar did not.

I ran the preload process, and was able to observe:
- A log message stating wp_cron_preload_cache: delete <path>/category/cheese/brie appeared in my logs, which was then followed by further log messages indicating files in the brie directory were fresh and so were not deleted. This occurs when Super Cache is considering deleting directories, and may not indicate that the indicated path is actually getting deleted.
- The same logs appeared for Cheddar.
- When I browsed to Contents > Show file list in the Super Cache settings page, I could see all three cheese related categories under the list of “Fresh WP-Cached files”.
You mention that you saw this deletion in your Debug logs.

If you view the contents of your cache after pre-loading, do all of your category pages appear there? Finally, if you browse to any category page which is missing from your cache does it load correctly, and does it appear in your cache contents after you load it manually?

The significant bug is a behavior that occurs at the end of a preload refresh cycle, but ONLY when preload is on a schedule. When preload is run manually (“Refresh preloaded cache files” set to 0 minutes), everything appears to function as intended. The total cached pages indicated in the UI is close to what I expect. It stays approximately at that level through subsequent manually started preload cycles. However, when preload refresh is set to run on a schedule, it deletes a large number of cached pages at the moment the cycle finishes. This can be up to 50% of the pages. This happens both with “Preload tags, categories and other taxonomies.” checked and unchecked. I observed this only through the UI.

That does sound like a severe bug.

I have attempted to recreate this on my test site, but so far haven’t been able to. I would love to see Debug logs around this occurring.

When you click the “Preload now” button, it internally schedules a preload for 10 seconds in the future – using the same code as the scheduled preloads.

At the moment, the best working theory I have is that another cron-job is running after your scheduled job, which is deleting the cache files.

In your original post, you mentioned that you set Garbage Collection to 0, but that it did not fix your original issue. Can I please verify that it’s still set to 0?
Thread Starter mjvito
(@mjvito)

1 year, 4 months ago
Hi @thingalon,

Thanks for checking into this. I look forward to solving it together with you.

For the child category issue, I have a log already, so I’ll address that now. For observing the mass cache file deletion at the end of preload, I’ll need to carve out time to set that up. Hopefully I can get to that in the next few days. I also inadvertently made a new observation that might shed more light on that, and note that at the end of this post.

Confirming that Cache Timeout is set to 0 (garbage collection disabled). In case it is relevant, noting that Scheduler is set to 86400 seconds. I have Notification Emails checked, but don’t receive any.

Child Categories

My site has a parent category Urbanism with five children. All child categories contain posts. When I run debug, I see the children are refreshed first. Let me know if you want to see the debug messages for that part. After they are refreshed, the following sequence occurs:
- The last child is fetched at the end of its refresh sequence. wp_cron_preload_cache: fetched <path>/category/urbanism/train-culture/
- The parent is deleted at the beginning of its refresh sequence. wp_cron_preload_cache: delete <path>category/urbanism/
- The compressed and normal versions of the cached page for a child category are deleted. prune_super_cache: deleted <path>/category/urbanism/train-culture/index-https.html.gz prune_super_cache: deleted <path>/category/urbanism/train-culture/index-https.html
- The folder for the child category is deleted. gc: deleted <path>/category/urbanism/train-culture, older than 0 seconds
- This repeats for each child.
- The parent category completes its refresh sequence at the end.
I cannot view cache contents through the UI because there are too many files, but I can see what is happening over SSH. The parent category folders and cached pages are present, but the child category folders and cached pages are not. When I browse to these child category pages on the site, they load correctly and subsequently appear in the cache folder.

Mass Cache File Deletion

When I observed that the deletions were happening only after scheduled preloads, but not after manual preloads, I didn’t consider the condition that I was starting these manual preloads very frequently. Usually I would start one in the morning with just posts and pages, then start the second with tags and categories as soon as the first finished in the afternoon. There was never more than 12 hours between the end of the second preload of the day and the beginning of the preload the next morning.

The other day, I took a one day break. After the break, I started a morning preload with just posts and pages, and at the end of that cycle, the significant deletion also occurred, even though it had been started manually. There was approximately 36 hours between the end of the previous cycle and beginning of the new one. I can try reproducing this with tags and categories checked, to see if the same thing happens. Potentially, the problem is not scheduled preloads, but something related to the age of the cached files.
Plugin Support Joseph B. (a11n)
(@tamirat22)

1 year, 4 months ago

Hi there @mjvito,

Thank you for your patience.

Our developers are working on the issue and will either share a workaround or address it in a new release. We appreciate your understanding and look forward to assisting you.

Best,

Plugin Contributor Mark (a11n)
(@thingalon)

1 year, 4 months ago

Hi @mjvito,

I have some good news! I think I’ve tracked down the issue. It was your comment that started me down the right path:

The other day, I took a one day break. After the break, I started a morning preload with just posts and pages, and at the end of that cycle, the significant deletion also occurred, even though it had been started manually.

Following that rabbit-hole, I tested multiple setups with different timing and eventually stumbled upon the real reason for it.

At the end of preloading, Super Cache calls its prune_super_cache method to clean up the cache directory. However, if your cache expiry time is set to 0 (which usually prevents calls to prune_super_cache in other situations), it deletes all files which are over 0 seconds old.

The timing is very sensitive to how quickly the preload process runs, and which files were preloaded first. If the preload takes less than a second, then often nothing will be deleted. However, if it takes longer than a second, then the older content preloaded will often be deleted at the end.

I’ve prepared a fix for this, which we will release in the next version of Super Cache. If you are interested in the development process, you can follow the patch here: https://github.com/Automattic/jetpack/pull/30052

Plugin Author Donncha O Caoimh (a11n)
(@donncha)

1 year, 4 months ago

After the break, I started a morning preload with just posts and pages, and at the end of that cycle, the significant deletion also occurred, even though it had been started manually

When you saw cached files being deleted, were they pages or posts?
Are your pages of type “page” or do you have a custom post type?
Did you see the following in your debug log? With $post_id being a number, and $dir is the directory where that post lives.

clear_post_supercache: post_id: $post_id. deleting files in $dir

Was the next entry in the debug log generated by prune_super_cache? Like this?

prune_super_cache: deleted $directory

Or was it generated by wpsc_delete_files like this?

wpsc_delete_files: deleting ‘ . $dir . $file

Obviously, those variables are replaced by the filenames of your cache files.

Thanks for using the debug log to help us track down why this is happening!

Thread Starter mjvito
(@mjvito)

1 year, 3 months ago

Hi @thingalon, that’s great! I’m glad I was able to help.

Hi @donncha, please see my responses to each of your questions below. But first noting for both of you that I ran the test to reproduce the mass deletion after a 36 hour gap, with categories and tags checked, and indeed the same result occurred. I have a debug log from the end of that preload cycle.

When you saw cached files being deleted, were they pages or posts?

Both, but my sample size for pages is tiny, I only have two.

Are your pages of type “page” or do you have a custom post type?

Standard “page” type.

clear_post_supercache: post_id: $post_id. deleting files in $dir

Yes, I see these.

next entry in the debug log generated by

prune_super_cache: deleted $directory

I also see wpsc_delete_files elsewhere in the log, but not following clear_post_supercache.

At the end of all refreshes, this sequence starts the final preload phase, where it looks like the garbage cleaning is happening:

wp_cron_preload_cache: clean expired cache files older than 86400 seconds.

Cleaning expired cache files in $dir

Doing GC on supercache dir: $dir

Is the Scheduler interval (86400 seconds) somehow substituting for Cache Timeout, or am I misunderstanding what this message means?

Plugin Author Donncha O Caoimh (a11n)
(@donncha)

1 year, 3 months ago

Thanks @mjvito for the detailed response. I’m sorry I didn’t reply earlier. This is complicated and I’ve been snowed under.

You’re right about the cache timeout. It’s set up to delete files older than when the preload started.

I’m going to be going through this code with a fine tooth comb tomorrow. @thingalon’s patch looks like it will work but there are a few ways to fix this, I think. I want to figure those out.

Thread Starter mjvito
(@mjvito)

1 year, 3 months ago

Hi @donncha, no worries. The situation over here is the same.

One unexpected good thing has happened in the meantime. My host increased the FastCGI read data timeout to 300 seconds. Now preload can complete its fetch cycles before the timeout. There are still things to fix, but the pressure (for me, anyway) has been alleviated.

Now all posts and pages are cached during preload.

The child categories are still deleted. This still needs a fix.

A new problem I observed, which may have been present earlier but I am only noticing now, is that preload does not cache all of my tags. It caches the first 440-450 out of 628 tags, then stops. I have not done debug log diving, but there are no read data timeouts in my server logs. This is not a high priority for me, though.

When manually triggering preloads at 24 hour intervals, there are usually only a few file deletions at the end of a preload cycle, and sometimes there are none.

I ran the “take a day off” test again, this time with 48 hours between preload runs. About 10% of cache files were deleted in this case, much less than before. The large deletions observed earlier were potentially an outcome of the cache state resulting from frequent read data timeouts.
Plugin Author Donncha O Caoimh (a11n)
(@donncha)

1 year, 3 months ago
Ah, that’s interesting. While preloading, the code uses set_time_limit() to extend the timeout by 60 seconds, which works when using Apache, but perhaps that doesn’t work on a host using FastCGI because of that hard read timeout.

The preload expects the loop will finish and increments the counter by 100 each time, so the next go through the loop will get the next 100. However, if there was a timeout, you might miss up to 100 posts (but it’ll probably be a lot less than that, hopefully the server won’t time out fetching the first post).

Here is maybe why all your tags aren’t getting preloaded. Each loop of the preload fetches the first archive page of 50 tags/categories. That means the loop has to run 13 times (628/50) to cache all the tags you have. To run 13 times you need to have 1300 posts because the preload operates 100 posts at a time.

To properly fix those issues, I think the preload should:
1. Preloading taxonomies shouldn’t depend on having enough posts to run the loops. While preloading taxonomies, ignore posts until done.
2. Preload 10 taxonomies and 10 posts on each preload to avoid general timeout problems.
3. While preloading, schedule the next preload in 1 or 2 seconds rather than 30 seconds as we’re working on a smaller volume of pages/posts.
The child categories problem definitely needs a fix too.
Plugin Author Donncha O Caoimh (a11n)
(@donncha)

1 year, 3 months ago

In this patch I have fixed the problems with preload not preloading all the tags, plus it will behave better and not time out so much. It does 10 posts or pages at a time rather than 100. You’ll notice that it preloads the tags and categories first to make sure that Preload should go a lot faster too!

If you’d like to give it a go, you can copy the wp-cache.php from here and upload it to wp-content/plugins/wp-super-cache/ on your server. It will overwrite wp-cache.php in that directory so make sure you download wp-cache.php or make a copy of it first, just in case it breaks, but I don’t think it will.