Random Musings of an Insane Mind

After installing Varnish 2.0.5 on a machine, ESI Includes didn’t work. When using varnishlog, the first error that occurred when debugging was:

No ESI processing, first char not ‘< '

   12 SessionClose – timeout
   12 StatSess     – 124.177.181.149 50662 4 0 0 0 0 0 0 0
   12 SessionOpen  c 68.212.183.136 60087 66.244.147.44:80
   12 ReqStart     c 68.212.183.136 60087 409391565
   12 RxRequest    c GET
   12 RxURL        c /esi.html
   12 RxProtocol   c HTTP/1.1
   12 RxHeader     c Host: cd34.colocdn.com
   12 RxHeader     c User-Agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.2b4) Gecko/20091124 Firefox/3.6b4
   12 RxHeader     c Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
   12 RxHeader     c Accept-Language: en-us,en;q=0.5
   12 RxHeader     c Accept-Encoding: gzip,deflate
   12 RxHeader     c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
   12 RxHeader     c Keep-Alive: 115
   12 RxHeader     c Connection: keep-alive
   12 RxHeader     c X-lori-time-1: 1259718658980
   12 RxHeader     c Cache-Control: max-age=0
   12 VCL_call     c recv
   12 VCL_return   c lookup
   12 VCL_call     c hash
   12 VCL_return   c hash
   12 VCL_call     c miss
   12 VCL_return   c fetch
   12 Backend      c 14 cd34_com cd34_com
   12 ObjProtocol  c HTTP/1.1
   12 ObjStatus    c 200
   12 ObjResponse  c OK
   12 ObjHeader    c Date: Wed, 02 Dec 2009 01:50:59 GMT
   12 ObjHeader    c Server: Apache
   12 ObjHeader    c Vary: Accept-Encoding
   12 ObjHeader    c Content-Encoding: gzip
   12 ObjHeader    c Content-Type: text/html
   12 TTL          c 409391565 RFC 120 1259718659 0 0 0 0
   12 VCL_call     c fetch
   12 TTL          c 409391565 VCL 43200 1259718659
   12 ESI_xmlerror c No ESI processing, first char not ‘< '
   12 TTL          c 409391565 VCL 0 1259718659
   12 VCL_info     c XID 409391565: obj.prefetch (-30) less than ttl (-1), ignored.
   12 VCL_return   c deliver
   12 Length       c 68
   12 VCL_call     c deliver
   12 VCL_return   c deliver
   12 TxProtocol   c HTTP/1.1
   12 TxStatus     c 200
   12 TxResponse   c OK
   12 TxHeader     c Server: Apache
   12 TxHeader     c Vary: Accept-Encoding
   12 TxHeader     c Content-Encoding: gzip
   12 TxHeader     c Content-Type: text/html
   12 TxHeader     c Content-Length: 68
   12 TxHeader     c Date: Wed, 02 Dec 2009 01:50:59 GMT
   12 TxHeader     c X-Varnish: 409391565
   12 TxHeader     c Age: 0
   12 TxHeader     c Via: 1.1 varnish
   12 TxHeader     c Connection: keep-alive
   12 TxHeader     c X-Cache: MISS
   12 ReqEnd       c 409391565 1259718659.088263512 1259718659.127703667 0.000059366 0.039401770 0.000038385
   12 Debug        c "herding"

ESI received significant performance enhancements in 2.0.4 and 2.0.5 so, it seemed something was incompatible. Downgrading to 2.0.3 and using the VCL from another machine still resulted in ESI not working.

In this case, mod_deflate was running on the backend which was causing the issue. However, in reading the source code, it appears that message could also occur if your ESI include wasn’t handing back properly formed XML/HTML content. If your include doesn’t contain valid content and is only returning a small snippet, you might consider passing:

-p esi_syntax=0x1

on the command line that starts Varnish.

The changes in Varnish address the issue of ESI being enabled on binary content. Since the first character isn’t an < in almost all binary files (jpg, mpg, gif) and isn't the start of most .css/.js files, varnish doesn't need to spend extra time checking those files for includes. While you can and should selectively enable esi processing, this is just an added safeguard and a performance boost to compensate for vcl that might have an esi directive on static/binary content. Since Varnish 2.0.3 now worked properly with the new machine, we upgraded to Varnish 2.0.5 which introduced a very odd issue:

[Tue Dec 01 20:58:11 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.htmlt
[Tue Dec 01 20:58:13 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html7
[Tue Dec 01 20:58:24 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xfa
[Tue Dec 01 20:59:01 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xb5
[Tue Dec 01 20:59:06 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xe7
[Tue Dec 01 20:59:07 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\xd4
[Tue Dec 01 20:59:08 2009] [error] [client 66.244.147.40] File does not exist: /gfs/www/cd/cd34.com/index.html\x1c

This generated 404s on the piece of the page that contained the ESI include. Downgrading to 2.0.4 fixed the issue and the issue appears to already be fixed in Trunk. Varnish Ticket #585

Varnish 2.0.4 and mod_deflate disabled addressed the two issues that prevented ESI from working correctly on this new installation.

The administration interface is quite simple. When the widget is installed, drag it to the Sidebar, then, drag any widgets that you want displayed to the ESI Widget Sidebar.

Current issues:
* When a user is logged in and comments on a post, their ‘login’ information is left on the page if they are the first person to hit the page when Varnish caches the page. If someone is logged in and visits a post page and the page hasn’t been previously cached, the html that shows their login status is cached, though, new visitors see the information, but lack the credentials.

Addons that don’t work properly:
* Any poll application (possible solution to wrap widget in an ESI block)
* Any stat application (unless they convert to a webbug tracker, this probably cannot be fixed easily)
* Any advertisement/banner rotator that runs internal. OpenX will work, as will most non-plugin
* Any postcount/postviews addon
* CommentLuv?
* ExecPHP (will cache the output, but does work)
* Manageable

Any plugin that does something at the time of the post or comment phase, that isn’t dependent on the logged in data should work without a problem. If it requires a login, or uses the IP address to determine whether a visitor has performed an action, will have a problem due to the excessive caching. For sites where the content is needed to be served quickly and there aren’t many comments, ESI Widget would work well.

Because of the way Varnish works, you wouldn’t necessarily have to run Varnish on the server running WordPress. Point the DNS at the Varnish server and set the backend for the host to your WordPress server’s IP address and you can have a Varnish server across the country caching your blog.

While talking about WordPress and it’s abysmal performance in high traffic situations to a client, we started looking back at Varnish and other solutions to keep their machine responsive. Since most of the caching solutions generate a page, serve it and cache it, posts and comments tend to lag behind the cache. db-cache does work around this by caching the query objects so that the pages can be generated more quickly and does expire the cache when tables are updated, but, its performance is still lacking. Using APC’s opcode cache or memcached just seemed to add complexity to the overall solution.

Sites like perezhilton.com appear to run behind multiple servers running Varnish, use wp-cache, move the images off to a CDN which results in a 3 request per second site with an 18 second pageload. Varnish’s cache always shows an age of 0 meaning Varnish is acting more as a load balancer than a front-end cache.

Caching isn’t without its downside. Your weblogs will not represent the true traffic. Since Varnish intercepts and serves requests before they get to the backend, those hits never hit the log. Forget pageview/postview stats (even with addons) because the addon won’t get loaded except during caching. Certain Widgets that rely on cookies or IP addresses will need to be modified. A workaround is to use a Text Box Widget and do an ESI include of the widget. For this client, we needed only some of the basic widgets. The hits in the apache logs will come from an IP of 127.0.0.1. Adjust your apache configuration to show the X-Forwarded-For IP address in the logs. If you truly need statistics, you’ll need to use something like Google Analytics. Put their code outside your page elements so that waiting for that javascript to load doesn’t slow down the rendering in the browser.

The test site, http://varnish.cd34.com/ is running Varnish 2.0.4, Apache2-mpm-prefork 2.2.11, Debian/Testing, WordPress 2.8.2. I’ve loaded the default .xml import for testing templates so that there were posts with varied dates and construction in the site. To replicate the client’s site, the following Widgets were added the sidebar: Search, Archives, Categories, Pages, Recent Posts, Tag Cloud, Calendar. Calendar isn’t in the existing site, but, since it is a very ‘expensive’ SQL query to run, it made for a good benchmark.

The demo site is running on:

model name	: Intel(R) Celeron(R) CPU 2.40GHz
stepping	: 9
cpu MHz		: 2400.389
cache size	: 128 KB

with a Western Digital 80gb 7200RPM IDE drive. Since all of the benchmarking was done on the same machine without any config changes taking place between tests, our benchmarks should represent as even a test base as we can expect.

Regrettably, our underpowered machine couldn’t run the benchmark with 50 concurrent tests, nor, could it run the benchmarks with the Calendar Widget enabled. In order to get apachebench to run, we had to bump the number of requests down and reduce the number of concurrent tests.

These results are from Apache without Varnish.

Server Software:        Apache
Server Hostname:        varnish.cd34.com
Server Port:            80

Document Path:          /
Document Length:        43903 bytes

Concurrency Level:      10
Time taken for tests:   159.210 seconds
Complete requests:      100
Failed requests:        0
Write errors:           0
Total transferred:      4408200 bytes
HTML transferred:       4390300 bytes
Requests per second:    0.63 [#/sec] (mean)
Time per request:       15921.022 [ms] (mean)
Time per request:       1592.102 [ms] (mean, across all concurrent requests)
Transfer rate:          27.04 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    2   7.0      0      25
Processing: 14785 15863 450.2  15841   17142
Waiting:     8209 8686 363.4   8517    9708
Total:      14785 15865 451.4  15841   17142

Percentage of the requests served within a certain time (ms)
  50%  15841
  66%  15975
  75%  16109
  80%  16153
  90%  16628
  95%  16836
  98%  17001
  99%  17142
 100%  17142 (longest request)

Normally we would have run the Varnish enabled test without the Calendar Widget, but, I felt confident enough to run the test with the widget in the sidebar. Varnish was configured with a 12 hour cache (yes, I know, I’ll address that later) and the ESI Widget was loaded.

Server Software:        Apache
Server Hostname:        varnish.cd34.com
Server Port:            80

Document Path:          /
Document Length:        45544 bytes

Concurrency Level:      50
Time taken for tests:   18.607 seconds
Complete requests:      10000
Failed requests:        0
Write errors:           0
Total transferred:      457980000 bytes
HTML transferred:       455440000 bytes
Requests per second:    537.44 [#/sec] (mean)
Time per request:       93.034 [ms] (mean)
Time per request:       1.861 [ms] (mean, across all concurrent requests)
Transfer rate:          24036.81 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   1.8      0      42
Processing:     1   92  46.2    105     451
Waiting:        0   91  45.8    104     228
Total:          2   93  46.0    105     451

Percentage of the requests served within a certain time (ms)
  50%    105
  66%    117
  75%    123
  80%    128
  90%    142
  95%    155
  98%    171
  99%    181
 100%    451 (longest request)

As you can see, even with the aging hardware, we went from .63 requests per second to 537.44 requests per second.

But, more about that 12 hour cache. The ESI Widget uses an Edge Side Include to include the sidebar into the template. Rather than just cache the entire page, we instruct Varnish to cache the page and include the sidebar. As a result, when a person surfs the site and goes from the front page to a post page, the sidebar doesn’t need to be regenerated when they go to the 2nd page. With wp-cache, it would have regenerated the sidebar Widgets and then cached the resulting page. Obviously, that 12 hour cache is going to affect the usability of the site, so, ESI widget purges the sidebar, front page and post page any time a post is updated or deleted or commented on. Voila, even with a long cache time, we are presented with a site that is dynamic and not delayed until wp-cache’s page cache expires. As this widget is a concept, I’m sure a little intelligence can be added to prevent the excessive purging in some cases, but, it does handle things reasonably well. There are some issues not currently handled with the ESI including how to handle users that are logged for comments. With some template modifications, I think those pieces can be handled with ESI to provide a lightweight method for the authentication portion.

While I have seen other sites mention Varnish and other methods to keep your wordpress installation alive in high traffic, I believe this approach is a step in the right direction. With the ESI widget, you can focus on your site, and let the server do the hard work. This methodology is based on a CMS that I have contemplated writing for many years, though, using Varnish rather than static files.

It is a concept developed in roughly four hours including the time to write the widget and do the benchmarking. It isn’t perfect, but does address the immediate needs of the one client. I think we can consider this concept a success.

If you don’t have the ability to modify your system to run Varnish, then you would be limited to running wp-cache and db-cache. If you can connect to a memcached server, you might consider running Memcached for WordPress as it will make quite a difference as well.

This blog site, http://cd34.com/blog/ is not running behind Varnish. To see the Varnish enabled site with ESI Widget, go to http://varnish.cd34.com/

Software Mentioned:

* Varnish ESI and Purge and Varnish’s suggestions for helping WordPress
* WordPress
* wp-cache
* db-cache

Sites used for reference:

* Supercharge WordPress
* SSI, Memcached and Nginx (with mentions of a Varnish/ESI configuration)

Varnish configuration used for ESI-Widget:

backend default {
.host = "127.0.0.1";
.port = "81";
}

sub vcl_recv {
 if (req.request == "PURGE") {
     purge("req.url == " req.url);
 }

 if (req.url ~ "\.(png|gif|jpg|ico|jpeg|swf|css|js)$") {
    unset req.http.cookie;
  }
  if (!(req.url ~ "wp-(login|admin)")) {
    unset req.http.cookie;
  }
}

sub vcl_fetch {
   set obj.ttl = 12h;
   if (req.url ~ "\.(png|gif|jpg|ico|jpeg|swf|css|js)$") {
      set obj.ttl = 24 h;
   } else {
      esi;  /* Do ESI processing */
   }
}