Really slow formatting performance for a specific piece of code

[valscion]

Metadata

• Operating system: macOS
• Ruby version: 2.7.5
• Node version: v16.13.0
• @prettier/plugin-ruby version: v3.2.0
• syntax_tree version: 3.2.1

Input

# frozen_string_literal: true
class SitemapWorker
  include Sidekiq::Worker
  include Rails.application.routes.url_helpers

  DEFAULT_OPTIONS = { ping_search_engines: Rails.env.production? }.freeze

  def perform(options = {})
    options = DEFAULT_OPTIONS.with_indifferent_access.merge(options)

    sites_grouped_by_domain = Site.group_by(&:domain)

    sites_grouped_by_domain.each do |domain, grouped_sites|
      SitemapGenerator::Sitemap.create(
        default_host: SitemapGenerator::DefaultLocationOptions.host(domain),
        sitemaps_path:
          SitemapGenerator::DefaultLocationOptions.sitemaps_path(domain),
        # Disable automatically adding root page, as sites under venuu.com have special front pages
        include_root: false
      ) do
        grouped_sites.each do |site|
          Site.with_current(site) do
            I18n.with_locale(site.locale) do
              #
              # The sitemap index file is added automatically for you.
              # Links are added to the Sitemap in the order they are specified.
              #
              # Usage: add(path, options={})
              #        (default options are used if you don't specify)
              #
              # Defaults: priority: 0.5, changefreq: :weekly,
              #           lastmod: Time.now, host: default_host
              #

              add root_path, changefreq: :always, priority: 1.0

              add venues_path, changefreq: :daily

              if FeatureToggle.on?(:catering_profiles)
                add catering_search_path, changefreq: :daily
              end

              if FeatureToggle.on?(:supplier_profiles)
                ::Search::SupplierSearchTopLevelCategory
                  .all
                  .visibility_public
                  .includes(:string_translations)
                  .find_each do |top_cat|
                    add(
                      search_suppliers_path(category: top_cat.slug),
                      changefreq: :daily
                    )

                    # Ignore sub-categories which don't have any SEO content
                    # to avoid Google punishing us for duplicate content too much
                    top_cat
                      .sub_categories
                      .with_mobility
                      .where.not(
                        ingress: [nil, ""],
                        description_heading: [nil, ""],
                        description_content: [nil, ""]
                      )
                      .includes(:string_translations)
                      .each do |sub_cat|
                        add(
                          search_suppliers_path(
                            category: top_cat.slug,
                            sub_category: sub_cat.slug
                          ),
                          changefreq: :daily
                        )
                      end
                  end
              end

              venues = Pundit.policy_scope(UserContext.new, Venue.in_site(site))
              venues.find_each do |venue|
                add profiles_venue_profile_path(venue),
                    lastmod: venue.updated_at,
                    priority: 0.8
              end

              add new_venue_owner_registration_path, priority: 0.5

              if FeatureToggle.on?(:static_pages)
                add about_path, priority: 0.3
                add about_contact_details_path, priority: 0.2
              end

              LandingPage
                .in_site(site)
                .each do |landing_page|
                  add landing_page.canonical_path, priority: 0.5
                end

              if FeatureToggle.on?(:supplier_profiles)
                supplier_profiles =
                  Pundit.policy_scope(
                    UserContext.new,
                    ::Profiles::SupplierProfile.all
                  )
                supplier_profiles.find_each do |profile|
                  add profiles_supplier_profile_path(profile),
                      lastmod: profile.updated_at,
                      priority: 0.8
                end
              end

              if FeatureToggle.on?(:catering_profiles)
                # TODO: Limit to `Catering::Profile.in_site(Site.current)` when profiles are Siteable
                catering_profiles =
                  Pundit.policy_scope(UserContext.new, Catering::Profile.all)
                catering_profiles.find_each do |profile|
                  add profiles_catering_profile_path(profile),
                      lastmod: profile.updated_at,
                      priority: 0.8
                end
              end

              if FeatureToggle.on?(:catering_profiles)
                CateringLandingPage
                  .in_site(site)
                  .each do |landing_page|
                    add landing_page.canonical_path, priority: 0.5
                  end
              end

              if FeatureToggle.on?(:catering_partner_landing_page)
                add catering_list_your_service_path
              end

              if FeatureToggle.on?(:supplier_partner_landing_page)
                add partner_inbound_list_your_event_service_path
              end
            end
          end
        end
      end

      # Ping search engines for each group of sites one time.
      if options[:ping_search_engines]
        Site.with_current(grouped_sites.first) do
          SitemapGenerator::Sitemap.ping_search_engines
        end
      end
    end
  end
end

Expected result

We expect the file to be formatted within one second

Actual result

Running formatting on this file takes a whopping 22 seconds — last run took 22341ms!

Additional details

We're upgrading from @prettier/plugin-ruby v2.1.0 to v3.2.0. Previously formatting this file took around 915ms.

We want to keep using Prettier via Yarn, so we don't want to start using bundle exec rbprettier. That's why we're formatting files with

yarn prettier --write

and have added the prettier_print and syntax_tree gems to Gemfile to make it work.

We also get plenty of experimental pattern match usage warnings now:

/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:609: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:1147: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:1406: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2125: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2252: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2355: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2380: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2426: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2452: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2468: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2478: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2505: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2610: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2773: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:2975: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:3070: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:5200: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:5191: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/node.rb:5359: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/parser.rb:556: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/parser.rb:1517: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-3.2.1/lib/syntax_tree/parser.rb:1943: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-haml-1.3.0/lib/syntax_tree/haml.rb:57: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-haml-1.3.0/lib/syntax_tree/haml/format.rb:381: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!
/Users/vesa/.rbenv/versions/2.7.5/lib/ruby/gems/2.7.0/gems/syntax_tree-haml-1.3.0/lib/syntax_tree/haml/format.rb:403: warning: Pattern matching is experimental, and the behavior may change in future versions of Ruby!

We've silenced them by adding RUBYOPT='-W:no-experimental' environment flag to various places where Prettier ends up being ran.

[kddnewton]

Interesting... this looks like it has to do with call chain formatting. If I turn that off it formats in half a second. I'll take a look.

[hulloitskai]

Hi @kddnewton, did you get a chance to look at this yet? Any insights that you might have that would help a new contributor unfamiliar with this codebase to take a stab at the issue would be appreciated too!

[kddnewton]

I haven't had the time yet. It looks like the issue is somewhere in the call chain formatter (https://github.com/ruby-syntax-tree/syntax_tree/blob/066dc61237900341dfda7ce165ce870b0ec2bb83/lib/syntax_tree/node.rb#L2339). If I comment out the part that checks if it's a call chain, it's an expected speed.

[valscion]

Here's a minimalized reproduction that still shows the slow formatting performance. This code is formatted in ~20 seconds on my machine:

# If we remove any block here, the time to format
# goes from ~20 seconds to ~10 seconds or less, no matter
# which level the block is removed from.
#
# Same is true if some of the blocks do not have method calls
# before the `do`

lorem.each do
  ipsum.create do
    dolor.each do
      sit.map do
        amet.with_more_stuff do
          consectetur
            .here_we_need_at_least
            .two_chained_method_calls do
              adipiscing.each do
                elit.then do
                  aenean.map do
                    puts convallis
                  end
                end
              end
            end
        end
      end
    end
  end
end

[valscion]

Actually looks like it doesn't even matter whether there are multiple chained method calls. The formatting time seems to grow exponentially the more blocks I add inside each other. For example, this even smaller reproduction takes ~40 seconds to format!

one.call do
  two.call do
    three.call do
      four.call do
        five.call do
          six.call do
            seven.call do
              eight.call do
                nine.call do
                  ten.call do
                    eleven
                  end
                end
              end
            end
          end
        end
      end
    end
  end
end

The way I ran these numbers was with a simple yarn prettier command, coupled with time, like so:

$ time yarn prettier path/to/test_file.rb > /dev/null
yarn prettier path/to/test_file.rb > /dev/null  0.71s user 0.13s system 2% cpu 39.854 total

If I remove one level of block calls there, formatting is done in ~10 seconds:

one.call do
  two.call do
    three.call do
      four.call do
        five.call do
          six.call do
            seven.call do
              eight.call do
                nine.call do
                  ten
                end
              end
            end
          end
        end
      end
    end
  end
end

And if I remove one more, formatting is done in ~4 seconds:

one.call do
  two.call do
    three.call do
      four.call do
        five.call do
          six.call do
            seven.call do
              eight.call do
                nine
              end
            end
          end
        end
      end
    end
  end
end

And one more and we get to ~2.4 seconds:

one.call do
  two.call do
    three.call do
      four.call do
        five.call do
          six.call do
            seven.call do
              eight
            end
          end
        end
      end
    end
  end
end

Here we are at 1.8 seconds:

one.call do
  two.call do
    three.call do
      four.call do
        five.call do
          six.call do
            seven
          end
        end
      end
    end
  end
end

...and at this point, I suppose my naïve benchmarking script needs to do too much work, as even this one runs in 1.6 seconds:

one.call do
  two
end

[valscion]

The results seem to be similar if I remove .call call chain, as this one also runs in ~11 seconds:

one.call do
  two.call do
    three.call do
      four.call do
        five.call do
          six.call do
            seven.call do
              eight.call do
                nine do
                  ten do
                    eleven
                  end
                end
              end
            end
          end
        end
      end
    end
  end
end

So removing two .call while keeping same indentation goes from ~40 seconds to ~11 seconds. So this indeed has got something to do with call chain formatting

[kddnewton]

@valscion this is not yet fixed, but you can turn off the deeply nested behavior by setting the STREE_FAST_FORMAT=1 environment variable. Obviously it's not a long-term solution, but it should alleviate this for now until a better solution is found.

[kddnewton]

@valscion I'm going to track this over in syntax tree since that's the source of the issue.

[jscheid]

@kddnewton just making sure that this is still being tracked, considering all related issues seem to be closed? It's still a problem with 4.0.4. One of our files takes 2 minutes to format for ~300 LOC.

Setting STREE_FAST_FORMAT=1 does help but is difficult to configure reliably in all environments (on our team we're using multiple editor plugins.) If there's no solution around the corner, could we have a setting in .prettierrc for this?

[kddnewton]

This is being solved by a rewrite of the parsing backend that is currently ongoing. It will happen, I promise, but it's taking longer than anticipated