Track request queue time based on available request headers

[AxelTheGerman]

Hi,

I've been using the gem for a while and I added a way to parse common queue time headers.

It's been very useful to determine queue time of requests on the proxy level (before reaching the application) as it is a common source for performance issues.

Let me know if you'd be interested in accepting this change at all and I'm happy to refactor if needed.

[alexisbernard]

Thanks for taking time to write the PR. I really appreciate.

It should report the queue time with a section. Thus it is automatically displayed in the web interface :

def report_queue_time
  if queue_time = calculate_queue_time(env)
    section = Section.new
    section.stop
    section.total_ms = queue_time
    section.gc_time_ms = 0
    section.file = "request-queue"
    section.line = 0
    section.kind = "queue"
    RorVsWild.agent.add_section(section)
  end
end

[AxelTheGerman]

Thank you for the immediate response and the suggestion! I didn't know too much how sections work but that makes sense.

Will update the PR shortly :)

[alexisbernard]

I'm sorry for my latency. I've tested and it only requires this line to report everything properly:

diff --git a/lib/rorvswild/agent.rb b/lib/rorvswild/agent.rb
index 4a56c6f..fceb1bf 100644
--- a/lib/rorvswild/agent.rb
+++ b/lib/rorvswild/agent.rb
@@ -123,6 +123,7 @@ module RorVsWild
       gc = Section.stop_gc_timing(data[:gc_section])
       data[:sections] << gc if gc.calls > 0 && gc.total_ms > 0
       data[:runtime] = RorVsWild.clock_milliseconds - current_data[:started_at]
+      data[:runtime] += data[:sections].sum(0) { |s| s.kind == "queue" ? s.self_ms : 0 }
       queue_request
     end

[alexisbernard]

Can you use delete_prefix instead of gsub, because it's faster. Unless you have an example where the header value does not start with "t=".

[alexisbernard]

In which case RangeError could be raised?

[AxelTheGerman]

Not sure exactly... https://ruby-doc.org/core-3.1.1/RangeError.html

RangeError: bignum too big to convert into `long'

But I couldn't find a way to make this code raise this error. E.g. the largest multiplier is 1_000_000 and RoRVsWild.clock_milliseconds is a pretty large number - even then multiplying is fine.

I wonder if this might be for older Ruby versions before BigNum and FixNum were combined into Integer.

[alexisbernard]

But here is the division, so I don't see any risk to have a value too large. However timestamp.to_f can return Infinity. So to_f could be called outside of the loop and checked if Infinity.

[AxelTheGerman]

I'm sorry for my latency. I've tested and it only requires this line to report everything properly:

diff --git a/lib/rorvswild/agent.rb b/lib/rorvswild/agent.rb
index 4a56c6f..fceb1bf 100644
--- a/lib/rorvswild/agent.rb
+++ b/lib/rorvswild/agent.rb
@@ -123,6 +123,7 @@ module RorVsWild
       gc = Section.stop_gc_timing(data[:gc_section])
       data[:sections] << gc if gc.calls > 0 && gc.total_ms > 0
       data[:runtime] = RorVsWild.clock_milliseconds - current_data[:started_at]
+      data[:runtime] += data[:sections].sum(0) { |s| s.kind == "queue" ? s.self_ms : 0 }
       queue_request
     end

No worries at all!

That works but I'm wondering if we could instead:

• set current_data[:queued_at]
• use data[:runtime] = RorVsWild.clock_milliseconds - (current_data[:queued_at] || current_data[:started_at])

That way we don't have to go through all the sections again and potentially it might be useful to have that queued_at timestamp along started_at?

[alexisbernard]

Yes, that will save one loop 👍

[alexisbernard]

Thanks a lot!

Before merging, could you add an entry in CHANGELOG.md please?

[alexisbernard]

That's great. Thanks!