First, a little background…

At LogNormal, we measure page load time (among other things) using JavaScript and beacon the results back to our servers. Our JavaScript is based on boomerang and we serve a different build of the JavaScript file for each of our clients. The JavaScript has a max age of 1 week from request and most clients honour this and make a conditional request a week later. Most, but not all. The JavaScript sends us a beacon when complete, and the beacon includes the version number of the JavaScript file.

This configuration has been active for a few months, and the first file served using this configuration was pushed out on February 1st.

Note that all times mentioned are UTC. What we see — Our log files for June 4th show the following:

JavaScript timestamp JavaScript version Number of Requests
Feb 1 17:33:00 0.9.1328117580 168
Mar 8 15:39:17 0.9.1331221157 53
Mar 16 18:16:32 0.9.1331921792 9
Mar 22 03:33:44 0.9.1332387224 25
Mar 27 16:39:11 0.9.1332866351 4
Mar 28 16:03:01 0.9.1332950581 28
Mar 28 19:59:40 0.9.1332964780 3
Mar 29 16:04:27 0.9.1333037067 6
Mar 30 22:23:14 0.9.1333146194 2
Mar 31 00:52:20 0.9.1333155140 161
Apr 9 17:34:33 0.9.1333992873 387
Apr 11 13:37:46 0.9.1334151466 17
Apr 11 16:46:14 0.9.1334162774 69
Apr 13 17:35:38 0.9.1334338538 388
Apr 19 21:26:08 0.9.1334870768 1
Apr 19 22:43:46 0.9.1334875426 241
Apr 28 18:11:26 0.9.1335636686 118
May 1 07:27:15 0.9.1335857235 169
May 1 22:17:11 0.9.1335910631 2411
May 23 08:10:48 0.9.1337760648 1529
May 25 20:41:28 0.9.1337978488 3837537

That last row is the latest version of the file, but as you can see, we still receive beacons from the version we pushed out on Feb 1. I decided to look only at requests from the oldest version of our JavaScript. The first thing to do was see if there was a pattern to these requests. Looking at our logs showed that three IPs accounted for the majority of these requests, and this was common across several days of logs.

Further investigation showed that all three of these IPs were proxies, two of which belonged to the same company and used the bluecat proxy software. I was unable to identify the proxy software running on the third host.

Forcing a cache refresh

As luck would have it, Stoyan and Steve did some research on forcing clients to update a cached script and this was exactly what I needed as the next step.

Our first attempt at this resulted in some of our users complaining about the reload page opening in a new tab. This time I decided to limit the test only to these three IPs and see what happened. Additionally, I made some changes to the reload HTML to let me know if things went wrong, and to avoid infinite loops if the proxy refused to update the script.

This is what the JavaScript in our new reload file looked like:

if(!window.parent) {
	BOOMR.version += '-1';
}
else if(window.parent === window) {
	BOOMR.version += '-2';
}
if (location.hash === '') {
	location.hash = "check";
	location.reload(true);
}
else if(location.hostname == 'lognormal.net') {
	location.href="about:blank";
}

The first two conditions check for exceptional situations that tell us if the page loaded in a new tab, or something weird. The last case makes sure our beacon only fires once (by default it fires every 5 minutes) if the user leaves the page open for a long time.

I added this in the morning of June 5th (UTC). There had been no requests from the Feb 1 version of the JavaScript prior to adding in this change. Over the course of the day, we received the following requests (sanitized for privacy). The displayed fields are: Time, response code, request URL, referrer URL, User Agent.

Remember that these requests come from a Proxy, so we see many different “users” from the same IP.

IP 1 04:27:12.421 200 beacon.js?d=client1 http://client1_page MSIE 8.0

Beacon request from page belonging to client1, using MSIE 8.0

04:27:12.488 200 reload.html http://client1_page MSIE 8.0

Beacon loads reload.html in an iframe
Note that our JavaScript isn't loaded because it's cached

04:27:12.613 204 beacon.js?d=lognormal.net reload.html MSIE 8.0

Beacon loaded from reload.html returns a 204 because it knows this is the reload page

04:27:12.673 200 reload.html http://client1_page MSIE 8.0

Page reloaded

04:27:12.751 200 client1_js.js reload.html MSIE 8.0

JavaScript loaded (returns a 200)

15:25:29.925 200 client2_js.js http://client2_page Chrome/18.0 15:25:30.225 200 beacon.js?d=client2&t=4463033&v=0.9.1337978488 http://client2_page Chrome/18.0 15:28:05.349 200 beacon.js?d=client2&t=4463034&v=0.9.1337978488 http://client2_page Chrome/18.0

The 3 requests above are for pages belonging to client2, using Chrome 18, and all have the latest JavaScript, so no reload.

15:53:23.396 200 beacon.js?d=client1&t=4463039&v=0.9.1337978488 http://client1_page MSIE 8.0

Another request for a page belonging to client1, but this time with the latest JavaScript

16:08:54.995 200 beacon.js?d=client1 http://client1_page MSIE 8.0 16:08:56.606 200 reload.html http://client1_page MSIE 8.0 16:08:56.844 204 beacon.js?d=lognormal.net reload.html MSIE 8.0 16:08:58.545 200 reload.html http://client1_page MSIE 8.0 16:08:58.609 200 client1_js.js reload.html MSIE 8.0

The 5 requests above are probably from a different user behind the same proxy, starts off with the old JavaScript, and ends up with the new JavaScript

17:48:46.666 200 beacon.js?d=client1&t=4463062&v=0.9.1337978488 http://client1_page MSIE 8.0 18:45:34.777 200 beacon.js?d=client1&t=4463073&v=0.9.1337978488 http://client1_page MSIE 9.0 19:16:25.665 200 beacon.js?d=client1&t=4463079&v=0.9.1337978488 http://client1_page MSIE 8.0

And finally, 3 requests from MSIE 8 & 9 using the new JavaScript

IP 2 13:07:25.914 200 beacon.js?d=client1 http://client1_page MSIE 8.0 13:07:26.474 200 reload.html http://client1_page MSIE 8.0 13:07:26.662 204 beacon.js?d=lognormal.net reload.html MSIE 8.0 13:07:26.837 200 reload.html http://client1_page MSIE 8.0 13:07:26.990 200 client1_js.js reload.html MSIE 8.0 13:07:36.524 200 beacon.js?d=client1&t=4463006&v=0.9.1337978488 http://client1_page MSIE 8.0

From the second IP, we see the same pattern starting with the old JavaScript and ending with the new JavaScript

19:20:14.674 200 beacon.js?d=client1&t=4463080&v=0.9.1337978488 http://client1_page MSIE 8.0 IP 3 13:36:28.651 200 beacon.js?d=client1 http://client1_page MSIE 8.0 13:36:30.385 200 reload.html http://client1_page MSIE 8.0 13:36:32.306 200 reload.html http://client1_page MSIE 8.0 13:36:32.593 200 client1_js.js reload.html MSIE 8.0

Same story here, but for some reason beacon.js is never requested a second time

13:48:46.252 200 beacon.js?d=client1 http://client1_page MSIE 8.0 13:50:28.566 200 reload.html http://client1_page MSIE 8.0 13:50:30.087 200 reload.html http://client1_page MSIE 8.0 13:50:30.262 200 client1_js.js reload.html MSIE 8.0

Then we go through the whole flow again

13:50:56.891 304 client1_js.js - "Mozilla/4.0 (compatible;)"

This is a strange request

13:51:00.284 200 beacon.js?d=client1&t=4463014&v=0.9.1337978488 http://client1_page MSIE 8.0 13:52:41.645 200 beacon.js?d=client1&t=4463015&v=0.9.1337978488 http://client1_page MSIE 8.0 14:05:07.855 200 beacon.js?d=client1&t=4463017&v=0.9.1337978488 http://client1_page MSIE 8.0

And a bunch of requests with the latest JavaScript

Results

I looked at the logs again at the end of the day (UTC), and this is what we have for the Feb 1st version:

JavaScript timestamp JavaScript version Number of Requests
Feb 1 17:33:00 2012 0.9.1328117580 35

The number of requests from the Feb 1 version of our JavaScript went down significantly, however, we should really look at the ratio.

On June 4, 153 out of 168 or 91% of requests from the Feb 1 version of our JavaScript came from the three IPs I looked at.

On June 5, the ratio is 6 out of 35 or 17%, giving us a 81% reduction in stale cache hits.

I’ll look at the numbers again tomorrow and update this post at that time and if things look good, will extend it to a few more IPs and versions.

Have thoughts on what else I should be looking at? Let me know in the comments. Interested in trying out LogNormal, visit our plans page.

Update: June 7

On June 6, 0 out of 84 requests using the Feb 1 version of our JavaScript came from the three IPs I looked at. We still receive many requests from old versions of our JavaScript, and over time we will try to get all of them to load up the latest version.