Front-end Search and use of Varnish with 2.0.2

[robfico]

When running 2.0.2 Enterprise with the standard built-in FPC enabled, front-end searches are fine, run quickly, run in parallel when tested concurrently, etc...

When switching to Varnish, the search becomes much slower, and even under parallel loads, only runs one search at a time, causing other search attempts to back up and wait for the ones in front of it to finish (siege tests back up and timeout). We verified Varnish set up is correct, as home page, catalog pages, product pages, etc... all get cached by Varnish, have proper results, etc... as expected with Varnish.

We also noticed that when adding a product to the cart, with Varnish on the TTFB is twice as slow as adding to the cart using the built-in FPC. Just an observation. Using the view cart link in both FPC and Varnish has the same time for TTFB and transactions/second, it's just adding a product to the cart that is twice as slow with Varnish enabled.

Not sure what would be causing these results, but they are easily reproduced when running one install via FPC, and the same install configured for Varnish.

[choukalos]

Hello @robfico can you provide some more details on your environment as we haven't seen this issue before. Are you using DNS names ( perhaps there's an issue with them resolving? )? What VCL file are you using? What are you using for your web server - Nginx or Apache, what port is the web server running on?

Thanks,
Chuck

[robfico]

Sure. Sorry for the lack of details before. Just wanted to make sure it was not already known or addressed, in case my search missed something...

The M2EE 2.0.2 install uses an IP number, so no DNS issues. Environment is:
centOS 6, 64-bit OS
Apache 2.2.31 (port 8080 for Varnish support)
MySQL 5.6.25
PHP 5..5.33 using php-fpm with Zend OpCode cache enabled
Varnish 4.0.3 using varnish4.vcl generated by Magento (port 80)
4 core 3.2 GHz CPU, RAID-10, 16 GB RAM, Gigabit network

I switched the install to FPC through Apache/php-fpm, ran a 60 second siege against search, and got these results:
Transactions: 219 hits
Availability: 100.00 %
Elapsed time: 59.72 secs
Data transferred: 23.03 MB
Response time: 3.94 secs
Transaction rate: 3.67 trans/sec
Throughput: 0.39 MB/sec
Concurrency: 14.46
Successful transactions: 219
Failed transactions: 0
Longest transaction: 6.83
Shortest transaction: 1.88
lots of php-fpm children as expected.

I then switched it back to Varnish, flushed all caches, ran same siege and received these results:
Transactions: 56 hits
Availability: 88.89 %
Elapsed time: 59.20 secs
Data transferred: 0.70 MB
Response time: 9.83 secs
Transaction rate: 0.95 trans/sec
Throughput: 0.01 MB/sec
Concurrency: 9.30
Successful transactions: 56
Failed transactions: 7
Longest transaction: 28.43
Shortest transaction: 1.02
one php-fpm child during entire test

Once switched to using Varnish, the search is considerably slower, and will only run one hit at a time. All other URLs / features run fine with Varnish, lots of php-fpm children for multiple hits, etc...

default.vcl.txt

[choukalos]

Created internal ticket - MAGETWO-52607 for tracking as a performance bug.

[bwaters]

I am having trouble reproducing these results. The number of transactions per second seem low. Can you confirm that you are running in production mode and have done all the steps to switch -- ie remove any conflicting MAGE_MODE server-variables in .htaccess or apache config and then
run

bin/magento deploy:mode:set production

Also how was your siege test structured did you have the same query or a url file with a lot of unique queries, and how large, extensive is your catalog in terms of number of items in your store?

[robfico]

Yes, it was in production mode, no conflicts, etc... Same store using FPC was fast for search and adding to cart, with Varnish it was much slower for search and add to cart. siege tests were same URL. The catalog was around 5,000 products.

[bwaters]

Thank you for pointing out this issue -- still working on a general fix but this is a solution for your version of varnish.

In sub vcl_backend_response {

At the bottom remove the return (deliver); and then add the following:

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

[pynej]

Both this pull request and the sample code above cause all page's to stop being served by varnish.

[piotrekkaminski]

@pynej can you elaborate? Do you mean Varnish doesn't work on 2.1RC1?

[pynej]

I didn't try the RC. I simply tried adding the indicated code sample from bwaters into my varnish.vcl and checked the hit/miss of my content pages. With the code addition all the pages in the site constantly miss. Similarly remove the line form the listed change 5544d73 causes all pages to miss. I don't have the log on hand.

[bwaters]

@pynej Thanks for the heads up.

This is the new code I am currently testing for 2.1
If you have a chance can you try it out?

remove return (deliver); at bottom of vcl_backend_response and replace with

   # 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.Vary == "*")) {
        # Mark as Hit-For-Pass for the next 2 minutes
        set beresp.ttl = 120s;
        set beresp.uncacheable = true;
    }
    return (deliver);

[pynej]

if (beresp.ttl <= 0s ||
beresp.http.Surrogate-control ~ "no-store" ||
(!beresp.http.Surrogate-Control && beresp.http.Vary == "*")) {
# Mark as Hit-For-Pass for the next 2 minutes
set beresp.ttl = 120s;
set beresp.uncacheable = true;
}
return (deliver);

@bwaters This is working as expected.

Results: (monitor with sudo varnishncsa -F "%U %{Varnish:time_firstbyte}x %T %{Varnish:handling}x")

Original config.

/outerwear.html 0.000139 0 hit
/pub/static/frontend/Superior/Custom/en_US/mage/calendar.css 0.000113 0 hit
/pub/static/frontend/Superior/Custom/en_US/css/styles-m.css 0.000115 0 hit
/pub/static/frontend/Superior/Custom/en_US/css/styles-l.css 0.000145 0 hit
/pub/static/frontend/Superior/Custom/en_US/css/custom.css 0.000184 0 hit
/pub/static/frontend/Superior/Custom/en_US/Magento_Swatches/css/swatches.css 0.000120 0 hit
/pub/static/_cache/merged/14e410c0dcc9ac037efd21fcde18665b.js 0.000102 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/5/7/578675_luckygreenblack_flat_front.jpg 0.000108 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/e/b/eb225_deepmagenta_flat_front_8.jpg 0.000104 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/l/o/loe720_geargrey_flat_front.jpg 0.000103 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/o/e/oe720_blacktop_flat_front.jpg 0.000110 0 hit
/pub/static/frontend/Superior/Custom/en_US/js/custom.js 0.000108 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/e/b/eb225_navy_flat_front.jpg 0.000114 0 hit
/pub/static/frontend/Superior/Custom/en_US/fonts/opensans/regular/opensans-400.woff2 0.000114 0 hit
/pub/static/frontend/Superior/Custom/en_US/fonts/Blank-Theme-Icons/Blank-Theme-Icons.woff2 0.000113 0 hit

After change

/outerwear.html 0.000134 0 hit
/pub/static/frontend/Superior/Custom/en_US/mage/calendar.css 0.000130 0 hit
/pub/static/frontend/Superior/Custom/en_US/css/styles-m.css 0.000138 0 hit
/pub/static/frontend/Superior/Custom/en_US/css/custom.css 0.000113 0 hit
/pub/static/frontend/Superior/Custom/en_US/Magento_Swatches/css/swatches.css 0.000179 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/e/b/eb225_navy_flat_front.jpg 0.000139 0 hit
/pub/static/_cache/merged/14e410c0dcc9ac037efd21fcde18665b.js 0.000133 0 hit
/pub/static/frontend/Superior/Custom/en_US/css/styles-l.css 0.000142 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/5/7/578675_luckygreenblack_flat_front.jpg 0.000116 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/e/b/eb225_deepmagenta_flat_front_8.jpg 0.000112 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/o/e/oe720_blacktop_flat_front.jpg 0.000110 0 hit
/pub/media/catalog/product/cache/1/small_image/240x300/beff4985b56e3afdbeabfc89641a4582/l/o/loe720_geargrey_flat_front.jpg 0.000124 0 hit
/pub/static/frontend/Superior/Custom/en_US/js/custom.js 0.000124 0 hit
/pub/static/frontend/Superior/Custom/en_US/css/print.css 0.000151 0 hit

[KrystynaKabannyk]

Hello @robfico, this issue has been fixed in the 2.1.0 Release, that's why I'm closing it. If you any questions or additional information regarding the issue feel free to reopen it or create a new one.