Debugging Varnish Cache Performance
Some steps to take to help debug cache performance issues, and if Varnish is configured optimally for the current dataset.
Watching a specific URLs Age
We can monitor how long a specific URL is staying in cache, by wrapping a curl command within a while loop. (Note: You may need to update your varnish config to stop removing the Age header)
while true; do curl -Iso /dev/null -w '[%header{Date}] %{http_code} %{url} %header{x-cache} %header{age}\n' https://example.com && sleep 1; done
Checking if you have allocated enough memory to Varnish
We can use the varnishstat
command, to see how many items have overflowed the varnish cache or if we have over provisioned our varnish cache. If n_lru_nuked
is above zero or g_space
is a low, you likely want to consider potentially increase your memory allocation for Varnish.
varnishstat -1 -f "SMA.s0.g_*" -f MAIN.n_lru_nuked -f MAIN.n_object
Field | Description |
---|---|
n_lru_nuked | This value is how many times an item has been discarded from the cache due to having no space for a new item. (This should be zero or fairly low) |
g_bytes | This is how much of the varnish cache storage is currently being used |
g_space | This is how much of the varnish cache storage is left over to be assigned to new content |
Using the output of the above command, we can adjust the available cache storage for varnish by editing the system file and updating the malloc value.
systemctl edit --full varnish
# Update the ExecStart line, and update the malloc value appropriately
Enable ongoing persistent logging
We can log varnish requests including hit/miss rates just like Nginx requests by using Varnishncsa. This is great for ingesting into your observability stack (NewRelic/Grafana/OpenTelemetry etc). Great for creating pretty graphs and dashboards or trigger notifications when items are being evicted from cache or if hit rate drops below a preset value.
echo '%{X-Forwarded-For}i %{Varnish:hitmiss}x %l %u %t "%r" %s %b "%{Referer}i" "%{User-agent}i" %D' > /etc/varnish/varnishncsa.format
systemctl edit --full varnishncsa # Add -f /etc/varnish/varnishncsa.format to the end of ExecStart
systemctl enable --now varnishncsa
Monitoring Cache Purges
Cache Purges happen when you update content / clear cache, from outside of Varnish. and you need to inform varnish it needs to refresh its content.
varnishlog -g request -q 'ReqMethod eq "PURGE"'
Enable Cache Invalidation Logging
If you have PURGE requests coming from Magento, but are unsure what is triggering it. You can enable debug logging by running the following commands, and this will start logging some cache_invalidate
entries to the system.log
file.
php bin/magento setup:config:set --enable-debug-logging=true && php bin/magento cache:flush
Alternatively if you do not want to change the config setting, you can edit the execute
method within vendor/magento/framework/Cache/InvalidateLogger.php
and change the log to info/warn level to enable logging in non debug mode.
Cache Invalidation Stack Traces
Sometimes the you need a bit more information about whats triggered the cache invalidate than just the method & URL. We can add the backtrace for the cache invalidation logs by editing the makeParams
method within vendor/magento/framework/Cache/InvalidateLogger.php
private function makeParams($invalidateInfo)
{
$method = $this->request->getMethod();
$url = $this->request->getUriString();
+ $trace = (new \Exception)->getTraceAsString();
+ return compact('method', 'url', 'invalidateInfo', 'trace');
- return compact('method', 'url', 'invalidateInfo');
}