cloudflare / cloudflare/workerd
🐛 BUG: reasoning about the TTFB outliers
- Dominant language
- C++
- Stars
- 8.7k
- Forks
- 739
- Avg merge
- 2d 20h
- Merged PRs (30d)
- 174
Description
### Which Cloudflare product(s) does this pertain to?
Workers Runtime
### What version(s) of the tool(s) are you using?
3.91.0 [wrangler], 5.7.2 [typescript], 4.20241202.0 [@cloudflare/workers-types]
### What version of Node are you using?
v20.18.0
### What operating system and version are you using?
macOS 15.2
### Describe the Bug
My workers have the following setup:
- 2 workers as http server, listening by different URL path on the same hostname
- 1 worker as the tail worker for both of the http servers, that handles logging and metrics reporting for each request
Currently I'm on a trial of the enterprise plan and discovered, through logpush, that around \~0.0003% requests having a high `EdgeTimeToFirstByteMs` ranged from 500ms\~7s. The logs also indicated these outliers had a `CacheCacheStatus: hit` status.
The 2 main workers are using `node:diagnostics_channel` to pass information to the tail worker, seemingly related to the TTFB issue so I'll post the relevant part of the code here. More details and full code can be shared once this is picked up by the Cloudflare support team.
### Observed behavior
- Among all the requests, an avg of 0.0003% requests having TTFB over 500ms, up to 7s.
- According to Cloudflare technical support's initial findings, the high TTFB cases were considered to be caused by making subrequests from our workers to a third-party metrics vendor, reaching the IAD node.
### Expected behavior
- All requests should have a consistent TTFB.
- By our code review, there's no subrequest made by our workers code to the third-party metrics vendor except for the tail worker. There should not be such subrequests observed.
### Steps to reproduce
**A minimal working subset of your worker code:**
```ts
// inside the fetch() function of index.ts
const originStart = Date.now()
const cache = caches.default
const cached = await cache.match(request.url)
if (cached) {
const respHeaders = new Headers(cached.headers)
respHeaders.set('Access-Control-Allow-Origin', '*')
respHeaders.set('Vary', 'Origin')
const resp = new Response(cached.body, {
headers: respHeaders,
status: cached.status,
})
sentinel.event({
event: eventNameRedacted,
request,
response: resp,
payload: {
...reqCtx,
duration: Date.now() - originStart
},
})
sentinel.event({
event: eventNameRedacted,
request,
response: resp,
payload: reqCtx
})
return resp
}
```
```ts
// inside the sentinel.ts
// datadog imported for calling a util method for generating the tags which doesn't make any HTTP request
import { Channel, channel } from 'node:diagnostics_channel'
import { SentinelEventType, SentinelMessage } from './types'
import { Datadog } from '../../shared/datadog'
import { DatadogPayload } from '../../shared/datadog.d'
export class Sentinel {
private readonly createdAt: Date
private readonly serviceName: string
private readonly channel: Channel
constructor(serviceName: string) {
this.createdAt = new Date()
this.serviceName = serviceName
this.channel = channel(serviceName)
}
event(message: { event: SentinelEventType;request ? : Request;response ? : Response;payload: DatadogPayload }): void {
if (!Boolean(message.payload.duration)) {
message.payload.duration = Date.now() - this.createdAt.getTime()
}
this.channel.publish({
event: message.event,
duration: message.payload.duration,
log: {
request: {
// tag fields redacted
},
response: {
// tag fields redacted
},
},
metric: {
// tag fields redacted
},
}
as SentinelMessage)
}
}
```
**A minimal working subset of your `wrangler.toml`:**
```toml
# for the http server
#:schema node_modules/wrangler/config-schema.json
main = "src/index.ts"
compatibility_date = "2024-08-06"
compatibility_flags = ["nodejs_compat"]
account_id = "redacted"
name = "redacted"
r2_buckets = [
{ binding = "BUCKET", preview_bucket_name = "redacted", bucket_name = "redacted" }
]
tail_consumers = [{service = "tail worker name redacted"}]
[vars]
# redacted
[[durable_objects.bindings]]
name = "redacted"
class_name = "redacted"
[[migrations]]
tag = "v1"
new_classes = ["redacted"]
```
```toml
# for the tail workers
#:schema node_modules/wrangler/config-schema.json
main = "src/index.ts"
compatibility_date = "2024-08-06"
compatibility_flags = ["nodejs_compat"]
account_id = "redacted"
name = "redacted"
[vars]
# redacted
[observability]
enabled = true
```
**Commands used to start your local dev server, including custom env and cli args:**
Not relevant, issue observed on edge.
**Steps to be performed in the browser, curl commands, or a test we can run that reliably fails (at least a percent of the time):**
This is a part of the enterprise support. Details are confidential.
Contributor guide
Assessment
This issue has not been assessed yet.