Transaction Trace Detail Revamp

[itsderek23]

The transaction trace view in Scout is ready for a revamp.

Working backwards, below are jobs that I'd like to make easier:

• Narrowing down time spent in uninstrumented code
  • "What is controller time" is one of the most-asked questions. ScoutProf is designed for this, but is BETA.
  • Often times, slow time is based on the size of the data (see below)
• Better understanding of the response flow
  • In the current UI, it's difficult to identify that an N+1 is being triggered by a database call in a collection of partials
• Better understanding of the impact of the size of the data on response times and memory usage
  • Requests are often slower than the median when:
  • The size of the payload is larger (ex: more JSON data to parse)
  • A database query needs to run over more rows than the median
  • A database query returns more rows than the median
  • The size of the response is larger, like when rendering more data
• Understanding parallel work
  • We don't have a way to represent parallel work, like executing HTTP requests in parallel

Share your thoughts! Give a 👍 and we'll ping when the new trace view enters BETA.

[itsderek23]

The size of the payload is larger (ex: more JSON data to parse)

New Relic breaks down time spent in ActionDispatch::ParamsParser#call middleware. I would expect this to be slower when a large payload is parsed.

Fetching the request header content-length may also help here. It could be added as context and/or as a detail on the ParamsParser layer.

The size of the response is larger, like when rendering more data

See Rack::ContentLength. This could be as context and/or as a detail on the view layer.

Narrowing down time spent in uninstrumented code

The ability to optionally append the output of the following to their parent layers:

• calls to record StatsD metrics
• calls to Rails.logger

...could prove very helpful in understanding the behavior of custom code in Controller and view layers.

[itsderek23]

calls to Rails.logger

I created a quick POC that appends log messages to the current layer in a transaction:

The output in the UI is too noisy, but that can be adjusted (perhaps show a log message every 10 ms with the ability to expand and view all log messages).

This is a similar approach to Sentry Breadcrumbs.

While these log messages aren't recording performance information, they can be used to infer where chunks are taking a lot of time by examining the amount of time btw 2 log messages. If a customer has a large block of time they'd like to break down, telling a customer to just add a call to Rails.logger before/after blocks of code is pretty approachable.

It's also be great to get backtraces to the LOC outputing the log messages. We'd need to be able to collect that in a more efficient manner than calling caller. Rotoscope's approach looks interesting.

[itsderek23]

WIP on a timeline view of a transaction trace:

Serves a couple of purposes:

• Understanding parallel work (not applicable to the above trace)
• Narrowing down time spent in uninstrumented code - notice those blocks of time in endpoints/trace ... you can more easily tell where that time is spent.

[itsderek23]

Via mouth-words, @cschneid mentioned we could condense the trace and make it easier to relate a deeper child span with its parent in some cases:

[itsderek23]

Everyone loves seeing the code (not just the backtrace) that we pop-in when the GitHub integration is enabled.

However, there are some drawbacks using GitHub. For example, not everyone uses GitHub (see #18 #20).

I'd wager that 85% of the value is just seeing the code. 15% is the blame data. We could get that 85% w/o any integration if we grabbed the file contents around the referenced frames (similar to how exception monitoring services work). We'd need to be careful about performance, but I think there are several options to do that. For example, rather than reading the file contents inline during the request, we can grab the data in the background before sending traces to Scout.

[itsderek23]

In an earlier comment, I mentioned that rendering time is often slower when the response body is larger. More content is being rendered:

The size of the response is larger, like when rendering more data See Rack::ContentLength. This could be as context and/or as a detail on the view layer.

As an experiment, I've created a middleware that can be dropped into a Rails app. This reports Response-Content-Length in bytes for each web request. You can then filter by this in Trace Explorer, looking for correlations in response time w/increases in content length.

[jsierles]

Is this going into beta after all?

[itsderek23]

@jsierles - sorry for the radio silence on this.

We are actively working on this and shooting for an EOY release.

[itsderek23]

The new traceview is now in Beta for Ruby. See our help docs for more information and upgrade instructions.

[jsierles]

Thanks, this looks great! Are there plans to support background jobs?

[itsderek23]

Are there plans to support background jobs?

Definitely. We're going to iron out quirks w/the initial web-focused release, then we'll apply to background jobs.

[dlanderson]

Timeline Traces were released in scout_apm 2.5.0 for ruby in August, and Python now supports timeline trace views also in 2.5.0! https://docs.scoutapm.com/#transaction-traces