In Async Programming, an Ounce of Opportunism is worth a Pound of Plan

I've recently found myself tackling some moderately complex asynchronous programming projects. This type of programming can, of course, be very error-prone and hard to maintain. The topic of this post is a design pattern which I've developed over the years, which can make asynchronous programming much more tractable. I call this pattern "continuous re-evaluation".

What is continuous re-evaluation good for?

Programming tasks suitable for this design pattern generally involve the following requirements:

• Asynchronous operations (e.g. I/O or RPCs)
• Multiple asynchronous steps, which may overlap
• The choice and timing of the asynchronous operations varies according to external events and the outcome of earlier operations.

These requirements arise frequently; for example, in RPC batching, or joining data from heterogenous servers. Three real-world problems I've had to solve over the years:

1. Document synchronization in the original Writely online document editor. This was the process by which edits were saved to the server, and collaborators' edits brought down to the browser. The task is complex, due to the possibility of simultaneous (and perhaps conflicting) changes; out-of-order message delivery; and the need to balance update speed against server load.

2. Implementing a responsive browser-based photo gallery. The gallery displayed one full-sized image at a time, plus a scrolling list of thumbnails for navigation. It was important to optimize response times for the initial page load, navigation to a new photo, and scrolling the thumbnail list. To implement this, the gallery used a careful prioritization scheme whereby images were prefetched according to the probability that they would soon be needed. The prioritization scheme covered both full-sized images, and thumbnails for use in the scrolling list. Outside events (e.g. the user selecting a different image, or resizing the window) would cause priorities to change on the fly.

3. Data replication in the Megastore data store. A typical transaction commit involves multiple types of RPC, such as Paxos prepare and accept operations, cache ("coordinator") invalidation, database updates, and log cleanup. Often, multiple instances of each RPC type are in flight simultaneously, alongside a variety of time-based triggers. Latency is a critical design parameter, requiring these RPCs to be very carefully orchestrated.

State machines vs. re-evaluation: to plan, or not to plan?

The classic approach to this sort of problem is to model it as a state machine. The machine begins in some initial state in which it initiates one or more asynchronous operations. As these operations complete (or fail), the machine transitions to other states; the transitions may trigger additional operations. The logic for chaining operations together is embedded in the transitions of the state machine.

This textbook approach has an appealing sense of rigor. However, in practice I've rarely found it to work very well. The primary drawback is that designing a state machine leads you to think in terms of an imperative, planned sequence of operations. In a (simplified) version of the Megastore data replication system, that planned sequence might be "create an entry in the write-ahead log; update the coordinator for any replica where the log couldn't be written; update the data tables; clean up the log". Unfortunately, such plans rarely survive contact with reality. There are always error paths, retry loops, and edge case handlers complicating your logic. It may be possible for operations to complete in several different sequences, each of which requires its own chain of state transitions. Your simple, linear plan becomes a tangle of overlapping, contingent plans: hard to write, harder to maintain, sometimes impossible to truly understand.

(State machines have other, more tactical problems as well. They are not directly supported by mainstream programming languages, forcing awkward workarounds. They force all state to be "unrolled" into a single variable, when it might have been better expressed as a collection of orthogonal variables. And, by associating code with each unrolled state, they encourage code duplication.)

In the continuous re-evaluation pattern, we abandon any notion of a plan. Instead, we ask the following question: in any given situation, what is the one thing we should do next? We don't attempt to plan beyond the immediate moment; we simply decide what action to take right now. (The choices are generally "initiate some new asynchronous operation", "set a timer", or "do nothing and await further events".) Whenever any event occurs -- an operation completes, a timer fires, one of our input variables changes, etc. -- we always do the same thing: evaluate the current situation and decide which one action, if any, to take.

I had initially thought of calling this pattern "stateless machines". However, it's not really accurate to call it stateless; any interesting algorithm requires some state to be held somewhere. So I settled on "continuous re-evaluation". In a continuous re-evaluation machine, we do maintain state, but this state does not reflect a plan; it is merely a direct description of the state of the world.

All this is best explained through examples. I'll do that in the next two sections.

Example: RPC failover

A classic case is issuing an RPC to a server pool, with failover. The idea is that any server in the pool can handle the request, and we don't care which one we use, but if our chosen server doesn't respond, we should retry on ("fail over to") another server.

Let's start with a very simple version of the problem. Suppose there are precisely two servers; we send each request to the first server; if a request fails, we resend it to the second server. Here is pseudocode for the state machine approach:

start:
  send_request(servers[0]);        // try server 0 first
  on rpc_succeeded: exit(success); // if the request succeeded, we're done
  on rpc_failed:    goto failover; // otherwise, try server 1

failover:
  send_request(server[1]);         // try server 1
  on rpc_succeeded: exit(success); // if it succeeds, great
  on rpc_failed:    exit(failure); // otherwise, give up

All well and good. However, in the real world, we usually have additional requirements. For example, if the first server doesn't respond quickly, we might want to try the second server in parallel. A simple specification for this is "after 50ms, initiate a request to the second server. Accept whichever response arrives first." Our state machine gets a little more complex now -- we need a timer to trigger the second request, and we need to keep track of whether the timer has triggered yet, and which requests are still in flight:

start:
  send_request(server[0]);
  start_timer(50);                 // kick off a 50ms timer
  on rpc_succeeded: exit(success);
  on rpc_failed:    goto failover;
  on timer:         goto timer;

failover: // server 0 failed, so try server 1 immediately (don't wait 50ms)
  send_request(server[1]);
  goto 0failed;

timer: // try server 1 while still hoping for a response from server 0
  send(server[1]);
  on rpc_succeeded: exit(success);
  on rpc_failed(0): goto 0failed;
  on rpc_failed(1): goto 1failed;

0failed: // server 0 failed; wait for response from server 1
  on rpc_succeeded(1): exit(success);
  on rpc_failed(1):    exit(failure);

1failed: // server 1 failed; wait for response from server 0
  on rpc_succeeded(0): exit(success);
  on rpc_failed(0):    exit(failure);

Now suppose we want to support an arbitrary number of servers, failing over repeatedly from one to the next. A pure state machine approach will no longer work, because information we need to keep track of (which servers have we sent requests to, which ones have responded) is too complex. The usual solution is to keep some state outside of the state machine proper. Suppose that our spec is "always maintain one in-flight request, or two in-flight requests if 50ms have elapsed since our current request was initiated; try each server at most once". We might wind up with something like this:

// Define an array that keeps track of which servers we've sent requests
// to, and the status of each request.  N is the number of servers.
enum Status { untried, pending, succeeded, failed };
Status[] statusArray = new Status[N]{untried};

start:
  goto launchRequest;

// No requests are in flight, we need to launch one.
launchRequest:
  // Choose a not-yet-tried server, and send a request to it.
  int i = <some server for which the status is "untried">;
  statusArray[i] = pending;
  send_request(server[i]);

  // Start a failover timer.
  start_timer(50);

  on rpc_succeeded: exit(success);
  on rpc_failed(j): goto failure(j);
  on timer:         goto timer;

// We had one request in flight, to server j; the request just failed.
failure(j): 
  statusArray[j] = failed;
  if <at least one server has status "untried">
    goto launchRequest; // launch a request to some other server
  goto wait;

// We've sent requests to every server, so now we're just waiting
// for responses.
wait:
  if <no server has status "pending">
    exit(failure);
  on rpc_succeeded: exit(success);
  on rpc_failed(j): goto failure(j);

// We had one request in flight, and our timer fired, so we'll kick off
// a parallel request to another server.
timer:
  if <no server has status "untried">
    goto wait;

  int i = <some server for which the status is "untried">;
  statusArray[i] = pending;
  send_request(server[i]);
  on rpc_succeeded: exit(success);
  on rpc_failed(j): goto parallelFailure(j);

// We had two requests in flight, and one of them (to server j) has
// just failed.
parallelFailure:
  statusArray[j] = failed;

  // Start a timer: if the other request doesn't complete soon,
  // we'll kick off another redundant request.  (Note, technically
  // we should reduce the timer interval by the amount of time since
  // the remaining in-flight request was launched.)
  start_timer(50);

  on rpc_succeeded: exit(success);
  on rpc_failed(j): goto failure(j);
  on timer:         goto timer;

This can be made to work, but it's quite complex, especially when you consider that the problem specification fits in a single sentence. The state machine style is not really helping. For instance, observe how we need different failure handlers for the "one rpc in flight' and "two rpc in flight" states, and how the parallelFailure state is nearly a copy-and-paste of the launchRequest state.

In the continuous re-evaluation style, we discard the state machine, and keep all state in conventional programming variables. The state we do maintain is relatively simple; we do not keep track of what has just changed (e.g. there's no equivalent to the "timer" or "parallelFailure" states), or where we are in some plan (e.g. the "launchRequest" state). We merely record the objective state of the world -- in this example, the status of each RPC we've launched.  Then, we write a single method that is invoked whenever any event occurs (e.g. a timer fires, or a response arrives). That method looks at the state of the world and decides what to do next. You can think of it as a conventional state machine with a single state. The code for our N-server failover logic might look like this:

// Keep track of the requests we've sent, and their status.
enum Status { untried, pending, succeeded, failed };
Status[] statusArray = new Status[N]{untried};

// Also keep track of when each request was sent.
Date[] requestTimes = new Date[N];

start:
  if <all servers have status "failed">
    exit(failure);

  // Make sure we have at least one in-flight request.
  int k = <number of servers with status "pending">;
  if (k < 1)
    sendRequest();

  // If we have only one in-flight request, and it's stale, start
  // another.
  if (k == 1)
    if (requestTimes[statusArray.indexOf(pending)] <= new Date().addMillis(-50))
      sendRequest();

  on rpc_succeeded: exit(success);
  on rpc_failed(j): statusArray[j] = failed; goto start;
  on timer:         goto start;

// If there are any untried servers, choose one and send a request.
function sendRequest() {
  int i = <some server for which the status is "untried", or -1 if none>;
  if (i >= 0) {
    statusArray[i] = pending;
    requestTimes[i] = new Date();
    send_request(server[i]);
    start_timer(50);
  }
}

This is a big improvement on the state machine. Not only is it shorter and easier to follow, its structure directly reflects that of the specification. It should be easy to maintain and adapt this code when the specification changes. As a side bonus, it handles the 50ms retry correctly, unlike the previous version (which waited 50ms after failure, instead of 50ms after the time when the still-outstanding request was sent).

The specification for a real-world, industrial-strength RPC implementation might be considerably more complex than the one I've used so far. For instance, we might want to:

• Allow servers to be added or removed on the fly. (This might by triggered by a manual configuration change, or a monitoring system that removes servers from the list when they appear unhealthy.)
• Allow the caller to specify that K servers be tried in parallel (without waiting for a 50ms staleness threshold to be reached). This would be an option, enabled for latency-sensitive requests.
• Specify a timeout for the overall operation -- after a specified interval, we abandon any in-flight requests and report failure.

With each new feature, the traditional state machine would become that much more convoluted. But for the continuous re-evaluation version, the changes are trivial.

Example: Writely document sync

The problem of document synchronization was mentioned briefly at the beginning of this post. In the original Writely implementation, synchronization occurred through a single RPC method. The browser sent its latest changes (if any) to the server, and the server responded with any fresh changes made by collaborators. The browser would send RPCs even if no changes were occurring locally, as a way of polling for collaborators' changes.

Some of the considerations that went into the decision of when to send a sync RPC:

• If our user has modified the document, we want to sync soon, to avoid data loss and so that any collaborators who are currently online can see the change.
• If a collaborator is modifying the document, we want to sync frequently, so our user can see the changes promptly.
• The acts of sending a request and receiving a response use enough CPU to cause a noticeable hiccup in typing response. So, if the user is actively typing, it's preferable to wait until they pause before syncing. (This might be less of an issue today than it was in 2005, when Writely was originally developed.)
• If a window is inactive, it's less important to sync that window frequently. 
• Syncing too frequently can put excessive load on the server.
• If a sync request fails (e.g. due to server or network problems), we should retry, but not right away.

As a state machine, this would be very complex. We'd need states to keep track of the cross product of <document is modified locally>, <collaborators are online>, <collaborators have made recent edits>, <window is active>, and <last sync request failed>, among other things. We'd need to define state transitions for "user has made an edit", "sync succeeded (with remote changes)", "sync succeeded (without remote changes, but with collaborators present)", "sync succeeded (with no collaborators present)", "sync failed", "window activated", and "window deactivated", and more.

Using the continuous re-evaluation pattern, the problem decomposes much more nicely. We'll need a handful of state variables:

Date timeLastSyncRequestWasSent;
Date timeOfLastLocalChange;
Date timeOfLastRemoteChange;
boolean anyUnsavedChanges;
boolean anyCollaboratorsOnline;
boolean windowIsActive;
int syncFailuresInARow;

Maintaining these state variables is trivial. Then we just need a re-evaluation method:

Date now = new Date();
double timeSinceLastRequest  = now - timeLastSyncRequestWasSent;
double timeSinceLocalChange  = now - timeOfLastLocalChange;
double timeSinceRemoteChange = now - timeOfLastRemoteChange;

// Based on the current state, decide how often we should be syncing.
double timeBetweenSyncs;
if (anyUnsavedChanges || timeSinceRemoteChange < 60)
  timeBetweenSyncs = 10;
else if (anyCollaboratorsOnline)
  timeBetweenSyncs = 30;
else
  timeBetweenSyncs = 60;

if (!windowIsActive)
  timeBetweenSyncs *= 2;

// Back off if we've been getting server errors.
if (syncFailuresInARow > 0) {
  double backoffTime = Math.min(10 * Math.pow(2, syncFailuresInARow), 300);
  timeBetweenSyncs = Math.max(timeBetweenSyncs, backoffTime);
}

// If the last sync request is too old, sync now.
if (timeSinceLastRequest >= timeBetweenSyncs) {
  // But, if the user is actively typing, wait a bit in hopes that
  // they will pause.  Concretely, we sync only if it has been 2 seconds
  // since the last change, or we're at least 10 seconds "overdue" to
  // sync.
  if (timeSinceLocalChange > 2 ||
      timeSinceLastRequest >= timeBetweenSyncs + 10)
    sendSyncRequest();
}

Really not bad at all. As in the RPC failover case, the re-evaluation code directly reflects the original specification. In Writely, I believe we simply invoked this method once per second.

A related problem is when and how to notify the user of sync failures. For failures that may be transient (e.g. request timeout, or "server busy"), we don't necessarily need to bother the user; but we should notify them if there are multiple such failures in a row, especially if the document contains unsaved changes. For permanent failures (e.g. the user's login credentials are no longer valid), we should notify immediately. If failures continue to occur, we should not bombard the user with error messages, but we probably should remind them occasionally that their work is not being saved. The continuous re-evaluation pattern handles all this without difficultly. The state variables would be something like this:

// Number of sync requests which have failed; resets to 0 after each success.
int transientErrorsInARow;

// True if the most recent sync request failed because the user needs
// to log in again.
boolean needLogin;

boolean documentContainsUnsavedChanges;

// Time when we last displayed an error dialog.
Date timeOfLastTransientErrorWarning;
Date timeOfLastNeedLoginWarning;

And the re-evaluation method is straightforward enough that I won't bother spelling it out.

Wrapping up

...not much to wrap up, actually. The continuous re-evaluation pattern has solved many real-world problems for me. I hope it can do the same for you. As always, questions, feedback, or other comments are welcomed.

SLAs Considered Harmful

If you're reading this blog, it's a fairly safe assumption that you've heard about the major Amazon Web Services outage last week.  This incident highlights something I've thought for a long time: SLAs, the traditional tool for describing the robustness of a service provider, are a useless distraction.

Suppose your service is hosted on AWS and was affected by last week's outage.  If I am reading Amazon's SLA correctly, you would probably be eligible for a refund of 10% of your April bill.  Is this supposed to make you feel better?  Go read Heroku's excellent post-mortem writeup.  It's a refreshingly candid assessment of the impact on Heroku's staff and customers, the response required, and the steps they'll be taking to avoid a repeat.  Here are some highlights:

• (Many? Most?) Heroku-based applications were down for 16 to 60 hours.  "In short: this was an absolute disaster... we never want to put our customers, our users, or our engineering team through this again".  This has to be a major black eye for Heroku in the eyes of many of their customers.
• Heroku engineers were working around the clock for days to restore service.  Anyone who has been in a similar situation knows that this takes a major toll on the team; other Heroku projects will be set back significantly.
• As a direct result of this incident, Heroku will be undertaking significant architectural changes, such as spreading data across multiple AWS regions.  This is likely to be a major undertaking, again detracting from other projects.

Does a 0.8% discount on your annual infrastructure bill compensate for this?  Obviously not.  The PR impact alone is probably more than Heroku's entire annual infrastructure costs.

[Note: I do not mean any criticism of Heroku; they were dealing with a major disruption to their underlying infrastructure.  A disruption that was significantly worse because it crossed AWS Availability Zones, something that Amazon implies should not occur, barring large external events.]

So, Amazon's SLA is not strong enough to adequately compensate for the impact of a major outage.  Is the problem unique to Amazon?  Let's look around.  Under the ("proposed draft") SLA for Google's App Engine, I believe this incident would have fallen in the "99.0% - 95.0%" uptime bucket, yielding a 25% credit for the month.  The "Windows Azure Compute Service Level Agreement" (sheesh! Microsoft still pays their writers by the word, I see) also appears to call for a 25% monthly credit.  The Rackspace Cloud SLA is more aggressive; the credit for an incident of this scale could be 100%, depending on exactly how it's interpreted.  However, that's 100% of a single month's infrastructure fees; still small potatoes, compared to an honest evaluation of the overall impact on Heroku.

Suppose there was a hosting provider that provided a full year's worth of credit after an incident like this.  Would that suffice?  It would certainly take some of the sting out of an outage.  But I don't think it's a practical approach.  First of all, it's not clear that even a year's infrastructure credit really compensates for an incident that may infuriate a large swath of your customers.  Second, it's simply too much risk for the hosting provider.  If Rackspace had to refund a year's revenue, it might sink them.  If I'm hosted on Rackspace, having them go out of business after an outage might carry an appealing scent of justice, but it certainly doesn't make my life any easier.

If not SLAs, then what?

If SLAs are hopeless as a mechanism for judging the robustness of a service provider, what are we left with?  Two things: track records and transparency.

The best way of evaluating a service's robustness is by looking at its track record.  If it has been stable for several years, that's a good indication that it will continue to be stable.  Of course, this approach isn't much use for evaluating young services... but that's practically a feature: young services almost always have some kinks to be worked out, so the lack of a track record correctly tells you not to trust them too much.

Proper evaluation of a service's track record takes some care.  Common metrics such as "mean latency" or "uptime percentage" can mask all sorts of problems.  For example, an incident causing latency to spike 5x for 10% of a service's customers for three days might have a huge impact on those customers, yet mean latency for the service as a whole would rise only 5% for that month.  Better would be detailed histograms and percentile measurements of a variety of metrics, over a variety of time scales, and reaching back for a year or more.  I'm not aware of any major hosting provider that publishes such information today.  (http://status.aws.amazon.com/, for instance, provides little more than green/yellow/red icons per service per day, and only goes back 35 days.  http://code.google.com/status/appengine is significantly better -- there are actual graphs, and the data seems to go back fairly far.  But still no percentiles, no histograms, and no ability to roll up data across a long time range.)

Another critical mechanism is transparency -- service providers should explain how their service works under the hood, so that customers can evaluate the likelihood of various scenarios.  Lack of transparency was one of the major problems in the recent AWS outage.  Amazon states that Availability Zones are "engineered to be insulated from failures in other Availability Zones", but it appears that this insulation failed in last week's incident.  Why?  We don't know.  It may be that, if Amazon had published more information about their service architecture, customers like Heroku would have been able to make a more informed decision as to the safety of relying on a single AWS region.

The clearest statement I'm aware of regarding the isolation of Amazon's Availability Zones relates to physical infrastructure: "Each availability zone runs on its own physically distinct, independent infrastructure, and is engineered to be highly reliable. Common points of failures like generators and cooling equipment are not shared across Availability Zones. Additionally, they are physically separate, such that even extremely uncommon disasters such as fires, tornados or flooding would only affect a single Availability Zone."  (Quote from the EC2 FAQ.)  In our modern age of complex multi-tenant services, most outages stem from software bugs, load surges, configuration errors, or other "soft" problems, not hardware failure.  So, merely knowing that Availability Zones have independent hardware doesn't tell us much about the probability of correlated failures.

What can you do?


When evaluating a service or hosting provider, push hard on them to provide you with detailed data on their track record for availability and performance.  Ask them to publish it openly.

Assuming your provider has an SLA, ask them why they believe in it.  How is their service architected?  How does this architecture support the SLA?

Gather as much data as you can regarding the infrastructure you're using, and publish it.  Leaving aside the benefit to the community, you'll be surprised at how much you'll learn about your own systems and how to improve them.  (I've done some work in this regard, which I've blogged about in the past.  If you want to poke around, go to http://amistrongeryet.com/dashboard.jsp.)

A modest proposal

Expanding on the previous point... imagine if a large sampling of AWS customers (and App Engine customers, Rackspace customers, etc.) were to publish latency and error rate statistics.  Imagine further if there were a central repository aggregating and analyzing this data.  We'd no longer be dependent on the hosting services themselves for information.

This would be a nontrivial undertaking, to say the least, but the benefits could be huge.  A topic for a future post.

Rate Limiting in 150 lines, or, Simplicity is Contagious

I recently had occasion to write a rate limiter -- a library that tracks the rate at which some operation is performed, so that excessive bursts of activity can be throttled. I was worried that it would be a big job, but it turned out to be quite simple, largely because I had some good tools to build on. That led to the topic for this post: how good building blocks enable simple designs.

Really, the title should be Complexity is Contagious. If you've ever worked on a large system, you've had the experience of needing a week to implement something that "should have been" trivial. Here's a fictitious, but plausible, example:

You work at a photo sharing service. You want to tweak the search results page to display an author name next to each photo. Simple enough: each photo record includes an author ID, so you just need to look up the ID in the users table and fetch the name column. But... your service supports three login mechanisms (your own native accounts, Facebook login, and Twitter login), so the author ID might refer to any of three different tables. One of those table has separate "first name" and "last name" fields, which you need to concatenate. Unless they're both blank, in which case you use the "e-mail address" field. But you need to check a settings record to see whether the e-mail address is public, and that's in a separate table.

Oh, and each lookup in the users table requires an RPC, so you need to batch the lookups, and run them asynchronously. Sometimes an RPC gets dropped, so you need a timeout. And sometimes a query matches thousands of photos -- you can't fetch all those user records without overloading the database server, so you have to implement a cap. (Only 50 photos are actually shown on the page, but that winnowing happens downstream from your code.)  And the cap needs to be dynamically configurable, so that you can tweak it according to system health.

Bleah. Suddenly, a week for this trivial feature starts to look optimistic.

The key point is that none of the complexity was intrinsic to the feature. It all arises from weaknesses in underlying services. The database abstraction could automatically implement batching and asynchrony, hiding them behind a Future. The same abstraction could provide timeouts and caps. A user-management library could present a uniform interface for the three login mechanisms. And so forth.

Of course, even with a strong foundation, if you choose a bad design for your feature you might still need a week to implement it. But at least a good design would have been possible. Clean infrastructure doesn't ensure simple designs, but it's an enabler. Hence the title of this post. In what follows, I'll outline the task I faced, my solution, and describe the building blocks that allowed the solution to remain simple.

Rate limiting

By rate limiting, I mean a mechanism that rejects operations which occur more frequently than a specified threshold. Rate limiting has many uses; for instance, to prevent a user from occupying an unreasonable share of some server's capacity.

A popular approach to rate limiting is the Leaky Bucket model. In brief, this model allows events to occur at a specified rate, with short-term bursts up to a specified threshold. For instance, "one request per second, with bursts of up to 10 requests". Here's a complete implementation:

public class RateLimiter {
  private final double fillRatePerMs;
  private final double maxBudget;
  private       double currentBudget;
  private       long   lastUpdateTime;
  
  public RateLimiter(double maxBudget, double fillRatePerMs) {
    this.fillRatePerMs  = fillRatePerMs;
    this.maxBudget      = maxBudget;
    this.currentBudget  = maxBudget;
    this.lastUpdateTime = System.currentTimeMillis();
  }
  
  /**
   * Attempt to consume the specified amount of resources.  If the resources
   * are available, consume them and return true; otherwise, consume nothing
   * and return false.
   */
  public boolean consume(double amount) {
    long msSinceLastUpdate = System.currentTimeMillis() - lastUpdateTime;
    currentBudget = Math.min(maxBudget,
        currentBudget + msSinceLastUpdate * fillRatePerMs);
    lastUpdateTime += msSinceLastUpdate;
    
    if (currentBudget >= amount) {
      currentBudget -= amount;
      return true;
    } else {
      return false;
    }
  }
}

That was easy enough, but it's only a start. There are a lot of practical considerations to be addressed:

• Multiple buckets. Suppose you want to limit the request rate from each user. You need a bucket per user.
• Sparse buckets. You have many users, but only a fraction are active at a time. Tracking inactive users would waste memory.
• Multiple request types. Your server handles several different operations, and you need different rate limits for each.
• Configuration. You need a way to specify the request rate and burst size for each request type.
• Dynamic configuration: when dealing with servers under stress, you may need to adjust rate limits without restarting.
• Distributed configuration: configuration settings may need to be distributed to multiple servers.
• Special cases. Perhaps your rate limit is one request / user / second, but you have a few special accounts which represent internal systems, and they need a higher limit. Or perhaps a particular server is behaving oddly, and you need to tweak one of the limits for that server without affecting other servers.
• Monitoring and introspection. To diagnose production problems, you need a way to peek into the state of the rate limiter.

This could easily turn into a major project. In the next section, I'll show how a careful design, and some good building blocks, kept the project simple -- a couple of hours, and about 150 lines of code, including all the details of configuration and introspection. (There are at least two common real-world requirements for rate limiting that I don't discuss here, because they weren't requirements for my application. One is aggregation across servers. The other is persistence -- preserving the state of the rate limiter across server restarts.)

Configuration

I've previously implemented a library, DynamicConfig, for managing configuration parameters. Most usage goes through a single method:

  public static String getString(String name, String defaultValue);

If the configuration file has an entry with the specified name, this method returns its value. Otherwise, it returns defaultValue. This looks simple, but it hides a lot of functionality. If a configuration file is changed, running servers detect the change. The configuration may come from a local file, or a global repository implemented on Amazon S3. Or both -- there's an inheritance mechanism which allows per-server and/or global configuration files to be layered on top of one another.

Using DynamicConfig as a building block, I developed the following design for configuring rate limits. The entry point into the rate limiter looks like this:

  public static boolean consume(String key, double amount);

The "key" parameter identifies a bucket, and the result is true if the specified resources were available in that bucket. The key corresponds to the name of a configuration variable, which is expected to hold the rate limit specification. However, if no such configuration variable exists, we split the key at slash characters, and look for a configuration variable corresponding to a partial key. For instance, if the key was "foo/bar/baz", we'd look for a configuration variable "foo/bar/baz", then for "foo/bar", and finally for "foo".  The configuration variable gives us the parameters (maxBudget and fillRatePerMs) for the leaky bucket algorithm.

By incorporating a user identifier into the key, this gives us per-user buckets, as well as support for custom rate limits by user. Suppose you want to allow 1 request/second from any IP address (with bursts up to 10 requests), but 100 requests/second from 192.168.11.3 (with bursts to 500). Your configuration file might look like this:

  rate_limit: "10, 1/sec"
  rate_limit/192.168.11.3: "500, 100/sec"

For each request, you'd do the following:

  boolean acceptRequest = RateLimiter.consume("rate_limit/" + client_ip, 1.0);

Observe how simple this is. Our new keyed consume() method is quite simple -- it just needs a hashtable to track buckets, and a short loop to probe DynamicConfig with a series of names. This simplicity is enabled by the simplicity of the DynamicConfig API. Some things RateLimiter doesn't have to do:

• Define a configuration schema
• Know where to find configuration files
• Care whether the configuration is local, global, or a hybrid
• Manage a "connection" to the configuration service
• Handle errors accessing the configuration service (these are captured, and reported, by DynamicConfig)

One thing we don't get completely for free is sparse buckets. For long-running servers, we'll need a background task that periodically sweeps the hashtable and discards "full" buckets (those for which currentBudget equals maxBudget). But that complexity, at least, is intrinsic to the problem we're addressing.

Introspection

Another building block I used is called Datasets: a mechanism for exposing server state via a web UI. Any object implementing the following simple interface can be exposed:

public interface Introspectable {
  /**
   * Return a unique, stable identifier for this object.
   */
  public String getId();
  
  /**
   * Return all introspectable fields for this object (possibly excluding
   * fields for which the object has no value).
   */
  public Collection getFieldNames();
  
  /**
   * Return this object's value for the field with the specified name, or
   * null if the field has no value in this object.
   */
  public Object get(String field);
}

In this API, a "field" is anything we want to expose in the introspection UI. For the rate limiter, each bucket is an introspectable object, and a reasonable set of fields is: bucket key, fill rate, current budget, maximum budget, time since last use, and budget fraction (ratio of current budget to maximum budget).

Built on top of this (plus another simple interface to iterate over the set of all objects) is a web UI that allows viewing, filtering, and sorting objects. So, for example, to identify users who are in danger of exceeding the rate limit for message sends, we could say (in the UI): "show all RateLimiter buckets whose key begins with 'message_send_rate_limit', where the budget fraction is less than 50%". Without this building block, introspection support for the rate limiter would be a major subproject in its own right.

Conclusion

The next time you find a simple-seeming task turning complex, ask yourself: where is the complexity coming from?  Is it intrinsic to the feature, a flaw in your design, or is it coming from your building blocks?  If the answer is "building blocks", consider investing time in improving the building blocks, rather than working around them.

The latest xkcd went live as I was writing this -- it seems a fitting place to wrap up:
http://xkcd.com/844/

Practical Web Performance Optimization

In web development nowadays, the importance of minimizing page load times is widely acknowledged.  (See, for instance, http://www.stevesouders.com/blog/2010/05/07/wpo-web-performance-optimization/.)  There are all manner of best practices for reducing load time.  However, many of these practices make day-to-day development more complicated.  In this post, I'll discuss some techniques we're using to reconcile performance with ease of development.

Consider the "primordial" approach to web serving: a site is a collection of files (static resources and/or dynamic templates) sitting in a directory.  JavaScript and CSS code is written in a modular fashion, grouping code into files in whatever organization makes it easiest to locate and manage.  Templating aside, files are served raw, always using the latest copy in the filesystem.  This is quite nice for development:

• You can edit using whatever tools you like.
• Changes are immediately visible in the browser.  No need to restart the server, or invoke any sort of recompilation tool.
• Comments, formatting, and file organization are preserved, making it easy to inspect and debug your JavaScript, CSS, and HTML code.

However, the resulting site is likely to break many rules of web performance.  Notably:

1. Each script module, CSS module, and image requires a separate HTTP request.

2. No CDN (content distribution network) is used -- all requests are served directly from the application server.

3. Content is not cacheable.  (Or, if you do mark some files as cacheable, you'll run into trouble when deploying a new version.)

4. JavaScript, CSS, and HTML code are not minified.

Development mode vs. production mode

The usual approach to this convenience / efficiency tradeoff is to implement two serving modes.  In development mode, the "primordial" model is used.  In production mode, a preprocessing step is used to minify script code, combine scripts, push content to a CDN, and otherwise prepare the site for efficient serving.

This approach can get the job done, but it is a pain to work with.  It's hard to debug problems on the production site, because the code is minified and otherwise rearranged.  It's hard to test performance fixes, because the performance characteristics of development mode are very different than production.  Developers may have to manually invoke the preprocessing step, and problems arise if they fail to do so. Web development is hard enough without this added complexity.

The preprocessing approach is also limited to static content.  For instance, it is difficult to minify dynamic pages with this approach.

Solution: optimize on the fly

In our site, optimizations are applied on the fly, in a servlet filter that postprocesses each response.  (Of course, the server is free to cache the optimized version of static files.)  Current optimizations include:

• Minify JavaScript and CSS files.
• Minify HTML pages, including embedded JavaScript and CSS.
• Rewrite script/style/image URLs to support caching (described below).

Forthcoming extensions:

• Asset bundling
• Rule checking
• Asset repository to avoid version skew (described below)

Because optimization is done on the fly, it is never "stale"; developers don't need to remember to re-run the optimizer.  At least as important, it can be enabled or disabled on the fly.  When investigating a problem on the production site, a developer can disable minification and debug the code directly.  Or they can turn on minification in a development build and observe the effects.

Optimization is enabled and disabled using a simple configuration system we've built.  Configuration flags can be specified at the server, session, or request level.  The session mechanism is particularly convenient: simply by invoking a special form, a developer can disable minification for themselves on the production server, without affecting the way content is served to other users.  And toggling minification in a development build doesn't require a server restart.

URL rewriting for cacheability and CDNs

For performance, it's critical to allow browsers to cache asset files (e.g. images and scripts).  However, this causes problems when those files are updated.  The best solution I'm aware of is to change the filename whenever an asset is modified.  This allows you to mark the files as permanently cacheable.  However, it's a hassle to implement: whenever you modify a file, you have to update all links referencing it.

Our servlet filter scans HTML content for asset references (e.g. <script src=...> or <img src=...>).  For any such reference, if the reference refers to a static file in our site, the filter rewrites the reference to include a fingerprint of the file contents.  Thus, references automatically adjust when an asset file is changed.

When our server receives a request for an asset file, it looks for a fingerprint in the filename.  If the fingerprint is present, we set the response headers to allow indefinite caching.  Otherwise, we mark the response as noncacheable.

When we adopt a CDN, we'll use this same mechanism to rewrite asset references to point to the CDN.

One issue we haven't yet tackled is rewriting asset references that appear in JavaScript code.  Fortunately, the mechanism is failsafe: if our filter doesn't rewrite a reference, that asset will be served as noncacheable.

File bundling

A page often references many asset files.  Performance can be improved by bundling these into a smaller number of larger files.  For JavaScript and CSS files, this is fairly straightforward; for images, it requires CSS sprites.  In both cases, we run into another tradeoff between convenience and performance -- development is easier with unbundled files.

Once again, on-the-fly rewriting comes to the rescue.  When the servlet filter sees multiple <script> or <style> references in a row, it can substitute a single reference to a bundled file.  When it seems multiple CSS image references, it can substitute references to a single sprite image.  The configuration system can be used to toggle this on a server, session, or request level.

Rule checking

Some web performance rules require nonlocal changes to a page or site.  For instance (from http://developer.yahoo.com/performance/rules.html):

• Put stylesheets at the top
• Put scripts at the bottom
• Avoid CSS expressions

Over time, we might extend our servlet filter to implement some of these optimizations by rewriting the response.  But in the meantime, it is relatively straightforward for the filter to detect and report violations.  It is easier to perform this detection at runtime than in a static lint tool, because we can observe the final, post-template-engine version of the page.  And unlike tools like YSlow, we don't have to manually test each release of the site.

Consistency across server updates

When you push a new version of your site to the production server, a "version skew" problem can occur.  Suppose a user opens a page just before the new version is activated.  They might wind up receiving the old version of the page, but the new version of the scripts.  This can cause script errors.  If your site is distributed across multiple servers, the window of vulnerability can be many minutes (depending on your push process).  This is not a performance issue, but it involves references from a page to its assets, so it ties into the mechanisms involved in asset caching.

Happily, the URL rewriting technique described in earlier offers a solution to version skew.  When a server receives a request for an asset file, it simply serves the file version that matches the fingerprint in the URL.  This ensures that all asset files come from the same site version as the main page.

This solution does assume that all servers have access to all versions of the site.  This can be addressed by copying asset files to a central repository, such as Amazon S3, during the push process.

Conclusion


A surprisingly large number of web performance optimization rules can be implemented with little or no impact on day-to-day site development.  Equally important, optimizations can be implemented with session-based disable flags, allowing problems to be debugged directly on the production site.  We've been using this approach in our site development, with good results so far.

Practical XSS defense

This blog has been quiet lately.  I've been working on the nuts and bolts of what we^[1] hope will eventually be a major web site, and that hasn't lent itself to the sort of material I want here.  I'm trying to post only when I have something at least mildly novel and meaty to talk about -- as opposed to, say, photos from my three-day trip to the land of Tomcat configuration.  We're starting to get past the boilerplate into more interesting work, so I hope to start posting more often again.

One thing I set out to tackle this week is XSS defense.  Traditionally, it's a tedious and error-prone task.  In this post, I'll present an attempt to improve on this.

Wikipedia provides a good introduction to the subject.  As a brief refresher, XSS (Cross-Site Scripting) is an attack where a malicious user enters deliberately malformed data into your system.  If your site is not properly protected, it may display that data on a web page in such a way that the browser interprets it as JavaScript code, allowing the attacker to take control of the browser of any victim who views the page.

Escaping

There are a variety of defenses against XSS.  The most common is escaping -- transforming the data in such a way that the browser will not interpret it as code.  For instance, when including a user-supplied value in a web page, characters like "<" and "&" should be rewritten as HTML entities -- "&lt;" and "&amp;".  Old hat, probably, to most of you reading this.

Escaping, if done correctly, is a solid defense against XSS.  However, getting it right is notoriously difficult.  You must apply the escaping in every single place where your code inserts user-supplied data into a web page.  That can easily be thousands of locations.  Miss a single one, and your site is vulnerable.  It's sometimes necessary to perform the encoding at different levels in the code, making it hard to keep track of which strings have already been encoded.  Worse yet, different sorts of encoding are needed depending on context: HTML entity encoding, URL encoding, backslash encoding, etc.  I've even seen cases where two levels of encoding were needed -- for instance, when a value is included in a JavaScript string literal, and the JavaScript code later places that string in the innerHtml of some DOM node.  If you get the encoding wrong, you may again be vulnerable.

Escaping also tends to uglify your code.  In JSP, <%= username %> might have to become <%= Escaper.entityEncode(userName) %>.  The impact on code readability and maintainability is nontrivial.  Some templating systems handle this better than others; we're using plain 'ol JSP, which offers no special support.  So, we weren't very enthusiastic about this approach.

Validation and filtering

Another well-known defense is to validate and/or filter your input: disallow users from entering special characters like <, or filter out those characters.  If these characters never enter your system, you don't have to worry about escaping them at output time.

Most web sites have fewer inputs than outputs, so airtight input filtering is easier to achieve than airtight output escaping.  Also, a single filter can render data safe for inclusion in a variety of contexts, unlike output escaping where you have to be careful to use the correct escaping mode according to context.  (Though this requires a broadminded definition of "special characters" -- see this link for a discussion.)

Input filtering does have some drawbacks.  Most notably, it is visible to users.  Some dangerous characters, like ' and &, appear frequently in ordinary situations, and users will be annoyed if they can't use them.  For this reason, filtering is most commonly used for specific data types, such phone numbers, rather than free-form text such as a message subject.

Another drawback of input filtering is that, if you find a bug in your input filter, you have to re-validate all existing data.  That can be a huge burden in practice, especially if you're under time pressure to close a security hole.  With output escaping, as soon as you fix the bug and push a new build, you're protected.

Design criteria

We're building an actual web site; rubber is meeting road.  Theory aside, we need a concrete plan for XSS defense.  Ideally, the solution would satisfy the following criteria:

• Easy to use -- no complex rules to be remembered while coding.
• Minimal impact on code readability and maintainability.
• Works with JSP (our current templating system), and portable to other templating systems.
• Little or no user-visible impact.
• Auditability -- it should be possible to scan the code with an automated tool and identify any possible XSS holes.
• Defense in depth -- multiple, independent / redundant mechanisms preventing XSS exploits.

Also, I'd like a pony.  (Well, not really.  One of these, maybe.)  Output escaping fails on ease of use, and is difficult to audit; input filtering fails on user impact, and by itself does not provide defense in depth.  Time to get creative.

Input transformation

Again, one problem with input filtering is that it can cause serious annoyance to users.  As noted in one of the pages linked above, imagine poor Mr. O'Malley's frustration when he can't type the ' in his name.

What if, instead of forbidding dangerous characters, we replace them with safer substitutes?  The most common offender, the single quote, has a very acceptable substitute -- the curved single quotes, ‘ and ’.  When we process a form submission, we could perform this substitution automatically.  Mr. O'Malley might not even notice that he's now Mr. O’Malley, and if he did notice, he probably wouldn’t mind.

This appeals to me.  The main objection to input filtering is the impact on users, and this mitigates that impact.  The impact is not eliminated completely, so this won't work in all situations.  But in our application, it should be usable for almost all inputs.

The mapping I'm currently envisioning is as follows:

  '  ->  ‘ or ’ (depending on context)

  "  ->  “ or ” (depending on context)

  <  ->  (

  >  ->  )

  &  ->  +

  \  ->  /

This isn't sufficient in every situation.  For instance, URLs need a different input transformation -- the mapping above will break some URLs, and doesn't rule out "javascript:" or other dangerous links.  And no reasonable input transformation will suffice if you include user-supplied values in an unquoted tag attribute -- quoting is essential.  But if you're good about quoting, this transformation suffices for most common situations.  And it scores pretty well on my "I want a pony" design criteria:

• Ease of use: simply replace every instance of request.getParameter("name") with something like XssUtil.getSafe(request, "name").  (With exceptions only for those unusual cases where the transformation is not acceptable.)
• Impact on code readability: the new form is not especially bulkier than the old.
• Template compatibility: input transformation has no impact on the templating system.
• Auditability: it's easy to grep your codebase for unprotected calls to getParameter.

That leaves only user impact, which I've discussed; and defense in depth.  Defense in depth brings me to my next topic.

Script tagging

Most approaches to XSS defense involve enumerating, and protecting, every spot on a page where scripts might creep in.  The idea is for the page to be "clean" as it emerges from the templating system.  As we've seen above, that's difficult.

Instead, let's accept that a malicious script might sneak into the generated page.  If we have a whitelist of places where scripts are supposed to appear, we could filter out any unwanted ones.  This would work as follows:

1. Tag all "good" scripts -- scripts that we're deliberately including in the page -- with a special marker.  In JSP, the coding idiom might be something like this:

  <script language=javascript>

    <%= scriptToken() %>

    ...regular JavaScript code here...

  </script>

It's important that an attacker not be able to guess the special marker.  This is easily ensured by generating a random marker for each request.

2. After the templating system executes, run the generated page through an HTML parser to identify all scripts on the page.  (For this to be robust, we'll actually need an HTML "cleaner" that rewrites the page in a way that all browsers can be trusted to parse properly.)  Here, "all scripts" means all constructs that could trigger undesired actions in the browser: <script> tags, <style> tags, onclick handlers, URLs with protocols other than http/https/mailto, etc.  Like any HTML cleaner, the system should be based on a whitelist -- any tag or attribute not in the whitelist is considered dangerous.

3. Whenever we see a script with the special marker, remove the marker and leave the script alone.  If we see any scripts without the marker, strip them out, and flag the page for manual inspection.

I don't recall seeing this approach suggested before, but at first blush it seems sound to me.  Of course, browsers are complicated beasts, and I may be missing something.  If you can poke a hole, please let me know!

This approach does impose processing overhead, to parse each generated page.  However, cycles are cheap nowadays; security holes are expensive, as is programmer time.  Also, the same processing pass can perform other useful functions, such as HTML minification.  How does the approach stack up on my design criteria?

• Easy of use: pretty good.  It only requires adding a bit of boilerplate at the beginning of every script block; in practice, it might look something like <%= scriptToken() %>.
• Code impact: the token is not a big deal for a script block.  It will be more annoying in something small like an onclick handler.
• Template compatibility: inserting a token should be easy in any templating system.
• User impact: none.
• Auditability: excellent.  Runtime reporting of marker-less scripts makes the system self-auditing.
• Defense in depth: this approach is completely independent of input transformation, so combining the two achieves a layered defense.  It could also be combined with traditional output escaping.

Conclusions

The combination of input transformation and script tagging yields a layered, auditable defense against XSS attacks, with less programming burden than traditional output escaping.  Output escaping will still be needed in a few places where input transformation is impractical, such as when embedding a user-supplied value in a URL.

If there is interest, I might take the time to open-source this code once when it's completed.

Notes

[1] My old partners in crime from Writely, Sam Schillace and Claudia Carpenter

Three-month review

On a whim, this afternoon I decided to take a look at the long-term graphs for some of my benchmarks.  Most of them now have at least three month's worth of data, and I was curious to see whether there have been changes over time.

Most of the graphs look pretty uneventful.  This computational benchmark from EC2 (measuring Math.sin) is typical:

Basically unchanged.  (The early blip in median latency might be a statistical artifact: the histogram shows a large peak around 130ns, and a smaller peak at 250ns; perhaps the large peak comprises more or less precisely half of the samples, so as it wanders from 49% to 51%, the median could flit back and forth between the two peaks..)

The Math.sin benchmark running on App Engine shows a little more variation:

This presumably follows from the fact that App Engine allows clients to share a CPU.

Shared storage services show much more variation.  Here is the latency to read a single record from an Amazon SimpleDB database (without consistency):

Here's the same graph, with the vertical scale capped at 100ns to make the lower percentiles more visible:

The lower percentiles look steadier, as one might expect -- intermittent issues are likely to be fringe issues, and thus to disproportionately affect the higher percentiles.

App Engine Datastore read and write latencies wander around in a similar manner -- here's the graph for (non-transactional) reads:

EBS read and write latencies are comparatively stable, with some variation at the 99th percentile.  EC2 local-disk latencies are even more stable.  Amazon RDS latency is another story -- look at this graph for reads (of a single record from a pool of 1M records):

There have been a couple of distinct improvements in 99th percentile latency. Expanding the Y axis shows more detail for the 90th percentile:

It has wandered around, though it improved sharply a few weeks ago along with the 99th percentile, and has been quite steady since then.  Further expansion (not shown here) reveals the median and 10th percentile latencies to have been rock-solid all along.

Here is the graph to write one record to RDS:

Again we see a sharp improvement around July 9th.  Zooming in shows that the 10th percentile and median values have actually gotten worse over time:

While RDS read latencies have improved substantially, the bizarre 6-hour cycle is still present.  This graph, showing a couple of days on either side of the July 9th improvement, makes that clear:

(Note, in this graph the Y axis has been clipped at 300ms; many of the peaks are actually as high as 750ms.)

Of course, I have no way of knowing what caused any of these variations.  I haven't gone near these servers in quite some time, so the RDS latency improvements in June and July can't be anything I did.  Just another reminder that you can't take the performance of a shared service for granted.  I did receive a communication in late June from AWS support that "we are currently working on adjustments that would reduce latency in the db.m1.small instances"; this may explain the drop on July 9th.

I'll revisit this topic every few months.  Until then, back to the logging project...

Instrumentation: what's going on in that server?

As part of their investigation into the RDS latency anomaly, Amazon asked me for a log of RDS request latencies.  Despite the fact that the entire purpose of the benchmark program is to measure, record, and analyze request latencies, there was no way to obtain an explicit log.  I had to modify the program and push a new build.

This spurred me to think more systematically about my approach to data gathering.  When developing and maintaining any sort of online service, it's important to be able to analyze the past and present behavior of your servers.  The primary tool for this purpose is usually some sort of server log (e.g. stdout or syslog), though many other tools are used as well.  In this post, I'll use the generic term "instrumentation" to cover all mechanisms that enable inspection of the past behavior of a server system.

The questions one might have about a system's behavior are virtually unbounded, and a plethora of instrumentation mechanisms have been invented to answer them.  Too many, really: real-world systems often use a hodgepodge of instrumentation mechanisms.  This is difficult to learn and use, and yields only patchwork functionality.  In this post, I look for a more organized approach.

How do we use instrumentation?

What sorts of questions might one want to answer using server instrumentation?  It's a broad space.  Here are some representative examples:

Why was that slow?  You've loaded a page from your own service, and you notice that it took several seconds to appear.  It's supposed to be faster.  What went wrong?  Where was the time spent?  Note that you might not know, a priori, specifically which server handled your request.  Also note that the request might have invoked nested requests (e.g. to a database server); if the nested requests were slow, you might have to look into the database server to understand the problem.

Why didn't that work?  A user reports that they got an error message while using your site.  They don't remember the details, but they can tell you their account name, and roughly when the error occurred.  What happened exactly?  You'd like to dig up the request that triggered the error, error details (e.g. stack crawl, relevant parameters and server state), and the user's interaction history leading up to the error.  Again, you might not know which specific server was involved, and the error might have bubbled up from a deeper server tier.

Are my servers healthy right now?  What is the average request latency?  Are we serving [m]any errors?  For a variety of server metrics, are the current values in line with past behavior?

I just tweaked something, what was the impact?  How did server metrics change when the tweak was made?  Any speedup or slowdown?  Are any new errors occurring?

What is this user's history on the site?  Perhaps you've noticed what looks like suspicious behavior from a particular user -- you suspect they may be a spammer.  How have they been using your service?

What is this server up to?  Suppose CPU usage spikes on one of your servers.  What is that server up to -- what operations is it performing, is there any unusual activity?

How many unique daily users does my site have?  This leads into more complex "analytics" questions -- breakdown of visitors by geographic region, referral source, trajectory through the site, etc.

Which records were modified by module X during a certain time period?  You might need to know this to clean up after a bug.

On what occasions has a certain operation been performed, and how long did it take on each occasion -- the question Amazon asked me about RDS requests.

Why instrumentation is needed

Logging, event counters, and other "historical record" instrumentation mechanisms are not the only tools for understanding the behavior of a software system.  There are also debuggers, black-box monitoring, scripted tests, and many other approaches.  However, proactively recording the internal behavior of live production servers can often be invaluable:

• It allows you to investigate problems that you can't reproduce.  ("This user says X happened to her yesterday morning.")
• Corollary: for problems that you can reproduce, it can save you the often-considerable hassle of reproducing them.
• It allows you to investigate problems that only arise in the live production environment.  ("Performance degrades every day during the morning traffic peak.  Our artificial load generator doesn't reproduce the pattern.")
• It allows you to detect patterns over time.  ("The site seems slower lately... has something changed?")

Instrument everything

Given that you are going to instrument your program, what should you instrument?  Which events are worth logging?  Which variables should be recorded?  It's hard to know in advance.  If you instrument too much, you will have a flood of data that may be hard to interpret, and you may even overload some server resource such as disk bandwidth.  If you instrument too little, you may not get the information you need.

We have at least two tools available to avoid this dilemma.  One is configurable instrumentation -- the ability to dynamically disable some instrumentation points at runtime, perhaps via a configuration file.  (Configurable "logging levels" -- e.g. discard all log messages at FINE and below -- are a simple example of this.)  If you liberally instrument your program, configurable instrumentation allows you to throttle the output down to a manageable level, while retaining the ability to enable detailed output on a moment's notice.

The second tool is temporal winnowing -- retain detailed data for a short period, then thin it out.  You might retain FINER logging in RAM for 100 seconds, FINE on local disk for a day, and INFO in a central repository for a month.  This provides detailed information for the recent past (the period you're most often interested in), while minimizing overall storage costs.

It's also worth recalling that disks have gotten very cheap.  Suppose we allow ourselves 1MB/sec of (moderately) compressed log output.  That allows for a lot of logging per request, even on a server handling hundreds or thousands of requests per second.  And yet retaining that output for a week requires only 600GB of disk space -- a fraction of a single modern hard disk.  So: "when in doubt, write it out".

A unified data model

To answer the sorts of questions mentioned above, we need several kinds of information:

1. Traditional logging -- a textual record of events of interest.
2. Rate counters -- how often do various events occur?
3. Latency measurements -- how long does each operation of interest take to complete?
4. Latency breakdowns -- how does the time spent in an operation break down into sub-operations?
5. Time-varying values -- what is the history of, say, heap size or CPU utilization?

Here is an attempt to unify these under a single mechanism.  I use the traditional logging model as my starting point; it's simple, easy to understand, and has stood the test of time.  Imagine that we are writing a servlet to display some sort of dynamic content.  We can sprinkle in a few log calls (using a hypothetical "Log" class whose precise API I leave unspecified):

  Log.info("rendering item % on behalf of user %", itemId, userId);
  if (...) {
     Log.fine("case 1; % subrecords", count);
     ...
  } else {

     Log.fine("case 2; % subrecords", count);

     ...

  }

  Log.fine("finished rendering item");

Nothing novel here.  Clearly this provides our first category of information -- a textual log of events of interest.  With a little pattern matching, we can get rate counters as well.  For instance, to determine the number of item pages that have been displayed, we can count the number of log messages that begin with "rendering item".  (If this is too fragile for your taste, you could adopt the convention of beginning each log message with a stable identifier -- Log.info("pages/render/item % on behalf of user %", itemId, userId)).

For latency measurements, we need to identify the start and end of an operation of interest.  This can be done by indicating which Log calls mark an operation start or end.  Here's the same code fragment again, with two slight tweaks (highlighted in bold):

  Log.startInfo("rendering item % on behalf of user %", itemId, userId);

  ...

  if (...) {

     Log.fine("case 1; % subrecords", count);

     ...

  } else {

     Log.fine("case 2; % subrecords", count);

     ...

  }

  Log.endFine();

The log calls at the start and end of the render operation have been explicitly identified.  (This naming convention -- "startInfo" and so forth -- is clumsy, especially when the start and end are logged at different severity levels.  For an actual implementation, I would try to come up with something better.  I've also glossed over many other details, such as what happens if an exception is thrown between the start and end calls.)  And the message text has been omitted for the "end" call, as the Log class now has enough information to generate an appropriate message automatically.  The output from this code might look something like the following:

  05:01:37.109 rendering item 8461 on behalf of user 196584
  05:01:37.110 | case 1; 9 subrecords
  05:01:37.254 | [completed in 0.145 seconds]

If Log.startXXX / Log.endXXX calls are nested, we can easily extract the fourth data category, hierarchical latency breakdowns.  (That leads to the interesting question of how to track sub-operations that execute on a different thread, or even in a different server; Google's Dapper project shows an approach.)

Finally, we have time-varying values.  These can be recorded by periodically emitting them into the log:

  Log.info("free memory currently %", Runtime.freeMemory());

The history can then be obtained using a simple pattern match.  Again, for more reliably pattern matching, we could use a stable identifier instead of the prose string "free memory currently".

This unified "everything in the log" approach provides many benefits.  For instance:

• A single Log call enables multiple forms of analysis -- you get traditional logging, rate counting, and latency graphing with a single hook.
• There's only one instrumentation system to learn and deploy.
• "Joins" become possible (e.g. graph the latency of operation X, considering only invocations made during requests from user Y).
• The log becomes comprehensive; you can see all available data in one place, rather than jumping around between different instrumentation systems.

Infrastructure requirements

To answer questions about system behavior using nothing more than log output would require significant infrastructure.  Logs would need to be stored, rotated, cataloged, summarized or indexed, and analyzed in fairly sophisticated ways.  In effect, I'm proposing a data warehousing approach to log management (despite knowing nothing about the field of data warehousing).  I'll dive into this in a later post.

Though the infrastructure required to support this approach is significant, it is important not to let the infrastructure drive the overall design.  The infrastructure only has to be written once, but it will be used every day.  This "use" falls into two categories:

1. Instrumenting a program -- adding Log calls while writing code.
2. Analyzing a system -- pulling up logs and graphs to understand what's going on.

The primary goal should be to make these two activities as cheap and easy as possible; let the infrastructure bend itself toward that goal.

Existing work?

There must be literature about logging and system forensics, but I'm not especially familiar with it.  If you're reading this and you can point me to any interesting papers, I'd love to see them.  (You can comment on this post, or e-mail me at steve at snewman.net.)  I'm especially interested in unified approaches to system instrumentation (encompassing logging, performance measurement, etc.), and real-world solutions for multi-server systems.