"Too many operations in progress" in FrontJsonFapi fetching

[rtyley]

There have been several recent incidents (13/07/23: retro, timeline)where the serving of fronts (eg https://www.theguardian.com/uk) to users became slow, and in fact failed.

There's a lot of things going on in these incidents, but in particular we do see these TooManyOperationsInProgress errors in the logs:

Failed rendering world with concurrent.FutureSemaphore$TooManyOperationsInProgress: Too many operations in progress, 
cannot execute task
concurrent.FutureSemaphore$TooManyOperationsInProgress: Too many operations in progress, cannot execute task
	at concurrent.FutureSemaphore.execute(FutureSemaphore.scala:16)
	at services.fronts.FrontJsonFapi.parsePressedPage(FrontJsonFapi.scala:34)
	at services.fronts.FrontJsonFapi.$anonfun$pressedPageFromS3$2(FrontJsonFapi.scala:58)

The code in FrontJsonFapi where this issue is occurring is interesting, because it has two implementation details that are worth revisiting: it's non-async, and it uses a semaphore to put a hard limit on how many operations can occur concurrently.

frontend/common/app/services/fronts/FrontJsonFapi.scala

Lines 31 to 60 in 3ad37c6

	private def parsePressedPage(
	jsonStringOpt: Option[String],
	)(implicit executionContext: ExecutionContext): Future[Option[PressedPage]] =
	futureSemaphore.execute {
	blockingOperations.executeBlocking {
	jsonStringOpt.map { jsonString =>
	DurationMetric.withMetrics(FaciaPressMetrics.FrontDecodingLatency) {
	// This operation is run in the thread pool since it is very CPU intensive
	Json.parse(jsonString).as[PressedPage]
	}
	}
	}
	}
	private def loadPressedPageFromS3(path: String) =
	blockingOperations.executeBlocking {
	DurationMetric.withMetrics(FaciaPressMetrics.FrontDownloadLatency) {
	S3.getGzipped(path)
	}
	}
	private def pressedPageFromS3(
	path: String,
	)(implicit executionContext: ExecutionContext): Future[Option[PressedPage]] =
	errorLoggingF(s"FrontJsonFapi.pressedPageFromS3 $path") {
	for {
	s3FrontData <- loadPressedPageFromS3(path)
	pressedPage <- parsePressedPage(s3FrontData)
	} yield pressedPage
	}

• Limit the number of parallel facia presses #18331 - 27th November 2017 : introduced futureSemaphore, limiting the number of concurrent operations to 10 per server
• Remove s3 WSClient. Replace with S3 API #18359 - 30th November 2017 : introduced the use of blockingOperations.executeBlocking to FrontJsonFapi - non-async, thread-blocking code

[rtyley]

We've had 2 TooManyOperationsInProgress outages recently (ELK logs):

• 13th July : 12:35 - 12:55 (20 minutes) - 49662 errors (peaking at 5133 requests per minute) over just 356 paths Initially there were 3 facia app-servers running (this was immediately after a deploy, facia scaled up to 12 across the course of the outage)

• 19th July : 9:35 - 9:57 (22 minutes) - 58577 errors (peaking at 4618 requests per minute)

I've exported the data for these outages out of the ELK, just trying to understand what paths are being requested

The rate of 5133 errors per minute is really high, given that fronts have a CDN cache time of 1 minute, and that only 356 different paths were being requested (or at least erroring) in the outage - the number of requests is 5133/356 = 14 times what an optimal request rate would be. In other words, if requests had been succeeding, and getting cached, there would have been 14x less traffic - but they were failing, being throttled by futureSemaphore.

parsePressedPage() takes 140ms when it's healthy, meaning the upper limit on a single healthy app server with the futureSemaphore 32-concurrent-actions limit is 13,700 per minute. During the outage, parsePressedPage() took 1937ms as it contested CPU with GC, giving an upper limit of 990 per minute - well below the incoming request rate - it couldn't catch up without 6 app servers running at the very least.

[rtyley]

I described a possible failure mode for Facia here: #26336 (comment) - basically, futureSemaphore would throw away 'download' work already done (ie downloading entire S3 files to Strings in memory) because of it's max-32-concurrent-actions limit on decoding, rather than holding on to that work and completing it so that a successful result could be returned to the CDN and cached - lack of CDN caching meant that many requests were repeated, and this would probably have led to increased GC pressure.

This graph shows how many downloads vs decodes Facia was doing. When the server was healthy, these were the same number - when things go wrong, you can see we are doing many more downloads than decodes - all that the extra download work is achieving is generating more garbage collection & consuming threads from the blockingOperations thread pool.