Massive performance degragation 3.0 -> 3.0.2

mscrivo commented 3 months ago

After upgrading from 3.0 to 3.0.2, we notice crashes during startup in our test environment. The pods were using an order of magnitude more CPU on startup than before. Upon profiling, we saw this:

Time since start: 13s. Press Ctrl+C to stop.
Summary of profiling data so far:
% self  % total  name
 90.78    90.78  initialize [c function] - (unknown)
  1.55     1.55  initialize_pattern - /usr/local/lib/ruby/3.3.0/uri/rfc2396_parser.rb:493
  1.38    93.02  initialize_regexp - /usr/local/lib/ruby/3.3.0/uri/rfc2396_parser.rb:525
  1.03    99.31  new [c function] - (unknown)
  0.69     0.69  split [c function] - (unknown)
  0.60     0.86  each_value [c function] - (unknown)
  0.34    99.48  each [c function] - (unknown)
  0.34     0.34  freeze [c function] - (unknown)
  0.34     0.34  compile_file [c function] - (unknown)
  0.26    97.93  translate - /home/app/vendor/bundle/ruby/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:117
  0.26    95.78  initialize - /usr/local/lib/ruby/3.3.0/uri/rfc2396_parser.rb:107
  0.17    97.93  t - /home/app/vendor/bundle/ruby/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:43
  0.17    97.16  map [c function] - (unknown)
  0.17     0.17  sysread_nonblock [c function] - (unknown)
  0.17     0.17  select [c function] - (unknown)
  0.17     0.17  count_objects [c function] - (unknown)
  0.09    99.31  inject [c function] - (unknown)
  0.09    96.21  escape - /home/app/vendor/bundle/ruby/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:124
  0.09     0.43  fetch [c function] - (unknown)
  0.09     0.17  each_byte [c function] - (unknown)

and this is what our CPU usage looked like before, after upgrade, and after reverting:

We don't use mustermann explicitly, just implicitly via usage of sinatra.

Some notes about our env:

Ruby 3.3.3 with YJIT enabled running in x64 docker image latest Sinatra + Puma versions

dentarg commented 3 months ago

@hsbt any idea?

hsbt commented 3 months ago

I will look at next week.

dentarg commented 3 months ago

@mscrivo do you see the same without YJIT? How does 3.3.4 behave?

mscrivo commented 3 months ago

Ah I misspoke, we're already using 3.3.4. I'll have to put together a test with the new version and YJIT disabled, or try and see if I can repro on my dev machine. Will let you know if I have anything interesting to share on that front.

travisbell commented 3 months ago

Just chiming in that we also have this problem with 3.0.2, so I've locked things to 3.0.1 until 3.0.3 is released.

ericproulx commented 2 months ago

I've noticed the same issue within Grape which depends on mustermann-grape. While profiling some code, I found that the memory allocation skyrocketed from 2.0.2 to 3.0.2

mustermann 2.0.2
Total allocated: 13844660 bytes (151009 objects)
Total retained:  478500 bytes (1419 objects)

mustermann 3.0.0
Total allocated: 13844660 bytes (151009 objects)
Total retained:  478500 bytes (1419 objects)

mustermann 3.0.1
Total allocated: 112875956 bytes (312625 objects)
Total retained:  478500 bytes (1419 objects)

mustermann 3.0.2
Total allocated: 310938548 bytes (635857 objects)
Total retained:  478500 bytes (1419 objects)

allocated memory by location
-----------------------------------
46772544  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:504
36381072  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:500
33332208  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:501
22451520  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:505
21656544  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:506
12544896  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:515
10015824  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:520
9832368  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:451
8290464  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:519
6473376  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:453
5346432  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:473
5263440  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:517
5136768  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:448
4599504  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:521
4599504  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:522
4590768  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:446
4333056  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:339
4333056  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:497
4018560  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:441
3922464  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:518
3900624  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:514
3524976  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:513
3468192  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:510
2891616  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:516
2856672  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:509
2795520  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:419
2795520  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:424
2795520  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:438
2321000  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:106
1397760  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:388
1397760  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:394
1397760  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:398
1397760  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:402
1397760  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:416
1397760  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:434
1397760  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:436
990720  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/parser.rb:129
931840  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:292
731240  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:42
698880  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:386
698880  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:414
698880  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:443
698880  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:99
582400  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/compiler.rb:17
570752  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:123
511489  /Users/eproulx/code/grape/lib/grape/router/base_route.rb:26
467344  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:108
432840  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/compiler.rb:129
411480  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/mustermann-3.0.2/lib/mustermann/ast/translator.rb:114
349440  /Users/eproulx/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/uri-0.13.1/lib/uri/rfc2396_parser.rb:296

You can execute a complete memory profiler from this script

require 'grape'
require 'memory_profiler'

class API < Grape::API
  default_format :json

  params do
    requires :name, allow_blank: false
  end
  get '/disallow_blank'

  params do
    optional :name, type: String, allow_blank: false
  end
  get '/opt_disallow_string_blank'

  params do
    optional :name, allow_blank: false
  end
  get '/disallow_blank_optional_param'

  params do
    requires :name, allow_blank: true
  end
  get '/allow_blank'

  params do
    requires :val, type: DateTime, allow_blank: true
  end
  get '/allow_datetime_blank'

  params do
    requires :val, type: DateTime, allow_blank: false
  end
  get '/disallow_datetime_blank'

  params do
    requires :val, type: DateTime
  end
  get '/default_allow_datetime_blank'

  params do
    requires :val, type: Date, allow_blank: true
  end
  get '/allow_date_blank'

  params do
    requires :val, type: Integer, allow_blank: true
  end
  get '/allow_integer_blank'

  params do
    requires :val, type: Float, allow_blank: true
  end
  get '/allow_float_blank'

  params do
    requires :val, type: Integer, allow_blank: true
  end
  get '/allow_integer_blank'

  params do
    requires :val, type: Symbol, allow_blank: true
  end
  get '/allow_symbol_blank'

  params do
    requires :val, type: Grape::API::Boolean, allow_blank: true
  end
  get '/allow_boolean_blank'

  params do
    requires :val, type: Grape::API::Boolean, allow_blank: false
  end
  get '/disallow_boolean_blank'

  params do
    optional :user, type: Hash do
      requires :name, allow_blank: false
    end
  end
  get '/disallow_blank_required_param_in_an_optional_group'

  params do
    optional :user, type: Hash do
      requires :name, type: Date, allow_blank: true
    end
  end
  get '/allow_blank_date_param_in_an_optional_group'

  params do
    optional :user, type: Hash do
      optional :name, allow_blank: false
      requires :age
    end
  end
  get '/disallow_blank_optional_param_in_an_optional_group'

  params do
    requires :user, type: Hash do
      requires :name, allow_blank: false
    end
  end
  get '/disallow_blank_required_param_in_a_required_group'

  params do
    requires :user, type: Hash do
      requires :name, allow_blank: false
    end
  end
  get '/disallow_string_value_in_a_required_hash_group'

  params do
    requires :user, type: Hash do
      optional :name, allow_blank: false
    end
  end
  get '/disallow_blank_optional_param_in_a_required_group'

  params do
    optional :user, type: Hash do
      optional :name, allow_blank: false
    end
  end
  get '/disallow_string_value_in_an_optional_hash_group'

  resources :custom_message do
    params do
      requires :name, allow_blank: { value: false, message: 'has no value' }
    end
    get

    params do
      optional :name, allow_blank: { value: false, message: 'has no value' }
    end
    get '/disallow_blank_optional_param'

    params do
      requires :name, allow_blank: true
    end
    get '/allow_blank'

    params do
      requires :val, type: DateTime, allow_blank: true
    end
    get '/allow_datetime_blank'

    params do
      requires :val, type: DateTime, allow_blank: { value: false, message: 'has no value' }
    end
    get '/disallow_datetime_blank'

    params do
      requires :val, type: DateTime
    end
    get '/default_allow_datetime_blank'

    params do
      requires :val, type: Date, allow_blank: true
    end
    get '/allow_date_blank'

    params do
      requires :val, type: Integer, allow_blank: true
    end
    get '/allow_integer_blank'

    params do
      requires :val, type: Float, allow_blank: true
    end
    get '/allow_float_blank'

    params do
      requires :val, type: Integer, allow_blank: true
    end
    get '/allow_integer_blank'

    params do
      requires :val, type: Symbol, allow_blank: true
    end
    get '/allow_symbol_blank'

    params do
      requires :val, type: Grape::API::Boolean, allow_blank: true
    end
    get '/allow_boolean_blank'

    params do
      requires :val, type: Grape::API::Boolean, allow_blank: { value: false, message: 'has no value' }
    end
    get '/disallow_boolean_blank'

    params do
      optional :user, type: Hash do
        requires :name, allow_blank: { value: false, message: 'has no value' }
      end
    end
    get '/disallow_blank_required_param_in_an_optional_group'

    params do
      optional :user, type: Hash do
        requires :name, type: Date, allow_blank: true
      end
    end
    get '/allow_blank_date_param_in_an_optional_group'

    params do
      optional :user, type: Hash do
        optional :name, allow_blank: { value: false, message: 'has no value' }
        requires :age
      end
    end
    get '/disallow_blank_optional_param_in_an_optional_group'

    params do
      requires :user, type: Hash do
        requires :name, allow_blank: { value: false, message: 'has no value' }
      end
    end
    get '/disallow_blank_required_param_in_a_required_group'

    params do
      requires :user, type: Hash do
        requires :name, allow_blank: { value: false, message: 'has no value' }
      end
    end
    get '/disallow_string_value_in_a_required_hash_group'

    params do
      requires :user, type: Hash do
        optional :name, allow_blank: { value: false, message: 'has no value' }
      end
    end
    get '/disallow_blank_optional_param_in_a_required_group'

    params do
      optional :user, type: Hash do
        optional :name, allow_blank: { value: false, message: 'has no value' }
      end
    end
    get '/disallow_string_value_in_an_optional_hash_group'
  end
end

report = MemoryProfiler.report do
  API.compile!
end

report.pretty_print

dentarg commented 2 months ago

Anyone in this thread that want this fixed please help at https://github.com/sinatra/mustermann/pull/141#discussion_r1729532052

dentarg commented 2 months ago

v3.0.3 released with fix, please report back if it has resolved your issues!

ericproulx commented 2 months ago

It resolved our issue :)

sinatra / mustermann

Massive performance degragation 3.0 -> 3.0.2 #140