We just started to use CF workers. We have an endpoint that receives requests from third parties, and we have a CF worker to process those requests. The script formats the request, pushes it to AWS SQS for further processing and sends a 200 response back to the requester(clients).
The clients who sends the requests to this endpoint complained about the time taken to respond is 10 sec. It is not happening every time, and we are not sure when exactly this happens. We need to know where exactly the issue is. What is the best way to address this issue? Do we need to setup logging for this? If yes, how to do that? Are there any other ways to know the issue with the delay in processing?
Maybe the push to AWS takes too much time. Maybe you can just respond with 200 at once and push whatever information you need stored asynchronously using event.waitUntil()
What is the best way to address this issue? Do we need to setup logging for this? If yes, how to do that? Are there any other ways to know the issue with the delay in processing?
So you face two tasks at a time - profiling and logging.
By profiling I mean getting timestamps of each and every ‘breakpoint’ you decide you want timestamp for. It’s not that easy(if possible at all) to do in workers even for a multiple breakpoints in single workers request - check out my question and answers on that Profiling Workers - same timstamp for start and end times . event.waitUntil() allows you to send logging request after worker response was completed - but it’s just a mean of transportation, it does not help you actually getting correct timestamps you actually need to do profiling.
Instead you might want to collect the timestamps on each event on the logs receiving endpoint. For this there are couple scenarios:
a) Just craft a simple logging worker and dump logs to KV. You’ll get one timestamp per log message and that’s no problems here. Should you send the each breakpoint as a event.waitUntil? Would need to check out how it works once again, not sure. You might as well just make sync calls to your logs worker - it should be running in same CF datacenter ant take no longer then 10ms. If you profile for 10s delays, 10ms variation might just be OK.
b) You want might to look at Commands - Wrangler · Cloudflare Workers docs (Announcing new tools to debug your Cloudflare Workers applications - DEV Community). You basicly would launch wrangler debug in a dedicated machine in digital ocean or else for collecting logs. Logged are two things - exceptions and console.log() output. They also have precise timestamps(need to doublecheck do timestamps for two console.log() outputs differ if they are generated from within single request. What you do from there is completely up to you - you might just dump all this data to database and analyze later. The point is that you get hard data - i.e. logs for each and every request. I tried it for debugging during the development process - all worked on first attempt.
So if it’s an actual problem you are facing - just invest some time and go for b) path. And if you manage to implement storing wrangler tail output to database successfully - let us know how it worked here:)
i’ve updated my answer on on wrangler tail, that part now reads as: “Logged are two things - exceptions and console.log() output. They also have precise timestamps. But it’d be needed to doublecheck if timestamps for two console.log() outputs actually differ if they are generated from within single request.” You might want to check this yourself or ask a separate question in this forum - as of now I do not have an answer to this.
So the final recipe would probably look something like this:
// Set URL of your temporary worker endpoint which just returns response
const pingWorkerUrl = 'https://mydomain.com/workers/ping'
// Create request for ping URL
let pingRequest = new Request(pingWorkerUrl, {
headers: request.headers,
method: 'GET'
})
let response = await fetch(request)
console.log('foo')
// some logic or 'burn some CPU' example from Harris ^.
response = await fetch(request)
console.log('bar')
// some logic or 'burn some CPU' example from Harris ^.
response = await fetch(request)
console.log('baz')
Now all the console.log outputs in wrangler tail should have different timestamps.
The code above is not tested, so high chances I’ve missed something on the code level and/or on the conceptual level as will, kindly please correct me.
And just to recap:
a) We need this let response = await fetch(request) to update Date.now(), as Harris explained.
b) We suggest to have separate worker andpoint which just returns response so to make that the request would not take more than 1-10ms and for the results accuracy. Again - if you profile for 10s issues, feel free to just call set pingWorkerUrl to any random API endpoint on internet.
c) We suggest to use wrangler tail to collect timestamps as it allows you not code any time diff calculations into worker itself, but you might as well just do the math yourself as discussed Profiling Workers - same timstamp for start and end times and avoid using wrangler tail.
Hope all that makes sense. Let us know if you face any problems!