Just Friday, the week before, I was speaking to Buck about the incident we had the previous week and expressing a strong desire to avoid another incident anytime soon.  We agreed to postpone the VS Online deployment so that we didn’t have to rush it in a short holiday week and we could ensure that everyone needed was on hand in case something went wrong. Then I woke up Monday morning to see that we were in the middle of an incident.  It started at 7:00 UTC (11:06 Sunday night, PST).  By the time I got online at about 11:30 UTC, the team had been engaged for hours and were working diligently on it. Ultimately, the issue was fully resolved by 14:41 UTC (with partial mitigations in the preceding hour or two). I’m sorry for the pain it caused – particularly in Europe and regions in a similar time zone, as it affected them most of the day on Monday.  Every single incident that we have is carefully scrutinized so that we can learn from it and make the product better and more reliable.

What happened?

The primary issue was caused by an update made to SQL Azure.  The change was described as follows:

Included in the SQL Azure November update was an enhancement to SQL Server telemetry to track SQL exception stats at a per-DB granularity.  This enhancement enables SQL Azure to perform automated repair actions on a per database basis.  This deployment completed in SQL Azure’s first GeoRegion before an issue was detected by the VS Online CRI.  The core issue is lock contention on a per-DB hash table tracking exception stats.  Only customers with very high exception stat rates on a single DB were impacted.  Deployment to the second GeoRegion was halted and rolled back while the issue was investigated.

As best they can tell, we were the only database in all of SQL Azure that was affected; certainly the only one affected significantly. VS Online has a stored procedure (prc_ReadGroupMembership) that uses IGNORE_DUP_KEY to suppress duplicate record errors.  Based on telemetry this stored procedure was generating 170,000 exceptions per minute.  The change to SQL Server telemetry did not account for a high rate of “errors” that were intended to be ignored and trying to keep track of them all created lock contention that consumed all worker threads causing SQL processing to effectively stop on a key VS Online database. Unfortunately, it took longer to identify and repair than it should have.  The good news is, according to standard practice, the new behavior was coded behind a feature flag.  So, once we identified the cause, it was easy to mitigate by disabling the feature flag on our database. Even more unfortunately, once we cleared that issue at 5:44 UTC, we immediately hit a second issue (that took the remaining hour of the incident to resolve).  The second issue was lock contention on a particular table in our database.  We have no reason to believe that any SQL Azure change caused it.  It turned out to be an unwise choice of a MERGE statement.  The scenario was updating a table to include all of the rows from a second table that didn’t already exist in the first table.  The key is that it was inserts only, no row updates.  Given that, it turns out to be WAY more efficient to use an INSERT statement like the one below rather than a MERGE statement.  We believe that the fail-over we attempted to mitigate the first issue caused a worse than usual query plan for  this MERGE statement causing it to cascade into a serious lock contention problem.   Regardless, that problem is now permanently fixed.  We’ve also updated the SQL online documentation for MERGE to encourage people to use INSERT in this scenario rather than MERGE.

INSERT tbl_A (col, col2)

SELECT col, col2

FROM tbl_B

WHERE NOT EXISTS (SELECT col FROM tbl_A A2 WHERE A2.col = tbl_B.col);

You’ll also notice at 6:11, in the table below, the stored procedure causing the second incident (prc_ProvisionAttributesUpsert) was manually updated to be a no-op.  This disabled VS roaming settings but enabled all other function on the service to come back to life.  This was, in essence, a manual circuit breaker.

Timeline

In the interest thanks full disclosure, here’s the raw incident log recording events and actions taken.

Learnings

There were a number of things that should have gone better here. VS Online needs to be more resilient to failures – I’ve mentioned this one in previous outages.  This is an area we’ve been working on but the work is not complete.

• We still have one global service (SPS – Shared Platform Services) that needs to be decomposed into smaller services and redundancy provided.  All other services are already multi-instanced.
• We’re part way  through implementing a circuit breaker pattern through our codebase but still have a fair amount of work to do to complete it.
• We need to improve mitigation controls to be able to more effectively, in a live site incident, shut down fractions of traffic while we fix underlying problems.  Being down 30% is better than being down 100%.
• We need to do a better job tracking metrics (like SQL I/Os) over time and looking for bad query patterns like table scans.  These are things that are often transparent until the data size gets too large and then cause sudden cascading failures.

Handle new code changes better – There are numerous ways we could have rolled this change out better.

• Clearly the engineering team missed a use case where there are valid scenarios for very high exception rates.  But, I don’t think this is the most important issue – there’s no way to stop all bugs from getting through.
• We need to roll out new changes in a more controlled fashion.  I’ve been suggesting for a couple of years now that we have an Azure wide canary instance.  Today each service has their own canary and, as a result, there’s no single place that all code changes across Azure can be tested against all services in a controlled fashion.  I’ve reopened the conversation on doing this.
• We need to provide better documentation for changes.  The operations team did not know what this new SE_REPL_EXCEPTION_STATS meant and that it was the result of a new code change.  Due to this, time was lost exploring “standard” performance issue mitigations – like failing over to alternate nodes.  Those mitigations, of course, had no effect.
• Once the change was identified as the culprit and we knew there was a feature flag, it took approximately 45 minutes to figure out how to turn it off due to tooling issues and lack of documentation.

Improvements in incident response

• It took 66 minutes to get ahold of an engineer that understood the malfunctioning code.  Granted it was the middle of the night but our expectation is 15 minutes.
• We should always check the change logs on affected clusters.  Time was wasted on “standard” mitigations before the team realized that a deployment had happened on that cluster hours before the incident.

Summary

It was a 7.5 hour incident.  I’m sorry it was so long.  I’m sorry it followed so closely on last week’s incident.  That’s not normal – usually we go months with no significant incident and I hope to get to more than a year.  All told it was probably 3-4 hours longer than it had to be due to inefficiencies.

• We’ve got work to do on VS Online resilience – that work is under way.  It will take many months to complete all of it but I hope to have significant improvements in the next few months.
• We’ve got work to do on better coordination of rollouts across our services.
• We’ve got some things to improve in how we manage live site incidents.

We’re going to work hard to ensure this is the beginning of another many month, incident free, stretch.  Thank you for your patience.

Brian