Add expected rspec duration
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
- We will print the test group's expected duration next to the actual duration. For example:
( 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.
-
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.
-
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:
- 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.
- Fixed the bug with expected duration not able to find.
- Now we are initializing the expected duration report in the
start
hook, so theJSON.parse
method is called only once. - 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.
-
I have evaluated the MR acceptance checklist for this MR.