0

Last days was trying to investigate why my magento 2.3.5p1 instance needed for uncached pages about 10-11 secs to load, measured with timer. I identified that the issues was Porto's template mega menu which for some reason when it rendered in layout needed about 6-7 secs. I found it with magento profiler. So after removed this module speed went about 4-5 secs.

I wanted more. So after digging I found 2 things:

  1. With varnishstat my hit rate never exceeds 9-10% although I have 1 week TTL( for this I am suspecting something and I have another post: Magento 2.3.5 stop cache invalidate when work in admin
  2. My template's header.phtml file in categories with more than 4000 products and in product pages still needed in profiler render layout section 4-5secs to load

So after reading a lot I found a post saying that magento has these issues:

Varnish should process this code and replace it with actual html every time the page is served for the visitor.

However, in some edge cases it’s not working:

ESI processing is turned off.

ESI include tags are generated with

HTTPS access protocol, while Varnish only works with HTTP.

ESI include tags are rendered inside JSON blocks.

Response headers are too big and Varnish can’t process them.

As far as I understood maybe this is related this this magento official post:

X-Magento-Tags header too large for child products

After all these what I did:

Checked in varnish vcl if this lines was there:

sub vcl_backend_response {
    ...
    set beresp.do_esi = true;
}

Which was in the file but like this:

if (beresp.http.content-type ~ "text") {
        set beresp.do_esi = true;
    }

And in file:

/lib/systemd/system/varnish.service

I added more parameters:

-p feature=+esi_ignore_other_elements

-p feature=+esi_disable_xml_check

-p feature=+esi_ignore_https

-p http_resp_hdr_len=1024k

-p http_resp_size=1536k

-p workspace_backend=1536k

For values in:

http_resp_hdr_len
http_resp_size
workspace_backend  

I started with low numbers but I had issues in frontend in large product categories and in cart with error in Varnish:

Error 503 Backend fetch failed 
Backend fetch failed

Now the results from all these is that my store uncached pages went down to 3-4 secs including cms,category and product pages which was what needed. Also Varnish hit rate went up to 14% which I think again is low for 1 week TTL

But I have noticed that randomly and not very often, in admin and in frontend, inside the product I lose the additional media gallery images:

Frontpage Screen

Admin when edit product

Image is ok if you refresh the page. It happens only the first time not very often. It happens with jpg or png files and I don't have any errors in logs or 503 errors in server logs

In Varnishstat I don't have nuked objects(varnish have 30GB ram) All seems fine.

I use varnish-6.2.3

My vcl file:

# VCL version 5.0 is not supported so it should be 4.0 even though actually used Varnish version is 6
vcl 4.0;

import std;
# The minimal Varnish version is 6.0
# For SSL offloading, pass the following header in your proxy server or load balancer: 'HTTP-SSL-OFFLOADED: https'

backend default {
    .host = "localhost";
    .port = "8082";
    .first_byte_timeout = 600s;
#    .probe = {
#        .url = "/pub/health_check.php";
#        .timeout = 2s;
#        .interval = 5s;
#        .window = 10;
#        .threshold = 5;
#   }
}

acl purge {
    "localhost";
}
   
sub vcl_recv {
    if (req.method == "PURGE") {
    # check if the client is allowed to purge content
        if (client.ip !~ purge) {
            return (synth(405, "Method not allowed"));
        }
        # To use the X-Pool header for purging varnish during automated deployments, make sure the X-Pool header
        # has been added to the response in your backend server config. This is used, for example, by the
        # capistrano-magento2 gem for purging old content from varnish during it's deploy routine.
        if (!req.http.X-Magento-Tags-Pattern && !req.http.X-Pool) {
            return (synth(400, "X-Magento-Tags-Pattern or X-Pool header required"));
        }
        if (req.http.X-Magento-Tags-Pattern) {
          ban("obj.http.X-Magento-Tags ~ " + req.http.X-Magento-Tags-Pattern);
        }
        if (req.http.X-Pool) {
          ban("obj.http.X-Pool ~ " + req.http.X-Pool);
        }
        return (synth(200, "Purged"));
    }

    if (req.method != "GET" &&
        req.method != "HEAD" &&
        req.method != "PUT" &&
        req.method != "POST" &&
        req.method != "TRACE" &&
        req.method != "OPTIONS" &&
        req.method != "DELETE") {
          /* Non-RFC2616 or CONNECT which is weird. */
          return (pipe);
    }

    
    # Remove has_js and Cloudflare/Google Analytics __* cookies.
          set req.http.Cookie = regsuball(req.http.Cookie, "(^|;\s*)(_[_a-z]+|has_js)=[^;]*", "");
          # Remove a ";" prefix, if present.
          set req.http.Cookie = regsub(req.http.Cookie, "^;\s*", "");

    # We only deal with GET and HEAD by default
    if (req.method != "GET" && req.method != "HEAD") {
        return (pass);
    }

    # Bypass shopping cart, checkout and search requests
    if (req.url ~ "/checkout" || req.url ~ "/catalogsearch" || req.url ~ "/search" || req.url ~ "/robots.txt") {
        return (pass);
    }

    # Bypass health check requests
    if (req.url ~ "/pub/health_check.php") {
        return (pass);
    }

    # Bypass xmls
    if (req.url ~ "/pub/media/feed/skroutzfeed_gr.xml" || req.url ~ "/pub/media/feed/facebook-feed.xml" || req.url ~ "/pub/media/feed/facebook-feed-living.xml" || req.url ~ "/pub/media/feed/facebook-feed-dining.xml" || req.url ~ "/pub/media/feed/facebook-feed-foayer.xml" || req.url ~ "/pub/media/feed/facebook-feed-bedroom.xml" || req.url ~ "/pub/media/feed/facebook-feed-bath.xml" || req.url ~ "/pub/media/feed/facebook-feed-clocks.xml" || req.url ~ "/pub/media/feed/facebook-feed-grafeiou.xml") {
        return (pass);
    }
    
    # Bypass store manager requests
    if (req.url ~ "/pub/bridge_JZOpQnn5.php") {
        return (pass);
    }

    # Bypass store manager requests
    if (req.url ~ "/bridge_JZOpQnn5.php") {
        return (pass);
    }

    # Set initial grace period usage status
    set req.http.grace = "none";

    # normalize url in case of leading HTTP scheme and domain
    set req.url = regsub(req.url, "^http[s]?://", "");

    # collect all cookies
    std.collect(req.http.Cookie);

    # Compression filter. See https://www.varnish-cache.org/trac/wiki/FAQ/Compression
    if (req.http.Accept-Encoding) {
        if (req.url ~ "\.(jpg|jpeg|png|gif|gz|tgz|bz2|tbz|mp3|ogg|swf|flv)$") {
            # No point in compressing these
            unset req.http.Accept-Encoding;
        } elsif (req.http.Accept-Encoding ~ "gzip") {
            set req.http.Accept-Encoding = "gzip";
        } elsif (req.http.Accept-Encoding ~ "deflate" && req.http.user-agent !~ "MSIE") {
            set req.http.Accept-Encoding = "deflate";
        } else {
            # unknown algorithm
            unset req.http.Accept-Encoding;
        }
    }

    # Remove all marketing get parameters to minimize the cache objects
    if (req.url ~ "(\?|&)(gclid|cx|ie|cof|siteurl|zanpid|origin|fbclid|mc_[a-z]+|utm_[a-z]+|_bta_[a-z]+)=") {
        set req.url = regsuball(req.url, "(gclid|cx|ie|cof|siteurl|zanpid|origin|fbclid|mc_[a-z]+|utm_[a-z]+|_bta_[a-z]+)=[-_A-z0-9+()%.]+&?", "");
        set req.url = regsub(req.url, "[?|&]+$", "");
    }

    # Static files caching
    if (req.url ~ "^/(pub/)?(media|static)/") {
        # Static files should not be cached by default
        # return (pass);

        # But if you use a few locales and don't use CDN you can enable caching static files by commenting previous line (#return (pass);) and uncommenting next 3 lines
        unset req.http.Https;
        unset req.http.HTTP-SSL-OFFLOADED;
        unset req.http.Cookie;
    }

    return (hash);
}

sub vcl_hash {
    if (req.http.cookie ~ "X-Magento-Vary=") {
        hash_data(regsub(req.http.cookie, "^.*?X-Magento-Vary=([^;]+);*.*$", "\1"));
    }

    # For multi site configurations to not cache each other's content
    if (req.http.host) {
        hash_data(req.http.host);
    } else {
        hash_data(server.ip);
    }

    # To make sure http users don't see ssl warning
    if (req.http.HTTP-SSL-OFFLOADED) {
        hash_data(req.http.HTTP-SSL-OFFLOADED);
    }

    if (req.http.X-Forwarded-Proto) {
        hash_data(req.http.X-Forwarded-Proto);
    }
    

    if (req.url ~ "/graphql") {
        call process_graphql_headers;
    }
}

sub process_graphql_headers {
    if (req.http.Store) {
        hash_data(req.http.Store);
    }
    if (req.http.Content-Currency) {
        hash_data(req.http.Content-Currency);
    }
}

sub vcl_backend_response {

    set beresp.grace = 3d;
    set beresp.ttl = 1w;

    if (beresp.http.content-type ~ "text") {
        set beresp.do_esi = true;
    }

    if (bereq.url ~ "\.js$" || beresp.http.content-type ~ "text") {
        set beresp.do_gzip = true;
    }

    if (beresp.http.X-Magento-Debug) {
        set beresp.http.X-Magento-Cache-Control = beresp.http.Cache-Control;
    }

    # cache only successfully responses and 404s
    if (beresp.status != 200 && beresp.status != 404) {
        set beresp.ttl = 0s;
        set beresp.uncacheable = true;
        return (deliver);
    } elsif (beresp.http.Cache-Control ~ "private") {
        set beresp.uncacheable = true;
        set beresp.ttl = 86400s;
        return (deliver);
    }

    # validate if we need to cache it and prevent from setting cookie
   if (beresp.ttl > 0s && (bereq.method == "GET" || bereq.method == "HEAD")) {
       unset beresp.http.set-cookie;
    }

   # If page is not cacheable then bypass varnish for 2 minutes as Hit-For-Pass
   if (beresp.ttl <= 0s ||
       beresp.http.Surrogate-control ~ "no-store" ||
       (!beresp.http.Surrogate-Control &&
       beresp.http.Cache-Control ~ "no-cache|no-store") ||
       beresp.http.Vary == "*") {
        # Mark as Hit-For-Pass for the next 2 minutes
        set beresp.ttl = 120s;
        set beresp.uncacheable = true;
    }

    return (deliver);
}

sub vcl_deliver {
    set resp.http.Access-Control-Allow-Origin = "*";
    
    if (resp.http.X-Magento-Debug) {
        if (resp.http.x-varnish ~ " ") {
            set resp.http.X-Magento-Cache-Debug = "HIT";
            set resp.http.Grace = req.http.grace;
        } else {
            set resp.http.X-Magento-Cache-Debug = "MISS";
        }
    } else {
        unset resp.http.Age;
    }

    # Not letting browser to cache non-static files.
    if (resp.http.Cache-Control !~ "private" && req.url !~ "^/(pub/)?(media|static)/") {
        set resp.http.Pragma = "no-cache";
        set resp.http.Expires = "-1";
        set resp.http.Cache-Control = "no-store, no-cache, must-revalidate, max-age=0";
    }

    unset resp.http.X-Magento-Debug;
    unset resp.http.X-Magento-Tags;
    unset resp.http.X-Powered-By;
    unset resp.http.Server;
    unset resp.http.X-Varnish;
    unset resp.http.Via;
    unset resp.http.Link;
}

# sub vcl_hit {
#    if (obj.ttl >= 0s) {
        # Hit within TTL period
#        return (deliver);
#    }
#    if (std.healthy(req.backend_hint)) {
#        if (obj.ttl + 600s > 0s) {
            # Hit after TTL expiration, but within grace period
#            set req.http.grace = "normal (healthy server)";
#            return (deliver);
#        } else {
            # Hit after TTL and grace expiration
#            return (miss);
#        }
#    } else {
        # server is not healthy, retrieve from cache
#        set req.http.grace = "unlimited (unhealthy server)";
#        return (deliver);
#    }
#}

Varnish metris:

MGT.uptime   1+00:50:49
MAIN.uptime  1+00:50:50

My questions now please:

  1. Are the parameters I inserted to varnish.service needed and if yes, the values I have there are ok or very high?
  2. In the vcl file can someone explain what it means and if it is written fine?
if (beresp.http.content-type ~ "text") {
        set beresp.do_esi = true;
    }
  1. Is varnish creates these kind of problem with images, or I should look somewhere else for my issue. If yes, I think I should have also other issues in my store, shouldn't I?
1

What you are observing is easily contributed by failed health probes in Varnish.

The default is to consider the backend as sick if it takes 2 or more seconds to respond:

backend default {
    .host = "/* {{ host }} */";
    .port = "/* {{ port }} */";
    .first_byte_timeout = 600s;
    .probe = {
        .url = "/pub/health_check.php";
        .timeout = 2s;
        .interval = 5s;
        .window = 10;
        .threshold = 5;
   }
}

So whenever it occurred that your server was under a heavy or load or the health check was slow, Varnish marked the backend as sick and prevented serving anything from it.

Since the default VCL for Magento instructs Varnish to not cache statics at all, it will fail to deliver images when the backend is "sick".

I'd recommend raising the mentioned timeout.

And on the related note, in any case, you would also want to change the probe URL to /health_check.php. The URL with /pub/ is for insecure setup. The secure setup assumes that the webroot is pub directory, so all URLs will be relative to it.

The /pub/health_check.php in Magento 2 source is a bug.

7
  • Do I really need health check in vcl file? – G. G. Jul 13 '20 at 21:50
  • 1
    It's required if you want to use the grace mode feature of Varnish. When Magento does have things cached up while e.g. PHP-FPM is down, it can serve cached copies instead of errors. – Danila Vershinin Jul 13 '20 at 21:52
  • I see. So if i understood right if health is commented in my vcl then my issue with media gallery images isn’t from varnish, right? – G. G. Jul 13 '20 at 21:55
  • The issue is likely from heavy system load overall, which side effects to a health probe that exceeds 2 seconds, which in turn results in "sick backend" in Varnish and its refusal to communicate to backend. Check metrics in uptime. – Danila Vershinin Jul 13 '20 at 21:58
  • 1
    Then you'd really want to check how fast the health check is returning. e.g. time curl http://127.0.0.1:8082/health_check.php -H 'Host: example.com' -H 'X-Forwarded-Proto: https' (you want to check directly with the backend response, thus you need to specify its port). – Danila Vershinin Jul 13 '20 at 22:47
1

I answered a similar question about failing backends containing some debugging commands: How do I properly debug the root cause of 503 errors produced by Varnish?

I always advise people to use varnishlog, because it contains valuable information about what's going on. I wrote an extensive blog post on how to use varnishlog: https://feryn.eu/blog/varnishlog-measure-varnish-cache-performance/.

Long story short: run varnishlog -g request -q "ReqUrl eq '/your-url'" and inspect the output. The FetchError tag will usually indicate what's going on.

Proactively running varnishlog -g raw -i backend_health will allow you do debug your health probes.

Try to create a reproducible case, capture the log information, and if you still need help, post the varnishlog output here, and I'll try to help.

4
  • Thank you for your answer. In varnishlog I don't have FetchError tag anywhere. I have Fetch_Body 2 chunked stream VCL_call BACKEND_FETCH VCL_return fetch Link bereq 1935301 fetch and Timestamp Fetch: 1594720392.379511 0.078102 0.078102 – G. G. Jul 14 '20 at 9:53
  • @G.G.Would you be so kind to share the full varnishlog output for the failing request? I suggest you add it to your original question. – Thijs Feryn Jul 15 '20 at 10:09
  • Of course I can but that's the problem. I don't have a failed request anywhere. In varnishlog I don't FetchError. Do you need varnishlog as it is? – G. G. Jul 15 '20 at 10:38
  • @G.G.The ideal scenario would be to have varnishlog running when the problem occurs. I'm not saying that there should be a FetchError tag, but at least there must be a way for you to identify the problem, and maybe even reproduce it. Every response coming from Varnish has an X-Varnish header containing the vxid of the transaction. You can filter the logs for this transaction ID and share the output here. I know it might be a tough job as this only happens occasionally. – Thijs Feryn Jul 15 '20 at 11:22

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.