core_clean_cache cronjob never stops until it is killed

[norgeindian]

We have the issue, that the cronjob core_clean_cache, which runs by default every night, never runs through and is always running until it is killed, as soon as the cache has a minimal size.
It can be "fixed" by running the cronjob every hour. Then the cache is so small, that it still works , but if you run it as default once a night, the issue occurs.
We already debugged this locally and found out, that the removal of specific cache entries takes more than a second, each.
So when the cronjob goes through the cache items, he should delete, some of them are easily removed within a very short time but some take that long, and we did not really find out, why.

We're using Magento with all Mage One patches applied and the newest version of this module.
The issue happens since we switched to PHP 8.1.

Does anyone encounter the same and has any ideas what we could try to fix it?

[colinmollenhour]

That's very strange, but not much info to go on.. Perhaps you could run strace on the running process to see what it is doing at a system call level?

[norgeindian]

@colinmollenhour, you're totally right, sorry. I debugged now a lot deeper.
Found out, that \Cm_Cache_Backend_File::_clean -> $result = $this->_updateIdsTags(array($id), explode(',', $metadatas['tags']), 'diff') && $result; takes more than 1 second per cache file ,but strangely only for some entries and only if the cache is big enough.

Most of the entries only take about 0.0006 seconds to finish.

So I debugged further into \Cm_Cache_Backend_File::_updateIdsTags:

if ($this->_options['file_locking']) {
                        flock($fd, LOCK_EX);
                        echo "Step 1.6: " . (microtime(true) - $starttime) . " seconds\n";

                    }
                    if ($mode == 'diff') {
                        $_ids = array_diff($this->_getTagIds($fd), $ids);
                        echo "Step 1.7: " . (microtime(true) - $starttime) . " seconds\n";

                    } else {
                        $_ids = array_merge($this->_getTagIds($fd), $ids);
                        echo "Step 1.8: " . (microtime(true) - $starttime) . " seconds\n";

                    }
                    fseek($fd, 0);
                    ftruncate($fd, 0);
                    $result = fwrite($fd, implode("\n", array_unique($_ids))."\n") && $result;
                    if ($this->_options['file_locking']) {
                        flock($fd, LOCK_UN);
                    }
                    echo "Step 1.9: " . (microtime(true) - $starttime) . " seconds\n";

In the problematic cases, the step between 1.6 and 1.7 takes bout 0.4 seconds, the one between 1.7 and 1.9 another 0.6 seconds.

Debugged that further and found the following bottlenecks:

• $_ids = array_diff($this->_getTagIds($fd), $ids); ~ 0.3 seconds (_getTagIds takes about 0.1 seconds, the array_diff then 0.2)
• $result = fwrite($fd, implode("\n", array_unique($_ids))."\n") && $result; ~ 0.4 seconds
• fclose($fd); ~ 0.2 seconds

Until now, I was not table to find out, how a "bad" entry could be identified before.
Currently, I run core_clean_cache every hour. This leads to a cache size of around 4 GB, and in these are no "bad" entries.
If I only run it once a day, the cache size is around 15 GB and the bad entries are included.

That is all I know for now. Do you have any good idea how to approach this issue further, or any idea what might be the reason for these "bad" entries?

[colinmollenhour]

15GB cache!? What are you storing in the cache to cause it to be so big?
How many tags are there for these entries that are slow?