Opcache errors after deployment with symlink switch

[mbrodala]

Even though we are invoking the cachetool during deployment to reset the PHP opcode cache, we encounter internal server errors after the symlink switch to the new release. The error disappears after a short while.

To verify that everything is basically working correct we have also put opcache:status before and after opcache:reset:

$ .../bin/cachetool opcache:status
+----------------------+---------------------------------+
| Name                 | Value                           |
+----------------------+---------------------------------+
| Enabled              | Yes                             |
| Cache full           | No                              |
| Restart pending      | No                              |
| Restart in progress  | No                              |
| Memory used          | 53.81 MiB                       |
| Memory free          | 74.19 MiB                       |
| Memory wasted (%)    | 0 b (0%)                        |
| Strings buffer size  | 16 MiB                          |
| Strings memory used  | 6.73 MiB                        |
| Strings memory free  | 9.27 MiB                        |
| Number of strings    | 335325                          |
+----------------------+---------------------------------+
| Cached scripts       | 1054                            |
| Cached keys          | 1372                            |
| Max cached keys      | 16229                           |
| Start time           | Fri, 12 Feb 2016 14:04:08 +0000 |
| Last restart time    | Tue, 16 Feb 2016 10:32:12 +0000 |
| Oom restarts         | 0                               |
| Hash restarts        | 0                               |
| Manual restarts      | 7                               |
| Hits                 | 8193                            |
| Misses               | 1073                            |
| Blacklist misses (%) | 0 (0%)                          |
| Opcache hit rate     | 88.420030218001                 |
+----------------------+---------------------------------+

$ .../bin/cachetool opcache:reset

$ .../bin/cachetool opcache:status
+----------------------+---------------------------------+
| Name                 | Value                           |
+----------------------+---------------------------------+
| Enabled              | Yes                             |
| Cache full           | No                              |
| Restart pending      | No                              |
| Restart in progress  | No                              |
| Memory used          | 20.87 MiB                       |
| Memory free          | 107.13 MiB                      |
| Memory wasted (%)    | 0 b (0%)                        |
| Strings buffer size  | 16 MiB                          |
| Strings memory used  |  452.05 KiB                     |
| Strings memory free  | 15.56 MiB                       |
| Number of strings    | 335325                          |
+----------------------+---------------------------------+
| Cached scripts       | 0                               |
| Cached keys          | 0                               |
| Max cached keys      | 16229                           |
| Start time           | Fri, 12 Feb 2016 14:04:08 +0000 |
| Last restart time    | Tue, 16 Feb 2016 12:08:43 +0000 |
| Oom restarts         | 0                               |
| Hash restarts        | 0                               |
| Manual restarts      | 8                               |
| Hits                 | 0                               |
| Misses               | 2                               |
| Blacklist misses (%) | 0 (0%)                          |
| Opcache hit rate     | 0                               |
+----------------------+---------------------------------+

While I'm not sure about the memory and string usage, scripts and keys are indeed removed as expected.

This is an environment with an Apache 2.4.10 and PHP 5.6.17 with PHP-FPM. The relevant part of the php.ini:

opcache.enable=1
opcache.memory_consumption=128
opcache.interned_strings_buffer=16
opcache.max_accelerated_files=8192
opcache.validate_timestamps=0
opcache.revalidate_freq=0

Any idea what could be wrong?

[gordalina]

Are you resetting the cache after symlinking? Can you post the deploy script (a slimmed down version).

[mbrodala]

Yes, the reset happens after the symlink switch. But we also tried before and even after the switch at the same time to no avail.

We are using Rocketeer for deployment so there is not really a "script", only a configuration and a set of tasks which are run at specific stages during the deployment.

We've hooked the Opcache reset directly after the symlink switch so it is really the last thing that is done during deployment. (Except of cleanup of old releases.)

Anyways here's a vastly slimmed down excerpt of the last deployment log:

...
[user@host] (connection) No migrations performed.
connection/0 |=> Sharing file /var/www/project/releases/20160216181832/foo
$ ln -s /var/www/project/shared/foo /var/www/project/releases/20160216181832/foo-temp
$ mv -Tf /var/www/project/releases/20160216181832/foo-temp /var/www/project/releases/20160216181832/foo
...
connection/0 |=> Successfully deployed release 20160216181832
connection/0 |-- Closure fired by deploy.after [~1.45s]
$ cd /var/www/project/releases/20160216181832
$ /usr/bin/php /var/www/project/releases/20160216181832/typo3cms cache:flush --force
$ /usr/bin/php /var/www/project/releases/20160216181832/typo3cms cache:warmup
[user@host] (connection) Flushed all caches.
[user@host] (connection) Warmed up the following caches: classes, package manager, tca, ext_tables, ext_localconf
connection/0 |-- Closure fired by deploy.after [~1.79s]
$ cd /var/www/project/releases/20160216181832
$ /usr/bin/php /var/www/project/releases/20160216181832/bin/cachetool opcache:status
[user@host] (connection) ...
connection/0 |-- ClearOpcodeCacheTask (Performs tasks on opcode caches) fired by deploy.after
$ cd /var/www/project/releases/20160216181832
$ /usr/bin/php /var/www/project/releases/20160216181832/bin/cachetool opcache:reset
connection/0 |-- Closure fired by deploy.after [~1.79s]
$ cd /var/www/project/releases/20160216181832
$ /usr/bin/php /var/www/project/releases/20160216181832/bin/cachetool opcache:status
[user@host] (connection) ...
connection/0 | Cleanup (Clean up old releases from the server)
$ rm -rf /var/www/project/releases/20160212170134

[gordalina]

Try clearing the realpath cache before or after the opcache reset:
cachetool stat:clear

[mbrodala]

@gordalina Didn't think of that, thanks I'll give it a try.

[mbrodala]

No luck, still getting errors after deployment. :-X I just saw this in the PHP-FPM logs though:

[18-Feb-2016 10:35:06] WARNING: [pool www] child 16153 said into stderr: "zend_mm_heap corrupted"
[18-Feb-2016 10:35:06] WARNING: [pool www] child 16153 exited with code 1 after 61793.224488 seconds from start
[18-Feb-2016 10:35:06] NOTICE: [pool www] child 25421 started

[gordalina]

That looks like a very specific error, did you try these solutions?

[mbrodala]

@gordalina I've also searched for this and saw the same suggestions but I fear none of them will help.

As for USE_ZEND_ALLOC=0 the manual says this:

Note: USE_ZEND_ALLOC=0 in the environment will stop the memory manager from functioning, all allocations fall back on the default system allocators which can be useful for debugging leaks.

This sounds more like a debugging measure and I'm not sure if this is something one wants in a production environment...

[gordalina]

Did you try reloading php-fpm after cachetool? It restarts the workers a gracefully.

[mbrodala]

This would be one of the remaining options which I tried to avoid due to requiring sudo. So far mod_realdoc also doesn't see to yield the expected results.

Do you mean that there will be no downtime when restarting PHP-FPM?

[gordalina]

Have a look here

[mbrodala]

@gordalina Thanks, so this is about reload vs. restart. Seems like it isn't that graceful either and the SO comment only mentions APC so I'm not sure about the Opcache behavior here.

[gordalina]

Not sure if I can be of further assistance. I'm closing this issue.
Feel free to reopen any time, or post a comment if you've found a solution.

[mbrodala]

@gordalina Thanks already for taking time to give me pointers here. I now went with PHP-FPM restart and so far it looks OK-ish in 90% of the deployments. I still saw an error once but I'll keep watching.

[pySilver]

Heh after few days of using cachetool I also started seeing this kind of behavior in my environment. Once cache is cleared – all require_* calls fails.

[pySilver]

Hopefully this would solve the issue: zendtech/ZendOptimizerPlus#126 (comment)

opcache.use_cwd = 1
opcache.revalidate_path = 1