Skip to content

Add expected rspec duration

Jennifer Li requested to merge jennli-rspec-runtime-it3 into master

What does this MR do and why?

Iteration 3: Improve rspec run time output in job stacktrace with the following changes:

Description for initial code review. Outdated info - collapsed
  1. We will print the test group's expected duration next to the actual duration. For example:

( 😀 I am aware of the Rspect typo, sorry)

# [RSpecRunTime] Starting example group ./spec/services/packages/nuget/sync_metadatum_service_spec.rb. Missing expected duration from Knapsack report.
Packages::Nuget::SyncMetadatumService
  #execute
    creates a nuget metadatum
    behaves like saving metadatum attributes
      saves nuget metadatum
# [RSpectRunTime] behaves like saving metadatum attributes finished. RSpec elapsed time: 4 minutes 58.02 seconds
    with exisiting nuget metadatum
      does not create a nuget metadatum
      behaves like saving metadatum attributes
        saves nuget metadatum
# [RSpectRunTime] behaves like saving metadatum attributes finished. RSpec elapsed time: 4 minutes 58.92 seconds
      with empty metadata
        destroys the nuget metadatum
# [RSpectRunTime] with empty metadata finished. RSpec elapsed time: 4 minutes 58.96 seconds
# [RSpectRunTime] with exisiting nuget metadatum finished. RSpec elapsed time: 4 minutes 58.97 seconds
    with metadata containing only authors and description
      updates the nuget metadatum
# [RSpectRunTime] with metadata containing only authors and description finished. RSpec elapsed time: 4 minutes 59.02 seconds
    with too long metadata
      truncates authors and description to the maximum length and logs its info
# [RSpectRunTime] with too long metadata finished. RSpec elapsed time: 4 minutes 59.25 seconds
# [RSpectRunTime] #execute finished. RSpec elapsed time: 4 minutes 59.25 seconds
# [RSpecRunTime] Example group Packages::Nuget::SyncMetadatumService (./spec/services/packages/nuget/sync_metadatum_service_spec.rb) took 2.49 seconds. Missing expected duration from Knapsack report.
# [RSpecRunTime] RSpec elapsed time: 4 minutes 59.31 seconds.

Note, I'm not sure why the expected duration info is missing for all specs so I'm still debugging this.

  1. In addition to printing the rspec run time after every level 0 test group - level 0 meaning they are on the outer most level of an rspec file - we will also print the elapse after each inner test group executes. This way, if a test group consists of multiple subgroups and is taking a large amount of time to finish, we'll have more visibility into which subgroup took the most time.

  2. Add a start-of-test-group marker output # [RSpecRunTime] Starting example group .. before a test group start to indicate the test group's file path, in case the job times out running this test group, we can easily spot in the job stacktrace which file is the culprit.

Re: gitlab-org/quality/engineering-productivity/team#323 (closed)

Update since the last code review

See this latest example: https://gitlab.com/gitlab-org/gitlab/-/jobs/5707720611

# [RSpecRunTime] Starting example group ee/spec/lib/gitlab/background_migration/create_vulnerability_links_spec.rb. Expected to take 1 minute 44.59 seconds.
Gitlab::BackgroundMigration::CreateVulnerabilityLinks
  #perform
    for vulnerability feedback issues
      when a Finding has no Vulnerability
        creates a Vulnerability from the Vulnerabilities::Finding
        behaves like when there was a problem saving the Vulnerability
          doesn't create a Vulnerability record
          logs an error
        when the feedback is associated with a non-existent issue
          doesn't create a Vulnerability record
# [RSpecRunTime] RSpec elapsed time: 20.13 seconds.
        behaves like a migration creating a vulnerability issue link
          creates a Vulnerabilities::IssueLink from the Vulnerabilities::Feedback
# [RSpecRunTime] RSpec elapsed time: 24.25 seconds.
      when there's only a Security::Finding
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
        creates a Vulnerability from the Security::Finding
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
        creates a Vulnerabilities::IssueLink from the Vulnerabilities::Feedback
        behaves like when creating any associated record fails
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
          doesn't create a Vulnerability record
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
          logs an error
# [RSpecRunTime] RSpec elapsed time: 42.15 seconds.
      when there is a vulnerability
        behaves like when the link is invalid
          doesn't create a IssueLink
          logs an error
# [RSpecRunTime] RSpec elapsed time: 49.81 seconds.
        behaves like a migration creating a vulnerability issue link
          creates a Vulnerabilities::IssueLink from the Vulnerabilities::Feedback
# [RSpecRunTime] RSpec elapsed time: 53.57 seconds.
    for vulnerability feedback merge requests
      when a Finding has no Vulnerability
        creates a Vulnerability from the Vulnerabilities::Finding
        behaves like when there was a problem saving the Vulnerability
          doesn't create a Vulnerability record
          logs an error
# [RSpecRunTime] RSpec elapsed time: 1 minute 5.8 seconds.
        when the feedback is associated with a non-existent merge request
          doesn't create a Vulnerability record
# [RSpecRunTime] RSpec elapsed time: 1 minute 9.49 seconds.
        behaves like a migration creating a vulnerability merge request link
          creates a Vulnerabilities::MergeRequestLink from the Vulnerabilities::Feedback
# [RSpecRunTime] RSpec elapsed time: 1 minute 13.61 seconds.
      when there's only a Security::Finding
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
        creates a Vulnerability from the Security::Finding
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
        creates a Vulnerabilities::MergeRequestLink from the Vulnerabilities::Feedback
        behaves like when creating any associated record fails
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
          doesn't create a Vulnerability record
WARNING: Active Record does not support composite primary key.
security_findings has composite primary key. Composite primary key is ignored.
          logs an error
# [RSpecRunTime] RSpec elapsed time: 1 minute 30.17 seconds.
      when there is a vulnerability
        behaves like when the link is invalid
          doesn't create a MergeRequestLink
          logs an error
# [RSpecRunTime] RSpec elapsed time: 1 minute 37.53 seconds.
        behaves like a migration creating a vulnerability merge request link
          creates a Vulnerabilities::MergeRequestLink from the Vulnerabilities::Feedback
# [RSpecRunTime] RSpec elapsed time: 1 minute 41.35 seconds.
# [RSpecRunTime] ee/spec/lib/gitlab/background_migration/create_vulnerability_links_spec.rb took 1 minute 46.61 seconds.Expected to take 1 minute 44.59 seconds.

Made the following changes since the last review:

  1. Print elapsed time after each inner-example group, only if it was last printed more than 1 second ago. We have a lot of fast example groups that take less than 1 second to run, so we omit the elapase time for them to keep the output as minimal as we can.
  2. Fixed the bug with expected duration not able to find.
  3. Now we are initializing the expected duration report in the start hook, so the JSON.parse method is called only once.
  4. I also removed the test group description, and only print the file path, because we just need one.

Screenshots or screen recordings

Screenshots are required for UI changes, and strongly recommended for all other merge requests.

Before After

How to set up and validate locally

Numbered steps to set up and validate the change are strongly suggested.

MR acceptance checklist

This checklist encourages us to confirm any changes have been analyzed to reduce risks in quality, performance, reliability, security, and maintainability.

Edited by Peter Leitzen

Merge request reports