Server-Timings reported for partials are incorrect (too high) when nested partials are used

Server Timings reported for partials are longer than the entire request as reported by the browser.

Steps to reproduce

1. Use an endpoint with a lot of nested-partials.
2. Look at server timings in browser network tabs
3. Observe that the timing for render_partial.action_view is longer than the entire duration the browser reports for the request.
4. Observe that the timing for render_partial.action_view is longer than the duration reported in the Rails log

Example: Rails might report Completed 200 OK in 2796ms but in the Server-Timings you'll see a higher number for render_partial.action_view such as 3725.8ms

Note: the test-case requires views. Please see the repo https://github.com/tgaff/rails-server-timing-issue-demo/tree/main/executable_test_case or add your own views.

# frozen_string_literal: true

require "bundler/inline"

gemfile(true) do
  source "https://rubygems.org"

  git_source(:github) { |repo| "https://github.com/#{repo}.git" }

  # gem "rails", github: "rails/rails", branch: "main"
  gem "rails", '=7.0.4.3'
  gem "rack", "~> 2.0"
  gem "debug", platforms: %i[ mri mingw x64_mingw ]
  gem "pry"
end

require "action_controller/railtie"

class TestApp < Rails::Application
  config.root = __dir__
  config.hosts << "example.org"
  secrets.secret_key_base = "secret_key_base"
  config.server_timing = true

  config.logger = Logger.new($stdout)
  Rails.logger  = config.logger

  routes.draw do
    get "/nested" => "test#nested"
    get "/not_nested" => "test#not_nested"
  end
end

class TestController < ActionController::Base
  include Rails.application.routes.url_helpers

  def nested
    self.append_view_path('./views')
    @nesting = true
    render 'index'
  end

  def not_nested
    self.append_view_path('./views')
    @nesting = false
    render 'index'
  end
end

require "minitest/autorun"
require "rack/test"

class ServerTimingBugTest < Minitest::Test
  include Rack::Test::Methods

  def test_nested_response_ok
    get "/nested"
    assert last_response.ok?
  end

  def test_nested_partial_timing_less_than_total_controller
    get "/nested"
    assert_operator render_partial_timing_dur, :<, process_action_timing_dur, "partial rendering should be less than total action time"
  end

  def test_not_nested_response_ok
    get "/not_nested"
    assert last_response.ok?
  end

  def test_not_nested_partial_timing_less_than_total_controller
    get "/not_nested"
    assert_operator render_partial_timing_dur, :<, process_action_timing_dur, "partial rendering should be less than total action time"
  end

  private
    def app
      Rails.application
    end

    def reported_server_timings
      last_response.headers["Server-Timing"]
    end

    def reported_timing_durations
      timings = {}
      reported_server_timings.split(',').each do |entry|
        k, almost_v = entry.strip.split(';')
        timings[k.strip] = almost_v.delete('dur=').to_f
      end
      timings
    end

    def render_partial_timing_dur
      reported_timing_durations['render_partial.action_view']
    end

    def process_action_timing_dur
      reported_timing_durations['process_action.action_controller']
    end
end

This is a little easier to understand in the browser where you can easily see the entire request time. As such I've uploaded a demo app: https://github.com/tgaff/rails-server-timing-issue-demo The executable test case is also in that repo in a sub-directory.

Expected behavior

• Server-timings reported for partials should be accurate.
• Server-timings reported for partials should be less than the total request time.

Actual behavior

• Server timings reported to chrome, when partials are involved indicate a longer duration than the entirety of the request.

System configuration

Rails version: 7.0.4.3 && main Ruby version: 3.2.0

screenshot

Note in the above request:

• the browser says the request took 13.70 seconds.
• server reported that partials took 23.39 seconds.

other info / commentary

• I'm aware of https://github.com/rails/rails/issues/41452 and believe this is a separate issue.
• My guess is that if _a render's partial _b, then the timing info for _a includes _b's render time, but _b's timing is also added in the final sum.
• Reproducible with logging turned off (ActionView::Base.logger = nil)
• Manual wristwatch verification of browser total time shows it to be correct-ish.
• Partials aren't processed in parallel are they?