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

Support recording exception frame's local variables for requests #1580

Merged
merged 6 commits into from
Sep 29, 2021

Conversation

st0012
Copy link
Collaborator

@st0012 st0012 commented Sep 24, 2021

Introduction

This PR introduces a new feature to capture local variables when an exception is raised. For example, given this script:

a = 1
b = 0
a / b #=> This would cause ZeroDivisionError

The captured exception will contain the value of local variable a and b.

Here are some screenshots:

From this SDK's demo application

截圖 2021-09-24 下午5 58 52

From my company's application with a real error

locals capturing

This feature needs to be activated with the new capture_exception_frame_locals config option:

Sentry.init do |config|
  config.capture_exception_frame_locals = true # default is false
end

So if you don't want to use it, it won't affect your application.

Reason

It's the dream, isn't it 😉

Limitations & Caveats

  • Currently, this feature only works within the Sentry::CaptureExceptions middleware. Background job support will come later.
  • For exceptions raised from non-app paths, the frame will be folded and you need to see the locals from the Full stacktrace view.
  • Locals can contain sensitive data (e.g. user record's attributes).
    • Rails 6.0+ users can avoid this by configuring Rails.application.config.filter_parameters.
  • It only captures locals when an exception is first raised. All local variables from later rescuing/re-raising will not be recorded.

Performance Impact

TL;DR:

  • If you don't activate the feature, it doesn't cause extra overhead.
  • In the context of web applications, the impact of this feature is ignorable. (See below)

Benchmark (with Ruby 2.7.4)

require 'benchmark/ips'

def raise_n_exceptions(n, with_sleep: false)
  n.times do |i|
    raise "exception: #{i}" rescue nil
  end
  sleep(0.05) if with_sleep
end

def raise_n_exceptions_with_tracepoint(n, with_sleep: false)
  TracePoint.new(:raise) do |tp|
    exception = tp.raised_exception

    next if exception.instance_variable_get(:@sentry_locals)

    locals = tp.binding.local_variables.each_with_object({}) do |local, result|
      result[local] = tp.binding.local_variable_get(local)
    end

    exception.instance_variable_set(:@sentry_locals, locals)
  end.enable do
    raise_n_exceptions(n, with_sleep: with_sleep)
  end
end

Benchmark.ips do |x|
  x.report("raise 50 exceptions") { raise_n_exceptions(50) }
  x.report("raise 50 exceptions with tracepoint") { raise_n_exceptions_with_tracepoint(50) }
  x.compare!
end

# simulate other workload with 50ms of sleep time
Benchmark.ips do |x|
  x.report("(with 50ms sleep) raise 50 exceptions") { raise_n_exceptions(50, with_sleep: true) }
  x.report("(with 50ms sleep) raise 50 exceptions with tracepoint") { raise_n_exceptions_with_tracepoint(50, with_sleep: true) }
  x.compare!
end

When the local-capturing TracePoint is enable, exception handling slows down significantly.

Warming up --------------------------------------
 raise 50 exceptions     1.919k i/100ms
raise 50 exceptions with tracepoint
                       537.000  i/100ms
Calculating -------------------------------------
 raise 50 exceptions     18.803k (± 2.1%) i/s -     94.031k
raise 50 exceptions with tracepoint
                          5.333k (± 3.8%) i/s -     26.850k

Comparison:
 raise 50 exceptions:    18803.0 i/s
raise 50 exceptions with tracepoint:     5332.8 i/s - 3.53x slower

However, our applications don't just raise exceptions and do nothing. So let's simulate some extra timespent on other stuff with sleep (just 50 ms):

Warming up --------------------------------------
(with 50ms sleep) raise 50 exceptions
                         1.000  i/100ms
(with 50ms sleep) raise 50 exceptions with tracepoint
                         1.000  i/100ms
Calculating -------------------------------------
(with 50ms sleep) raise 50 exceptions
                         19.032  (± 5.3%) i/s -     96.000
(with 50ms sleep) raise 50 exceptions with tracepoint
                         18.953  (± 5.3%) i/s -     95.000

Comparison:
(with 50ms sleep) raise 50 exceptions:       19.0 i/s
(with 50ms sleep) raise 50 exceptions with tracepoint:       19.0 i/s - same-ish: difference falls within error

Since Ruby's exception raising/rescuing are pretty fast, the extra overhead added by TracePoint isn't even observable in this case.

Future Development

If this approach is proved working, we can enhance it in 2 directions:

  1. Add more information to the frame, e.g. instance variables.
  2. Capture local variables for more frames.

The 2nd enhancement may be the most-desirable feature to add. However, its overhead may be significant because the SDK will need to walk through every frame for collecting local variables, and do that for every exception raised. So it's possible that we need to introduce it with extra configurations to reduce the overhead (e.g. only capture certain number of frames or certain exceptions).

@st0012 st0012 added this to the 4.8.0 milestone Sep 24, 2021
@st0012 st0012 self-assigned this Sep 24, 2021
@st0012 st0012 added this to In progress in 4.x via automation Sep 24, 2021
@codecov-commenter
Copy link

codecov-commenter commented Sep 25, 2021

Codecov Report

Merging #1580 (f6aecf2) into master (e6c7079) will decrease coverage by 0.05%.
The diff coverage is 93.05%.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #1580      +/-   ##
==========================================
- Coverage   98.53%   98.47%   -0.06%     
==========================================
  Files         127      127              
  Lines        7022     7091      +69     
==========================================
+ Hits         6919     6983      +64     
- Misses        103      108       +5     
Impacted Files Coverage Δ
sentry-ruby/lib/sentry/rack/capture_exceptions.rb 86.27% <58.33%> (-8.73%) ⬇️
sentry-rails/spec/support/test_rails_app/app.rb 100.00% <100.00%> (ø)
sentry-ruby/lib/sentry/configuration.rb 97.98% <100.00%> (+0.02%) ⬆️
...try-ruby/lib/sentry/interfaces/single_exception.rb 100.00% <100.00%> (ø)
...y-ruby/spec/sentry/rack/capture_exceptions_spec.rb 100.00% <100.00%> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update e6c7079...f6aecf2. Read the comment docs.

@st0012 st0012 changed the title Support recording exception frame's local variables Support recording exception frame's local variables for requests Sep 29, 2021
@st0012 st0012 merged commit f23b093 into master Sep 29, 2021
@st0012 st0012 deleted the support-exception-locals branch September 29, 2021 13:05
4.x automation moved this from In progress to Done Sep 29, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
4.x
  
Done
Development

Successfully merging this pull request may close these issues.

None yet

2 participants