Varnish is working with everything but magento

[plumrocket]

Hello Nexcess,

One month ago we went on Magento Imagine conference where Nexcess rep's suggested to use Varnish + Turpentine extension to speed up magento sites.

We've tried reading all manuals possible to make Varnish work with Magento CE 1.7.0.2 and still no luck... Varnish works for all pages but magento.

So we really need your help.

This is the testing magento website on our hosting (where varnish doesn't work): http://demo-ihor1.plumrocket.net

And here is the file under sub-folder where varnish works: http://demo-ihor1.plumrocket.net/test/php/test.html

We use this website to test: http://www.isvarnishworking.com/

Or check varnish logs:

  11 Fetch_Body   b 3(chunked) cls 0 mklen 1
   11 Length       b 11542
   11 BackendReuse b default
   19 RxRequest    c GET
   19 RxURL        c /
   19 RxProtocol   c HTTP/1.1
   19 RxHeader     c TE: deflate,gzip;q=0.3
   19 RxHeader     c Connection: TE, close
   19 RxHeader     c Cache-Control: max-age=0
   19 RxHeader     c Accept-Encoding: gzip, x-gzip, deflate, x-bzip2
   19 RxHeader     c Host: demo-ihor1.plumrocket.net
   19 RxHeader     c User-Agent: W3C_Validator/1.767
   19 VCL_call     c recv lookup
   19 VCL_call     c hash
   19 Hash         c /
   19 Hash         c demo-ihor1.plumrocket.net
   19 VCL_return   c hash
   19 HitPass      c 720790472
   19 VCL_call     c pass pass
   19 Backend      c 11 default default
   19 TTL          c 720790494 RFC 0 -1 -1 1368565285 0 1368565285 375007920 0
   19 VCL_call     c fetch
   19 TTL          c 720790494 VCL 120 -1 -1 1368565285 -0
   19 VCL_return   c hit_for_pass
   19 ObjProtocol  c HTTP/1.1
   19 ObjResponse  c OK
   19 ObjHeader    c Date: Tue, 14 May 2013 21:01:25 GMT
   19 ObjHeader    c Server: Apache
   19 ObjHeader    c Expires: Thu, 19 Nov 1981 08:52:00 GMT
   19 ObjHeader    c Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
   19 ObjHeader    c Pragma: no-cache
   19 ObjHeader    c Set-Cookie: frontend=hclgf7i7u8nengg1kk473hq4u4; expires=Tue, 14-May-2013 22:01:25 GMT; path=/; domain=demo-ihor1.plumrocket.net; HttpOnly
   19 ObjHeader    c Content-Type: text/html; charset=UTF-8
   19 VCL_call     c deliver deliver
   19 TxProtocol   c HTTP/1.1
   19 TxStatus     c 200
   19 TxResponse   c OK
   19 TxHeader     c Server: Apache
   19 TxHeader     c Expires: Thu, 19 Nov 1981 08:52:00 GMT
   19 TxHeader     c Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
   19 TxHeader     c Pragma: no-cache
   19 TxHeader     c Set-Cookie: frontend=hclgf7i7u8nengg1kk473hq4u4; expires=Tue, 14-May-2013 22:01:25 GMT; path=/; domain=demo-ihor1.plumrocket.net; HttpOnly
   19 TxHeader     c Content-Type: text/html; charset=UTF-8
   19 TxHeader     c Content-Length: 11542
   19 TxHeader     c Accept-Ranges: bytes
   19 TxHeader     c Date: Tue, 14 May 2013 21:01:25 GMT
   19 TxHeader     c X-Varnish: 720790494
   19 TxHeader     c Age: 0
   19 TxHeader     c Via: 1.1 varnish
   19 TxHeader     c Connection: close
   19 TxHeader     c X-Cache: MISS!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
   19 Length       c 11542
   19 ReqEnd       c 720790494 1368565285.054073334 1368565285.218540907 0.000087738 0.164434195 0.000033379
   19 SessionClose c Connection: close

Our magento .HTACCESS FILE:

    DirectoryIndex index.php

<IfModule mod_php5.c>

    php_value memory_limit 256M
    php_value max_execution_time 18000
    php_flag magic_quotes_gpc off
    php_flag session.auto_start off
    php_flag suhosin.session.cryptua off
    php_flag zend.ze1_compatibility_mode Off

</IfModule>

<IfModule mod_security.c>
    SecFilterEngine Off
    SecFilterScanPOST Off
</IfModule>

<IfModule mod_deflate.c>
</IfModule>

<IfModule mod_ssl.c>
    SSLOptions StdEnvVars
</IfModule>

<IfModule mod_rewrite.c>
    Options +FollowSymLinks
    RewriteEngine on
    RewriteRule ^api/rest api.php?type=rest [QSA,L]
    RewriteRule .* - [E=HTTP_AUTHORIZATION:%{HTTP:Authorization}]
    RewriteCond %{REQUEST_METHOD} ^TRAC[EK]
    RewriteRule .* - [L,R=405]
    RewriteCond %{REQUEST_URI} !^/(media|skin|js)/
    RewriteCond %{REQUEST_FILENAME} !-f
    RewriteCond %{REQUEST_FILENAME} !-d
    RewriteCond %{REQUEST_FILENAME} !-l
    RewriteRule .* index.php [L]
</IfModule>

    AddDefaultCharset Off

<IfModule mod_expires.c>
    ExpiresDefault "access plus 1 year"
</IfModule>

    Order allow,deny
    Allow from all

    <Files RELEASE_NOTES.txt>
        order allow,deny
        deny from all
    </Files>

I know that someone suggested that issue could be related to these headers: 19 TxHeader c Age: 0 Or 19 TxHeader c Set-Cookie: frontend=hclgf7i7u8nengg1kk473hq4u4;

If it is true - how can we fix this? It would be nice to have solution documented somewhere so others can use it.

Thank you.

[aheadley]

Did you install the Turpentine extension? The X-Cache header in the response isn't set by the VCL (Varnish config) that Turpentine generates.

[plumrocket]

Hello aheadley,

Yes, here is screenshots:

[plumrocket]

How do we make sure that Varnish takes VCL config generated by Turpentine ?

[aheadley]

You can hit the Apply Varnish Config button on the System > Cache Management page.

[plumrocket]

Hello Alex,

We just went to System > Cache Management and clicked on "Save Varnish Config" and "Apply Varnish Config".

Now for this subdomain "http://demo-ihor1.plumrocket.net/" on http://www.isvarnishworking.com/ I can see message "NOPE, We didn't find the "X-Varnish" header..."

However if I restart varnish: /etc/init.d/varnish restart

Then the X-Cache header you mentioned earlier will re-appear.

It looks like "Apply Varnish Config" makes some changes only until the next varnish restart?

[plumrocket]

Here is contents of system VCL file:

cat /etc/varnish/default.vcl

backend default {
  .host = "243.35.12.113";
  .port = "8088";
}

sub vcl_deliver {

  if (obj.hits > 0) {
    set resp.http.X-Cache = "HIT!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!";
  } else {
    set resp.http.X-Cache = "MISS!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!";
  }
}

[aheadley]

It looks like "Apply Varnish Config" makes some changes only until the next varnish restart?

Correct, if you want the changes to persist through a restart of Varnish you need to either tell Varnish to use the VCL that Turpentine generates (at $PATH_TO_MAGENTO/var/default.vcl by default) or replace /etc/varnish/default.vcl that file (or just symlink it so that Turpentine can update it as needed).

EDIT: Also, if Turpentine's debugging is turned off then isvarnishworking.com won't be able to tell that Varnish is enabled as the VCL removes the X-Varnish header that that site looks for.

[plumrocket]

Ok, I just replaced /etc/varnish/default.vcl with magento default.vcl and restarted varnish. It still doesnt work on "http://demo-ihor1.plumrocket.net/"

Here is latest varnish log:

   14 Hash         c
   14 Hash         c &c=
   14 Hash         c
   14 VCL_return   c hash
   14 VCL_call     c pipe pipe
   14 Backend      c 15 default default
   14 ReqEnd       c 1999969327 1368644656.048365116 1368644656.069883108 0.000036955 0.000128031 0.021389961
   14 StatSess     c 36.25.43.17 46246 0 1 1 1 0 0 0 0
   11 SessionOpen  c 36.25.43.17 38618 :80
   11 SessionClose c pipe
   13 BackendOpen  b default 243.35.12.113 57709 243.35.12.113 8088
   13 TxRequest    b GET
   13 TxURL        b /skin/frontend/default/default/css/print.css
   13 TxProtocol   b HTTP/1.1
   13 TxHeader     b Host: demo-ihor1.plumrocket.net
   13 TxHeader     b Cache-Control: max-age=0
   13 TxHeader     b Accept: text/css,*/*;q=0.1
   13 TxHeader     b If-None-Match: "27a75a-621-4c412e88f3f40"
   13 TxHeader     b If-Modified-Since: Thu, 05 Jul 2012 10:49:57 GMT
   13 TxHeader     b User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.64 Safari/537.31
   13 TxHeader     b Referer: http://demo-ihor1.plumrocket.net/
   13 TxHeader     b Accept-Language: en-US,en;q=0.8
   13 TxHeader     b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
   13 TxHeader     b Cookie: adminhtml=<redacted>; frontend=2cb59da9-7477-4477-864f-533576b85a36
   13 TxHeader     b X-Forwarded-For: 36.25.43.17
   13 TxHeader     b Accept-Encoding: gzip
   13 TxHeader     b X-Varnish: 1999969328
   13 TxHeader     b Connection: close
   13 BackendClose b default
   11 ReqStart     c 36.25.43.17 38618 1999969328
   11 RxRequest    c GET
   11 RxURL        c /skin/frontend/default/default/css/print.css
   11 RxProtocol   c HTTP/1.1
   11 RxHeader     c Host: demo-ihor1.plumrocket.net
   11 RxHeader     c Connection: keep-alive
   11 RxHeader     c Cache-Control: max-age=0
   11 RxHeader     c Accept: text/css,*/*;q=0.1
   11 RxHeader     c If-None-Match: "27a75a-621-4c412e88f3f40"
   11 RxHeader     c If-Modified-Since: Thu, 05 Jul 2012 10:49:57 GMT
   11 RxHeader     c User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.64 Safari/537.31
   11 RxHeader     c Referer: http://demo-ihor1.plumrocket.net/
   11 RxHeader     c Accept-Encoding: gzip,deflate,sdch
   11 RxHeader     c Accept-Language: en-US,en;q=0.8
   11 RxHeader     c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
   11 RxHeader     c Cookie: adminhtml=<redacted>; frontend=2cb59da9-7477-4477-864f-533576b85a36
   11 VCL_call     c recv pipe
   11 VCL_call     c hash
   11 Hash         c /skin/frontend/default/default/css/print.css
   11 Hash         c demo-ihor1.plumrocket.net
   11 Hash         c
   11 Hash         c gzip
   11 Hash         c s=
   11 Hash         c

[aheadley]

Did you enable the Varnish Pages and Varnish ESI Blocks caches under System > Cache Management?

[plumrocket]

Yes, just did again. Still the same result.

[plumrocket]

By the way, non-magento page that was cached with varnish (in my first post) is not cached anymore.

http://demo-ihor1.plumrocket.net/test/php/test.html

[aheadley]

Ok, can you run this command: varnishadm vcl.show "$(varnishadm vcl.list | grep '^active' | awk '{print $3}')"

and put the output on gist.github.com and link it here? This will show me your active VCL.

EDIT: You will (probably) need to run that command as root or use sudo.

[plumrocket]

Ok, done: https://gist.github.com/plumrocket/abff119354276688be11

[aheadley]

Ok, the problem is that the VCL you copied to /etc/varnish/default.vcl was generated before the Varnish ESI Pages cache was enabled so the VCL tells Varnish not to cache anything. You need to hit the Save Varnish Config button to regenerate the VCL and re-copy $PATH_TO_MAGENTO/var/default.vcl to /etc/varnish/default.vcl then restart Varnish.

[plumrocket]

Alex, Ok, I saved varnish config again and replaced old one in /etc/varnish/default.vcl and restarted varnish.

Here is new VCL: https://gist.github.com/plumrocket/cc06b9089cdfb267d4f2

Here is latest Log: https://gist.github.com/plumrocket/f5ed7d43733bcd857821

Still not working

[aheadley]

Unfortunately that log snippet doesn't really show anything besides a cache miss, how are you determining that it's not working?

[plumrocket]

Alex, I was checking on http://www.isvarnishworking.com/ , but you made me realize that it might be not the best way to check.

I just run command: varnishstat

and saw the "Hitrate ratio:" started changing after each page refresh.

Here is results of "varnishstat": https://gist.github.com/plumrocket/a659473f0089ab1dc119

Firebug also shows 66ms server response time. I think its faster than before.

Do you think its working now?

[plumrocket]

One more thing. I tried enabling APC cache, and varnishstat "Hitrate ratio" wasn't changing.

Is that means that APC & Varnish cannot work together?

[aheadley]

Do you think its working now?

It looks like it, but if you want to know for sure you can enable Turpentine's debugging and check the X-Varnish-Hits header.

Is that means that APC & Varnish cannot work together?

APC should work fine with Turpentine/Varnish. Note that the "Hitrate ratio" is a ratio so it won't necessarily change with each page load, you'd need to look at the actual hit/miss counters.

[plumrocket]

Ok, Thanks a lot for your help then!

One last question to you. I checked our test site with firebug and found that turpentine loads something for 1.33s. Is it normal?

[aheadley]

I checked our test site with firebug and found that turpentine loads something for 1.33s. Is it normal?

Those are the messages and _globalmessages blocks and are loaded via AJAX so their load times aren't really noticeable to a visitor. That said, 1.3s is probably longer than normal; is it like on every page load?

[plumrocket]

Yes, it looks like on all pages. And always 1.31 - 1.33 seconds.

Try yourself: http://demo-ihor1.plumrocket.net/

[x86fantini]

hi, similar problem happened to me also, in my case was memcache that was not flushing his cache correctly so magento always read "old" vcl file.

now i have only varnish + nginx and magento using APC as cache, and results are very interesting :+1: http://www.magespeedtest.com/results?key=97194809-83d4-4e0c-8f4c-6632823b7f68

[plumrocket]

x86fantini, thanks for comment. I just checked your site hosted on ip from your magespeed test, but I do not see turpentine in firebug. Are you sure you have it enabled?

[x86fantini]

really? try to clean ur firefox cache :)

please take a look

[plumrocket]

Alex,

Can you suggest something on turpentine's AJAX script that takes 1.31 - 1.33 seconds to load??

I actually ran couple of siege tests before installing Varnish + Turpentine and after. Please check my results here: https://gist.github.com/plumrocket/d342f39c45fdedf39157

Whats weird is that:

1) response time with just APC enabled for 25 concurrent siege users is at "0.83" seconds. While when APC+VARNISH is installed, response time = "2.09" seconds. Basically never lower than 2 seconds.

2) because of response time difference, number of successful (OKAY) transactions is almost twice higher for APC than APC+VARNISH.

3) you can only start noticing difference with more than 50 concurrent siege users. When number of transactions double and triple for APC+VARNISH configuration.

---

Do you think it is related to the issue with AJAX turpentine script ?

[aheadley]

Can you suggest something on turpentine's AJAX script that takes 1.31 - 1.33 seconds to load??

I'm not sure what would cause that only for one of the requests. Can you look at the responses for the two XHR requests in the developer tools and see what the X-Turpentine-Block header is for the one that takes longer to load? Also, what session storage method are you using?

While when APC+VARNISH is installed, response time = "2.09" seconds.

I would guess that your version of siege isn't being picked up as a crawler by Turpentine. Since siege doesn't support cookies it makes Varnish generate a new session for each request which means the ESI blocks need to be regenerated for each request. What User-Agent is your version of seige using (try looking in your webserver logs)?

Do you think it is related to the issue with AJAX turpentine script ?

No, seige doesn't process the response HTML so it doesn't do the AJAX requests at all.

[plumrocket]

Hello Alex,

You were right about Siege, I had version 2.7 installed on Ubuntu and it was probably too old.

I installed version 3.0 on Amazon EC2 Centos 6.3 and ran tests again..

Here is results (800 concurrent users):

Transactions: 12338 hits Availability: 100.00 % Elapsed time: 60.28 secs Data transferred: 117.99 MB Response time: 1.85 secs Transaction rate: 204.68 trans/sec Throughput: 1.96 MB/sec Concurrency: 379.26 Successful transactions: 12338 Failed transactions: 0 Longest transaction: 31.06 Shortest transaction: 0.03

Full results are here: https://gist.github.com/plumrocket/d342f39c45fdedf39157

I think its good this time

[aheadley]

Glad to hear it.