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

Sb8244 request queue #142

Merged
merged 10 commits into from Oct 10, 2019
Merged

Conversation

sb8244
Copy link
Contributor

@sb8244 sb8244 commented Oct 9, 2019

Okay, this is for #141. It's the biggest PR I've done here, so it probably has a good bit that could be changed.

Goals:

  • Track queueDuration as seconds (fractional to the microsecond) on web transactions
  • The queue start time is interpreted from one of "x-request-start", "x-queue-start", "x-middleware-start", as per the Ruby implementation
  • The queue start time can be microseconds, milliseconds, or seconds (fractions supported)
  • Clock skew, start time in the future, is interpreted as "now"
  • WebFrontend/QueueTime metric is dispatched with completed requests

The Ruby implementation served as inspiration for deriving queue start, but I didn't handle some cases like having a compound header, or multiple headers with different values.

I haven't tried it in practice, yet.

defp derive_queue_duration(%{start_time: start_time, queue_start_us: queue_start_us} = tx)
when not is_nil(queue_start_us) do
start_time_us = System.convert_time_unit(start_time, :native, :microsecond)
queue_duration_us = max(0, start_time_us - queue_start_us)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is one protection from skew. This could stay, or the other could stay, or both. I think this one is much more performant since it's not going to clock, so it might be a better candidate to stay.

max_call_time: total_time_s
}
]
|> queue_duration_metric(queue_duration_s)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we should report the queue metric separately from this, in this file we should just be adding a function like this:

def transform(:queue_time, duration_s: duration_s) do
  [
    %Metric{}
  ]
end

@@ -494,7 +510,8 @@ defmodule NewRelic.Transaction.Complete do
def report_transaction_metric(tx) do
NewRelic.report_metric({:transaction, tx.name},
duration_s: tx.duration_s,
total_time_s: tx.total_time_s
total_time_s: tx.total_time_s,
queue_duration_s: Map.get(tx, :queue_duration_s, nil)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

let's have 2 calls to report_metric here instead of smushing them together

|> NewRelic.add_attributes()
end

@queue_duration_headers ["x-request-start", "x-queue-start", "x-middleware-start"]
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'd rather just stick with x-request-start than pile on a bunch of extra logic for backwards compatibility

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Happy to make that change. I didn't realize they were legacy

{:halt, us}

{:error, reason} ->
Logger.debug(reason)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's a NewRelic logger that'd be preferable, though i'm not sure it's something i'd really want to log out

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm happy to remove it. I put it here to mirror the Ruby agent log. I could see someone wondering "why isn't my queueing metric reporting?"

@@ -23,7 +24,8 @@ defmodule NewRelic.Transaction.Event do
timestamp: transaction.timestamp,
name: transaction.name,
duration: transaction.duration,
type: transaction.type
type: transaction.type,
queueDuration: transaction.queue_duration
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This isn't where we should be reporting the attribute, only a small set of attributes are accepted here, we can remove this from Event.

tx
|> Map.merge(%{
queue_duration_us: queue_duration_us,
queue_duration_s: queue_duration_us / 1_000_000
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is actually where we need to report the final queueDuration attribute... I don't think we need the other time unit attributes, and we should actually drop the queue_start_us attribute

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh. So these transaction attributes will be added to the final transaction automatically? The key should be queueDuration in that case?

@binaryseed binaryseed changed the base branch from master to request-queue October 10, 2019 04:09
@binaryseed
Copy link
Collaborator

Thanks for contributing! I'm going to follow up with a few commits before pulling this into master and cutting a release...

@binaryseed binaryseed merged commit cce9098 into newrelic:request-queue Oct 10, 2019
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.

None yet

3 participants