Add CPU time to output for requests #175
Conversation
Fastly uses CPU time to denote how much time is spent *actually running*
the WASM code given to us. Given how asynchronous code works, it means
we only run the code when it's being polled. This means we can't just
slap `Instant::now()` in front of the call to the main function of the
WASM in Viceroy. We instead construct a future that will check how long
each call to `poll` was and add it to a `Duration`. When we are done
polling we will have the result of the request made to Viceroy and how
long that took! We then report it with the other metrics for customers
to look at so that they can approximate how much time they spend in
their module. While this is by no means a 1 to 1 in terms of how much
CPU time is actually used as a customer's local environment is not the
same as our POPs it should help guide them in terms of optimizing their
code so that requests are fast.
Sample output when running now for stats:
```
Sep 13 13:22:40.291 INFO request{id=14}: request completed using 1.1 MB of WebAssembly heap
Sep 13 13:22:40.291 INFO request{id=14}: request completed in 5ms
Sep 13 13:22:40.291 INFO request{id=14}: CPU Time 3ms
```
You can see that it takes 5ms for the whole request to complete, but only
3ms of which is spent working on the actual request using the customer's
code.
mgattozzi
requested review from
a team and
awortman-fastly
and removed request for
a team
| let poll_time = Instant::now().duration_since(now); | ||
| self.duration += poll_time; |
There was a problem hiding this comment.
| let poll_time = Instant::now().duration_since(now); | |
| self.duration += poll_time; | |
| self.duration += now.elapsed(); |
take it or leave it, but i'm like 95% sure this is a correct suggestion...
| @@ -302,6 +303,7 @@ impl ExecuteCtx { | |||
| ); | |||
|
|
|||
| info!("request completed in {:.0?}", request_duration); | |||
| info!("CPU Time {:.0?}", cpu_time); | |||
There was a problem hiding this comment.
probably good to have a message more consistent with the other info text, something like...
| info!("CPU Time {:.0?}", cpu_time); | |
| info!("request completed using {:.0?} of CPU time", cpu_time); |
additionally moving this up a line or two would give output like:
request completed using ... of WebAssembly heap
request completed using ... of CPU time
request completed in ...
which leaves the first two grouped together as they're both talking about resource use for the request in question. that seems preferable to the WebAssembly heap/request completed/CPU used sandwich we'd get here?
|
This PR is on hold until we get some confirmation from product regarding this. The issue is that Viceroy is more of a correctness implementation. You run it in CI and then can check things like did my request go to the origin as expected etc. It's not an exact copy of a production environment and while we can show some timings like request total time it's just not going to run at the same speeds or interact with things the same as on our POPs. Viceroy only mimics a part of how Fastly works. What we don't want is to guarantee that Viceroy is the same as a prod environment, especially for guiding optimizations. It's a good approximation, but it's just not the same as running it in production and it would be better for a customer to run things in a staging environment for tuning perf while using Viceroy to make sure their code runs as expected. Until we talk to product about how to handle this bit of trickiness or what we want to guarantee I'm going to close this PR for now and reopen it if we wish to proceed with this. |
Fastly uses CPU time to denote how much time is spent actually running the WASM code given to us. Given how asynchronous code works, it means we only run the code when it's being polled. This means we can't just slap
Instant::now()in front of the call to the main function of the WASM in Viceroy. We instead construct a future that will check how long each call topollwas and add it to aDuration. When we are done polling we will have the result of the request made to Viceroy and how long that took! We then report it with the other metrics for customers to look at so that they can approximate how much time they spend in their module. While this is by no means a 1 to 1 in terms of how much CPU time is actually used as a customer's local environment is not the same as our POPs it should help guide them in terms of optimizing their code so that requests are fast.Sample output when running now for stats:
You can see that it takes 5ms for the whole request to complete, but only 3ms of which is spent working on the actual request using the customer's code.