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.

Sign up for GitHub

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

Jump to bottom

Increase in CPU usage when performance_stats = true #488

Closed
lenon opened this issue Jul 1, 2019 · 3 comments · Fixed by #491
Closed

Increase in CPU usage when performance_stats = true #488

lenon opened this issue Jul 1, 2019 · 3 comments · Fixed by #491

Comments

@lenon
Copy link

lenon commented Jul 1, 2019

Hi,
Last week we upgraded airbrake from 9.2.2 to 9.3.0 and airbrake-ruby from 4.4.0 to 4.5.0. After the deploy of this upgrade, we had an increase in CPU usage and latency times in our app which was fixed by setting performance_stats to false. Here's our latency metrics:

Screen_Shot_2019-07-01_at_15_09_28

And CPU usage metrics from one of our VMs:

Screen_Shot_2019-07-01_at_15_16_42

These metrics are from DataDog and are reported by ddtrace gem.

We also had **Airbrake: Your account does not accept APM data logged hundreds of times per minute. Maybe that's because we need to decrease our log level, but I'm not sure.

Everything looks normal in our app now, but I'm still opening this issue so you folks can check if there are some improvements that can be done to reduce CPU usage. I also think that would be good to mention something about performance_stats in airbrake changelog.

Additional info:

  • Airbrake version: 9.3.0
  • Ruby version: 2.6.3
  • Framework name & version: Rails 5.2.3, Sidekiq 5.2.7
kyrylo added a commit that referenced this issue Jul 9, 2019
@kyrylo
Don't allocate strings when we don't log
93921eb 
https://ruby-doc.org/stdlib-2.4.0/libdoc/logger/rdoc/Logger.html#class-Logger-label-How+to+log+a+message

> The block form allows you to create potentially complex log messages, but to
> delay their evaluation until and unless the message is logged.

This should help with troubleshooting #488 (Increase in CPU usage when
performance_stats = true). PerformanceNotifier has a debug statement that we
calculate each time we send a request. It builds a complex object and quite
likely makes performance worse.
kyrylo added a commit that referenced this issue Jul 9, 2019
@kyrylo
performance_notifier: delay string conversion of payload on logging
b5d3e45 
In #488 a lot of users mentioned that they see performance slowdown when they
enable APM. My theory is that this is due to the fact that we log debug
output. Converting `payload` to string is expensive. The Logger library offers
another way to log:

https://ruby-doc.org/stdlib-2.4.0/libdoc/logger/rdoc/Logger.html#class-Logger-label-How+to+log+a+message
> The block form allows you to create potentially complex log messages, but to
> delay their evaluation until and unless the message is logged.

This should help with performance. I dropped a `binding.pry` in the context of
the debug statement and ran benchmarks to verify this (logger level is
`Logger::ERROR`):

```
[7] pry(#<Airbrake::PerformanceNotifier>)> ::Benchmark.ips do |ips|
[7] pry(#<Airbrake::PerformanceNotifier>)*   ips.report('inline') do
[7] pry(#<Airbrake::PerformanceNotifier>)*     logger.debug("#{LOG_LABEL} #{signature}: #{payload}")
[7] pry(#<Airbrake::PerformanceNotifier>)*   end
[7] pry(#<Airbrake::PerformanceNotifier>)*   ips.report('block') do
[7] pry(#<Airbrake::PerformanceNotifier>)*     logger.debug { "#{LOG_LABEL} #{signature}: #{payload}" }
[7] pry(#<Airbrake::PerformanceNotifier>)*   end
[7] pry(#<Airbrake::PerformanceNotifier>)* end
Warming up --------------------------------------
              inline     3.006k i/100ms
               block   101.266k i/100ms
Calculating -------------------------------------
              inline     31.775k (± 2.3%) i/s -    159.318k in   5.016549s
               block      1.341M (± 6.4%) i/s -      6.684M in   5.001161s
```

This is a huge difference. Production apps usually don't debug production, so
they shouldn't be suffering this performance hit. That said, the issue with slow
debug output is not completely solved since apps that do use the `debug`
severity, still suffer a performance hit. This should be resolved separately.
kyrylo added a commit that referenced this issue Jul 9, 2019
@kyrylo
performance_notifier: delay string conversion of payload on logging
f9422f4 
In #488 a lot of users mentioned that they see performance slowdown when they
enable APM. My theory is that this is due to the fact that we log debug
output. Converting `payload` to string is expensive. The Logger library offers
another way to log:

https://ruby-doc.org/stdlib-2.4.0/libdoc/logger/rdoc/Logger.html#class-Logger-label-How+to+log+a+message
> The block form allows you to create potentially complex log messages, but to
> delay their evaluation until and unless the message is logged.

This should help with performance. I dropped a `binding.pry` in the context of
the debug statement and ran benchmarks to verify this (logger level is
`Logger::ERROR`):

```
[7] pry(#<Airbrake::PerformanceNotifier>)> ::Benchmark.ips do |ips|
[7] pry(#<Airbrake::PerformanceNotifier>)*   ips.report('inline') do
[7] pry(#<Airbrake::PerformanceNotifier>)*     logger.debug("#{LOG_LABEL} #{signature}: #{payload}")
[7] pry(#<Airbrake::PerformanceNotifier>)*   end
[7] pry(#<Airbrake::PerformanceNotifier>)*   ips.report('block') do
[7] pry(#<Airbrake::PerformanceNotifier>)*     logger.debug { "#{LOG_LABEL} #{signature}: #{payload}" }
[7] pry(#<Airbrake::PerformanceNotifier>)*   end
[7] pry(#<Airbrake::PerformanceNotifier>)* end
Warming up --------------------------------------
              inline     3.006k i/100ms
               block   101.266k i/100ms
Calculating -------------------------------------
              inline     31.775k (± 2.3%) i/s -    159.318k in   5.016549s
               block      1.341M (± 6.4%) i/s -      6.684M in   5.001161s
```

This is a huge difference. Production apps usually don't debug production, so
they shouldn't be suffering this performance hit. That said, the issue is not
completely solved since apps that do use the `debug` severity still suffer a
performance hit. This should be resolved separately.
@kyrylo kyrylo mentioned this issue Jul 9, 2019
Merged
kyrylo added a commit that referenced this issue Jul 9, 2019
@kyrylo
performance_notifier: delay string conversion of payload on logging
a38462f 
In #488 a lot of users mentioned that they see performance slowdown when they
enable APM. My theory is that this is due to the fact that we log debug
output. Converting `payload` to string is expensive. The Logger library offers
another way to log:

https://ruby-doc.org/stdlib-2.4.0/libdoc/logger/rdoc/Logger.html#class-Logger-label-How+to+log+a+message
> The block form allows you to create potentially complex log messages, but to
> delay their evaluation until and unless the message is logged.

This should help with performance. I dropped a `binding.pry` in the context of
the debug statement and ran benchmarks to verify this (logger level is
`Logger::ERROR`):

```
[7] pry(#<Airbrake::PerformanceNotifier>)> ::Benchmark.ips do |ips|
[7] pry(#<Airbrake::PerformanceNotifier>)*   ips.report('inline') do
[7] pry(#<Airbrake::PerformanceNotifier>)*     logger.debug("#{LOG_LABEL} #{signature}: #{payload}")
[7] pry(#<Airbrake::PerformanceNotifier>)*   end
[7] pry(#<Airbrake::PerformanceNotifier>)*   ips.report('block') do
[7] pry(#<Airbrake::PerformanceNotifier>)*     logger.debug { "#{LOG_LABEL} #{signature}: #{payload}" }
[7] pry(#<Airbrake::PerformanceNotifier>)*   end
[7] pry(#<Airbrake::PerformanceNotifier>)* end
Warming up --------------------------------------
              inline     3.006k i/100ms
               block   101.266k i/100ms
Calculating -------------------------------------
              inline     31.775k (± 2.3%) i/s -    159.318k in   5.016549s
               block      1.341M (± 6.4%) i/s -      6.684M in   5.001161s
```

This is a huge difference. Production apps usually don't debug production, so
they shouldn't be suffering this performance hit. That said, the issue is not
completely solved since apps that do use the `debug` severity still suffer a
performance hit. This should be resolved separately.
kyrylo added a commit that referenced this issue Jul 9, 2019
@kyrylo
stat: define custom #inspect
62b0d83 
Hopefully fixes #488 (Increase in CPU usage when performance_stats = true)

I noticed that dumping TDigest is very slow. Here's performance payload with
TDigests:

```
Warming up --------------------------------------
                         1.553k i/100ms
Calculating -------------------------------------
                         15.906k (± 3.0%) i/s -     80.756k in   5.082704s
```

And here's the same payload but without TDigests.

```
Warming up --------------------------------------
                          4.443k i/100ms
Calculating -------------------------------------
                         45.498k (± 1.8%) i/s -    231.036k in   5.079495s
```

It makes sense to not dump TDigests because it's mostly clutter and it makes
performance much worse.
@kyrylo kyrylo mentioned this issue Jul 9, 2019
Merged
@kyrylo
Copy link
Contributor

kyrylo commented Jul 9, 2019

Thanks for the useful info. I addressed these performance hits in #490 and #491. I don't have 100% confidence that this will resolve all the performance issues that you spotted on the graph but it is a significant improvement.

I also suspect that you may run your app in the debug mode (debug logger severity). If that's the case, try to use error severity. It's a lot to ask, so what you could do is configure your airbrake notifier to a custom severity.

In other news (unrelated to this issue but also about logging), check this out: https://github.com/airbrake/airbrake#logging
We now log to log/airbrake.log by default (only for new Rails apps), so with that setting it'll be easier to debug Airbrake.

P.S. We do mention the performance_stats = true change in this project but it's probably a good idea to duplicate that info in airbrake as well, since you're not the first person to be confused.

@lenon
Copy link
Author

lenon commented Jul 9, 2019

@kyrylo thanks for taking a look at this. We are not running our app in debug mode. I checked our log level and it is the default from Rails, which is "info". It makes me think that the severity of the message we saw in our logs is "info" or "error".

@zefer zefer mentioned this issue Jul 19, 2019
Closed
@kyrylo
Copy link
Contributor

kyrylo commented Aug 8, 2019

Hey @lenon. Could you please check out airbrake v9.4.3? It contains a significant performance improvement. I would really appreciate if you could share how it impacts your app.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

stat: define custom #inspect airbrake/airbrake-ruby
2 participants
@lenon @kyrylo