Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add a timestamp to the Rook request object. #262

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

atheriel
Copy link
Contributor

@atheriel atheriel commented Apr 6, 2020

This PR adds a httpuv.timestamp member containing a timestamp compatible with Sys.time() to the Rook request object. You can use these timestamps it to measure and report on request latency:

httpuv::runServer(
  "127.0.0.1", 8080,
  list(call = function(req) {
    elapsed_ms <- difftime(Sys.time(), req$httpuv.timestamp, units = "secs") * 1000
    list(
      status = 200L,
      headers = list("Content-Type" = "text/plain"),
      body = sprintf("Latency (ms): %.3f\n", elapsed_ms)
    )
  })
)

Importantly, this timestamp is captured when the request is received at the C++ level in the background thread, which has two advantages:

  1. We can much more accurately capture the total time the client actually waits for the request to get processed, especially if the R thread is congested or running GC.

  2. We can instrument the time it takes before the R-level callback actually runs.

More broadly, the timestamp makes it easier to log measures of request latency in httpuv-based applications, and reduces the overhead of common ways to do so -- e.g. using Plumber hooks.

I'm unsure about whether httpuv.timestamp is a good name, and am happy to take suggestions for improvements.

Also, I have little faith in my C++ (though I've made sure to use C++11-compatible interfaces here).

Finally, if you're interested in R's internal Sys.time() implementation, the source is in time.c:currentTime().

@atheriel
Copy link
Contributor Author

atheriel commented Apr 6, 2020

CI failures seem unrelated.

@wch
Copy link
Collaborator

wch commented Apr 6, 2020

The CI failures are due to RcppCore/Rcpp#1048.

Requests objects now have a `httpuv.timestamp` member containing a
timestamp compatible with Sys.time().

This timestamp is captured when the request is received at the C++ level
in the background thread, which has two advantages:

1. We can much more accurately capture the total time the client
   actually waits for the request to get processed.

2. We can instrument the time it takes before the R-level callback
   actually runs.

More broadly, the timestamp makes it easier to log measures of request
latency in httpuv-based applications, and reduces the overhead of common
ways to do so -- e.g. using Plumber hooks.

Signed-off-by: Aaron Jacobs <aaron.jacobs@crescendotechnology.com>
@atheriel atheriel force-pushed the timestamps-in-requests branch from b16a5f4 to a24c919 Compare May 5, 2021 16:34
@atheriel
Copy link
Contributor Author

atheriel commented May 5, 2021

Tweaked slightly and rebased to fix merge conflicts.

@CLAassistant
Copy link

CLA assistant check
Thank you for your submission! We really appreciate it. Like many open source projects, we ask that you sign our Contributor License Agreement before we can accept your contribution.
You have signed the CLA already but the status is still pending? Let us recheck it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants