React Storefront
|

Debugging Performance

All requests served by the Moovweb XDN contain a response header called x-moov-t, which contains the time the request took at every layer of the Moovweb stack. This can be extremely helpful when diagnosing performance issues.

x-moov-t

The format is x-moov-t: <id>=<time>[,<id2>=<time2>...]

x-moov-t is an order list of timings: values are prepended at response time. Thus reading them left to right goes from the outermost edge (e.g. Fastly) to innermost component (e.g. moovworker). Furthermore every component timing includes the duration of processing of components inner from it. To calculate how much time each component took you can simply deduct component's *t from the next component's *t (e.g. outer edge took ot - nt)

Components

What are the components involved?

  • Outer Edge = o
  • Outer Edge Shield = s
  • Inner Edge NGINX = n
  • Inner Edge Varnish = v
  • MPS = m
  • MoovWorker = w

Keys

All times are in milliseconds.

Here is an example of the header:

x-moov-t: ot=180,oc=miss,of=179,st=170,sc=miss,sf=169,bf=169,nt=168,ep=5,et=165,vt=160,vc=miss,vf=144,mt=143,mu=133,wt=127,wu=113,wp=12,wc=2

If there is a cache hit, we do not report the remaining metrics

x-moov-t: ot=10,oc=hit
x-moov-t: ot=12,oc=miss,st=2,sc=hit
x-moov-t: ot=14,oc=miss,st=12,sc=miss,nt=2,vc=hit

Moovworker

  • wt = Total time (including wp)
  • wm = Time of longest upstream request that was completed
  • wp = Time executing JavaScript code in user request and response
  • wc = Count of upstream requests that completed (Note: This is not a time, but a count)

To get the total time spent waiting for upstream requests to complete, subtract wp from wt.

Moovweb Proxy Service (MPS)

  • mt = Total time (including mu)
  • mu = Time waiting for upstream (not included if upstream is skipped)
  • mp = Time executing user Tritium project code time (not included if Tritium is not executed)
  • mb = Time waiting for associated BLOB to be fetched (not included if there is no associated BLOB)

Inner Edge Varnish

  • vt = Total time (including vf)
  • vf = Time waiting for upstream
  • vc = Cache action - hit, cached, miss or pass

Inner Edge NGINX

  • nt = Total time waiting for upstream (in seconds)

Outer Edge Varnish

  • ot = Total time (including of)
  • of = Total time waiting for upstream
  • oc = Cache action - hit, cached, miss or pass
  • bd = Time spent on bot detection

Shield Outer Edge Varnish

  • st = Total time (including sf)
  • sf = Total time waiting for upstream
  • sc = Cache action - hit, cached, miss or pass

Common Outer Edge Varnish

  • bf = Total time waiting for inner edge upstream (stands for "backend fetch")

Cache Action

Cache action can be one of the following values:

  • hit - The request checked the cache and found the page. The response was served from the cache.
  • cached - The request checked the cache and did not find the page. The response was served from the upstream and stored in the cache.
  • miss - The request checked the cache and did not find the page. The response was served from the upstream and not stored in the cache. E.g. set-cookie found in response.
  • pass - The request did not check the cache. The response was served from the upstream. e.g. ?moov_debug=true found in request or request was not GET or HEAD.

Additional Notes

The timing stats from Fastly are a .vcl variable %{time.elapsed.usec}V are in microseconds. For cache hits we should not log the metrics at all as they would just skew the data (we would have to exclude all such metrics from composite metrics) and add unnecessary cost to our logging space.

Parser

A small NodeJS program to parse x-moov-t:

#!/usr/bin/env node
const stdin = process.openStdin();
let xmt = '';
stdin.on('data', function(chunk) {
  xmt += chunk;
});
stdin.on('end', function() {
  xmt = xmt.split('\n')[0];
  xmt = xmt.split('\r')[0];
  xmt = xmt.replace(/(< )?x-moov-t\: /ig, '');
  const components = {};
  for (let component of xmt.split(',')) {
    const [key, value] = component.split('=');
    components[key] = value;
  }

  if (components.ot !== undefined) {
    console.log(`Outer edge total time: ${components.ot} ms`);
  }
  if (components.of !== undefined) {
    console.log(`Outer edge total time waiting for upstream: ${components.of} ms`);
  }
  if (components.oc !== undefined) {
    console.log(`Outer edge request was ${getCacheDescription(components.oc)}.`);
  }
  if (components.bd !== undefined) {
    console.log(`Outer edge total time for bot detection: ${getCacheDescription(components.bd)}.`);
  }

  if (components.st !== undefined) {
    console.log(`Shield outer edge total time: ${components.st} ms`);
  }
  if (components.sf !== undefined) {
    console.log(`Shield outer edge total time waiting for upstream: ${components.sf} ms`);
  }
  if (components.sc !== undefined) {
    console.log(`Shield outer edge request was ${getCacheDescription(components.sc)}.`);
  }

  if (components.nt !== undefined) {
    console.log(`Inner edge total time: ${components.nt} ms`);
  }

  if (components.vt !== undefined) {
    console.log(`Inner edge Varnish total time: ${components.vt} ms`);
  }
  if (components.vf !== undefined) {
    console.log(`Inner edge Varnish total time waiting for upstream: ${components.vf} ms`);
  }
  if (components.vc !== undefined) {
    console.log(`Inner edge Varnish request was ${getCacheDescription(components.vc)}.`);
  }

  if (components.mt !== undefined) {
    console.log(`MPS total time: ${components.mt} ms`);
  }
  if (components.mu !== undefined) {
    console.log(`MPS total time waiting for upstream: ${components.mu} ms`);
  }
  if (components.mp !== undefined) {
    console.log(`MPS total time executing Tritium code: ${components.mp} ms`);
  }
  if (components.mb !== undefined) {
    console.log(`MPS total time fetching project BLOB: ${components.mb} ms`);
  }

  if (components.wt !== undefined) {
    console.log(`MoowWorker total time: ${components.wt} ms`);
  }
  if (components.wc !== undefined) {
    console.log(`MoowWorker requests count: ${components.wc}`);
  }
  if (components.wm !== undefined) {
    console.log(`MoowWorker longest upstream request time: ${components.wm} ms`);
  }
  if (components.wp !== undefined) {
    console.log(`MoowWorker total CPU time executing JavaScript code: ${components.wp} ms`);
  }
});

const getCacheDescription = (cacheValue) => {
  switch(cacheValue) {
    case 'hit': return 'a cache hit';
    case 'cached': return 'a cache miss and response was cached';
    case 'miss': return 'a cache miss and response was not cached';
    case 'pass': return 'not cacheable';
  }
};

Example use:

curl https://www.moovweb.com -v -o /dev/null 2>&1 | grep "x-moov-t" | parse-x-moov-t.js