CPU and Average Response increased after version 7 #990

rodolfobandeira · 2019-07-18T17:22:39Z

Looks like more people came here complaining about the same issue. Although, for some people just disabling performance_stats and upgrading from version 8 to 9 solved the issue.
Unfortunately, for us here, changing that config and versions didn't help. It only came back to the regular ~130 ms after rolling back the gem to version 7. The average response for the webservers increased from ~130ms to ~260ms. Doesn't look that our database was affected. All stats looks the same.

Please let us know what would be your recommendation otherwise we'll have to stay on version 7 forever. Thank you! 😕

More details:

Rails 5.1 and Ruby 2.4:

New Relic Average Response:

Web Servers CPU Usage:

After rolling back to version 7

First upgrade, avg response from ~130ms to ~260ms:

7 -> 8, config.performance_status = true

Gemfile

- gem 'airbrake', '~> 7.3'
+ gem 'airbrake', '~> 8.3.2'

Gemfile.lock

-    airbrake (7.4.0)
-      airbrake-ruby (~> 2.12)
-    airbrake-ruby (2.12.0)
+    airbrake (8.3.2)
+      airbrake-ruby (~> 4.1)
+    airbrake-ruby (4.2.5)
+      rbtree3 (~> 0.5)

config.performance_stats = true

Second upgrade. Still ~260ms avg response

Gemfile:

- gem 'airbrake', '~> 8.3.2'
+ gem 'airbrake', '~> 9.3.0'

Gemfile.lock

-    airbrake (8.3.2)
-      airbrake-ruby (~> 4.1)
-    airbrake-ruby (4.2.5)
+    airbrake (9.3.0)
+      airbrake-ruby (~> 4.5)
+    airbrake-ruby (4.5.0)

config.performance_stats = true

Third change, avg response still ~260ms

config.performance_stats = false

Airbrake and Airbrake ruby same of previous step.

Airbrake 9.3.0
Aibrake-ruby 4.5.0

Last change. Back to ~130ms avg response:

9 -> 7, Remove config: "config.performance_stats = false"

Gemfile

- gem 'airbrake', '~> 9.3.0'
+ gem 'airbrake', '~> 7.3'

Gemfile.lock

-    airbrake (9.3.0)
-      airbrake-ruby (~> 4.5)
-    airbrake-ruby (4.5.0)
-      rbtree3 (~> 0.5)
+    airbrake (7.4.0)
+      airbrake-ruby (~> 2.12)
+    airbrake-ruby (2.12.0)

The text was updated successfully, but these errors were encountered:

zefer · 2019-07-19T09:20:04Z

Hi @rodolfobandeira. Thanks for this useful info. We're actively working on this but @kyrylo (who leads this library's development) is currently on vacation hence the delays, sorry for the inconvenience.

It's possible that what you are seeing is what @kyrylo addressed in airbrake/airbrake-ruby#488, those two PRs are on master but are not yet released to Rubygems: https://github.com/airbrake/airbrake-ruby/blob/master/CHANGELOG.md#master. Exactly which version of airbrake and airbrake-ruby were you running?

We'll get this resolved but it may take a couple of weeks. In the meantime, a couple of possible options are to a) try the versions on master, b) hang-tight and wait for @kyrylo to review this and release the necessary fixes including those on master.

Thanks for your patience and your helpful report!

rodolfobandeira · 2019-07-20T16:16:19Z

Thanks @zefer. Version 7 works fine for what we need here so far so no rush.

I updated the first message with more details. What puzzles me is that even after disabling config.performance_stats = false it had no effect. Please let me know if you need more information or any other test. Thank you!

zefer · 2019-07-25T12:28:52Z

Excellent, many thanks @rodolfobandeira, we'll update this as soon as possible.

kyrylo · 2019-07-29T17:33:07Z

Hey @rodolfobandeira, sorry to make you wait. Could you please test airbrake-ruby v4.5.1 and airbrake v9.4.0? There are some performance improvements which should reflect what you see on the graph.

I also strongly recommend to update your Airbrake config to log to log/airbrake.log. Please check this section to see an example: https://github.com/airbrake/airbrake#logging

This way it'll be easy to pinpoint issues with Airbrake. This is useful because previously we would log just to where Rails.logger logs, which makes things quite cluttered with our performance stats debug output.

By the way, I am not closing this issue just yet because we want to make sure that the problem is gone. There may be more performance improvements that we have to make and I would greatly appreciate your help here.

brunozrk · 2019-08-02T13:24:22Z

@kyrylo I was running with that versions (airbrake-ruby v4.5.1 and airbrake v9.4.0) with performance stats enabled and I noticed that the responses were slow, after rolling back to an old version (5.5.0), the response time came back to normal.

kyrylo · 2019-08-02T13:40:43Z

Thanks for testing @brunozrk. Could you specify what you consider slow and what difference we're talking about?

brunozrk · 2019-08-02T13:52:17Z

Looking at new relic:

Difference in ruby tab: roughly 150ms
Difference in mysql tab (I don't know why, but now is faster): 150ms

Likely fixes: * airbrake/airbrake#994 (Memory usage) * airbrake/airbrake#990 (CPU and Average Response increased after version 7) The SQL query collection feature is still in alpha and we display it only for certain accounts. Therefore, the vast majority of our customers cannot even see what airbrake-ruby collects. Since the feature is still in alpha, it is currently buggy (in a sense that it consumes too much memory & CPU power). I profiled a Rails app on a certain route with `memory_profiler` for Rack Mini Profiler and I can see a significant increase of memory usage. === performance_stats = false ``` Total allocated: 12434583 bytes (145711 objects) Total retained: 508023 bytes (3346 objects) allocated memory by gem 264 airbrake/lib ``` === performance_stats = true && query_stats = false ``` Total allocated: 12461685 bytes (146002 objects) Total retained: 508431 bytes (3353 objects) allocated memory by gem 3816 airbrake/lib ``` === performance_stats = true && query_stats = true ``` Total allocated: 186535107 bytes (1447037 objects) Total retained: 35810972 bytes (349882 objects) allocated memory by gem 709720 airbrake/lib ``` According to these reports memory usage ramped up by 700% compared to the route stats feature. The route stats feature itself is already quite expensive and the query collection feature is just too much.

Likely fixes: * #994 (Memory usage) * #990 (Add support for Rails engine route prefixes) More details in airbrake/airbrake-ruby#495. In short, this disables SQL query collection by default and allows enabling it only for certain accounts.

kyrylo · 2019-08-05T15:16:46Z

I released v9.4.1 with a fix. Could you guys take a look? The issue was that we accidentally run SQL query collection for your accounts as an alpha feature but you cannot even test see it because it's still in the works.

I believe v9.4.1 fixes your issues but I want to double check. Thanks a lot for your input and screenshots, it was a great help.

kyrylo · 2019-08-12T05:43:05Z

I'm closing this because I believe this is resolved but I still welcome any feedback of yours.

rodolfobandeira · 2020-06-26T17:23:11Z

Hi @kyrylo

I decided to try again upgrading the Airbrake gem. Today, deployed the latest version 10 instead of 8 like I did when this issue was created. This is what happened:

Here are the more details:

Ruby 2.6.6 (compiled with jemalloc)
Rails 5.2.4.3

    airbrake (10.0.5)
      airbrake-ruby (~> 4.13)
    airbrake-ruby (4.15.0)
  airbrake (~> 10.0, >= 10.0.5)

My main concern is that Airbrake would deprecate the version 7 at some point. We're also seeing a warning when we access the Airbrake portal saying we're running an outdated library version.

Do you have any recommendation?
Thank you

@brunozrk how's the situation over there? Any luck?

kyrylo · 2020-06-30T02:11:03Z

Hey @rodolfobandeira, on your screenshot it started spiking before your code was deployed (if I understood the screenshot correctly):

Do you have an explanation for this?

Do you guys run APM? You could try to disable it, deploy and see the effect:

Airbrake.configure do |c|
  c.performance_stats = false
end

If that detects an issue, you can flip the switch back to true (just delete the performance_stats option). Then, to further isolate the problematic code try disabling query_stats or job_stats.

Airbrake.configure do |c|
  c.query_stats = false
end

Airbrake.configure do |c|
  c.job_stats = false
end

I would really appreciate if you could test that. That will give me an idea where to look.

P.S. So far you are the only one who reported about this issue (and @brunozrk) :)

rodolfobandeira · 2020-06-30T20:58:56Z

Hi @kyrylo

The short spikes around ~75 ms and is comon in our application here. And as you can see, most of the big short spikes are related with database (yellow) mainly. Our deplyment process runs many different steps so the vertical line you can see doesn't represent the exact minute the servers switched to the new config. It might shift by few minutes.

The clear pattern for us is the avg line moving from ~75ms to 150ms only when the Airbrake > 7 gem is present. Here is another screenshot with what happened before, during and after:

As you could see, the latency is definitely around the ruby block. I'll try to get more info. I can't try this week though because we'll have some holidays here in Canada. I'll get back to you by next week. Also, I'm not sure if you get any more details from your backend, but our account with Airbrake is: nudgerewards.

Thanks again,
Rodolfo

kyrylo · 2020-07-01T04:37:28Z

Thanks for the update! Just a heads up, this is a public repo, you may edit out your account name.
Looking forward to see those results.

brunozrk · 2020-07-01T11:51:44Z

@rodolfobandeira unfortunately I didn't try an update after that event. And now im not able to test (I have just changed my job). Sorry

kyrylo · 2020-07-13T10:54:25Z

Gentle ping @rodolfobandeira

rodolfobandeira · 2020-07-25T13:09:24Z

I'm sorry we've been really busy here and we can't test this again in production once I already did and shared results here 3 times.

Keep in mind that your gem > version 7 is the issue to us here and was also identified for other user. This for me is a flag that there is a big issue affecting all your clients. Putting an effort to understand what is going on will help everyone. For us, is unacceptable to have a 2x increase in latency if we just upgrade Airbrake's gem.

Unfortunately, if we loose support for the version 7, we'll need to find another alternative.
Thank you

kyrylo · 2020-07-28T10:45:42Z

You can upgrade and set performance_stats = false since you don't use APM. That should resolve the problem. If you are looking into using APM I need to understand what exactly is slowing things down for you. If this is our SQL collection feature, then you can easily verify it by disabling it:

Airbrake.configure do |c|
  c.query_stats = false
end

This will give me a clue as to where to look for the problem.

kyrylo mentioned this issue Aug 5, 2019

Implement the "query_stats" option and disable it airbrake/airbrake-ruby#495

Merged

kyrylo mentioned this issue Aug 5, 2019

rails: install the ActiveRecord hook only when query_stats = true #995

Merged

kyrylo added Bug Rails labels Aug 5, 2019

kyrylo closed this as completed Aug 12, 2019

kyrylo reopened this Jun 30, 2020

scottsbaldwin assigned kyrylo Jul 15, 2020

kyrylo closed this as completed Jul 23, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

CPU and Average Response increased after version 7 #990

CPU and Average Response increased after version 7 #990

rodolfobandeira commented Jul 18, 2019 •

edited

zefer commented Jul 19, 2019

rodolfobandeira commented Jul 20, 2019 •

edited

zefer commented Jul 25, 2019

kyrylo commented Jul 29, 2019

brunozrk commented Aug 2, 2019 •

edited

kyrylo commented Aug 2, 2019

brunozrk commented Aug 2, 2019

kyrylo commented Aug 5, 2019

kyrylo commented Aug 12, 2019

rodolfobandeira commented Jun 26, 2020

kyrylo commented Jun 30, 2020

rodolfobandeira commented Jun 30, 2020 •

edited

kyrylo commented Jul 1, 2020

brunozrk commented Jul 1, 2020

kyrylo commented Jul 13, 2020

rodolfobandeira commented Jul 25, 2020

kyrylo commented Jul 28, 2020

CPU and Average Response increased after version 7 #990

CPU and Average Response increased after version 7 #990

Comments

rodolfobandeira commented Jul 18, 2019 • edited

zefer commented Jul 19, 2019

rodolfobandeira commented Jul 20, 2019 • edited

zefer commented Jul 25, 2019

kyrylo commented Jul 29, 2019

brunozrk commented Aug 2, 2019 • edited

kyrylo commented Aug 2, 2019

brunozrk commented Aug 2, 2019

kyrylo commented Aug 5, 2019

kyrylo commented Aug 12, 2019

rodolfobandeira commented Jun 26, 2020

kyrylo commented Jun 30, 2020

rodolfobandeira commented Jun 30, 2020 • edited

kyrylo commented Jul 1, 2020

brunozrk commented Jul 1, 2020

kyrylo commented Jul 13, 2020

rodolfobandeira commented Jul 25, 2020

kyrylo commented Jul 28, 2020

rodolfobandeira commented Jul 18, 2019 •

edited

rodolfobandeira commented Jul 20, 2019 •

edited

brunozrk commented Aug 2, 2019 •

edited

rodolfobandeira commented Jun 30, 2020 •

edited