coordination #71926
open[epic] t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally (but errors but still succeeds?), and no log output visible in circleCI
75%
Description
Observation¶
[14:37:26] t/14-grutasks.t ........................................... ok 274117 ms ( 0.22 usr 0.00 sys + 260.33 cusr 9.39 csys = 269.94 CPU)
but locally I have:
[21:33:58] t/14-grutasks.t .. 34/? [2020-09-26 21:34:04.39357] [15810] [error] Gru job error: No job ID specified.
[2020-09-26 21:34:04.44377] [15814] [error] Gru job error: Job 98765 does not exist.
[2020-09-26 21:34:04.51354] [15817] [error] Gru job error: Finalizing results of 1 modules failed
[21:33:58] t/14-grutasks.t .. ok 5976 ms ( 0.08 usr 0.01 sys + 3.34 cusr 0.90 csys = 4.33 CPU)
[21:34:04]
All tests successful.
Files=1, Tests=36, 6 wallclock secs ( 0.10 usr 0.01 sys + 3.34 cusr 0.90 csys = 4.35 CPU)
Result: PASS
so two differences: Insane long runtime within circleCI compared to just 6s locally but locally I have errors which do not fail the test. I can reproduce my local observations in 20 reruns with the same observation. I wonder if this is reproducible for anyone else. Comparably small runtime was confirmed by others.
Acceptance criteria¶
- AC1: No unhandled error messages in non-verbose output shown #73126
- AC2: Runtime within CI is comparable to local runtime, e.g. less than 30s #73129
Suggestions¶
- DONE:
Crosscheck locally if anyone can reproduce the observation from CI or my (okurz's) local onesame for others - If the error messages are expected, catch them with Test::Output, otherwise prevent them (or even better fail tests if there is any unexpected output)
- In case excessive runtime is reproducible in any environment, e.g. only within CI, with Devel::Cover, in a container, etc., then find a way to reduce runtime significantly
Updated by okurz about 4 years ago
- Status changed from Workable to Feedback
- Assignee set to okurz
Ok, found out the first part already: https://circle-production-customer-artifacts.s3.amazonaws.com/picard/58f7029dc9e77c000129905e/5f6df8cd2a301e095fa7ca33-0-build/artifacts/artifacts/14-grutasks.t?X-Amz-Algorithm=AWS4-HMAC-SHA256&X-Amz-Date=20200926T213349Z&X-Amz-SignedHeaders=host&X-Amz-Expires=60&X-Amz-Credential=AKIAJR3Q6CR467H7Z55A%2F20200926%2Fus-east-1%2Fs3%2Faws4_request&X-Amz-Signature=3248db1660d544b054e93e7ddb7f7e80ca9c066f312e1894f6b932712a3b4db6 shows that the artifact with the complete output has the error message included. This means that any unhandled output is not showing up in circleCI log output at all. I consider this bad and one more reason why the output redirection is flawed. With this I can handle the output using Test::Output
as normal: https://github.com/os-autoinst/openQA/pull/3427
This does not cover the excessive runtime part (yet).
Updated by okurz about 4 years ago
- Related to action #71464: Show output of failed tests within circleci log view, like on local prove calls, not only "Tests" tab added
Updated by okurz about 4 years ago
Created https://github.com/os-autoinst/openQA/pull/3428 to make sure unhandled output shows up in the circleci log view again.
Updated by kraih about 4 years ago
On my machine it takes 7 seconds.
ok
All tests successful.
Files=1, Tests=36, 7 wallclock secs ( 0.10 usr 0.03 sys + 2.70 cusr 2.06 csys = 4.89 CPU)
Result: PASS
Updated by livdywan about 4 years ago
okurz wrote:
[21:33:58] t/14-grutasks.t .. 34/? [2020-09-26 21:34:04.39357] [15810] [error] Gru job error: No job ID specified. [2020-09-26 21:34:04.44377] [15814] [error] Gru job error: Job 98765 does not exist. [2020-09-26 21:34:04.51354] [15817] [error] Gru job error: Finalizing results of 1 modules failed so two differences: Insane long runtime within circleCI compared to just 6s locally but locally I have errors which do not fail the test. I can reproduce my local observations in 20 reruns with the same observation. I wonder if this is reproducible for anyone else.
The above errors are present on the log in CircleCI.
It's 12 wallclock secs
for me.
Updated by okurz about 4 years ago
cdywan wrote:
The above errors are present on the log in CircleCI.
they are? Can you show me where?
It's
12 wallclock secs
for me.
ok, good. So as expected the problem is only within circleCI, maybe because of Devel::Cover?
Updated by livdywan about 4 years ago
okurz wrote:
cdywan wrote:
The above errors are present on the log in CircleCI.
they are? Can you show me where?
In 14-grutasks.t under Artifacts.
Updated by okurz about 4 years ago
The above errors are present on the log in CircleCI.
they are? Can you show me where?
In 14-grutasks.t under Artifacts.
Yes, correct. This is why I created https://github.com/os-autoinst/openQA/pull/3428 so that we have the same behaviour locally as within circleCI again regarding showing unhandled log output as well as failed test context.
Updated by okurz about 4 years ago
- Copied to action #73123: t/14-grutasks.t shows errors but still succeeds added
Updated by okurz about 4 years ago
- Copied to action #73126: No tests show unhandled output in main test summary log added
Updated by okurz about 4 years ago
- Copied to action #73129: t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally added
Updated by okurz about 4 years ago
- Subject changed from t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally (but errors but still succeeds?) to [epic] t/14-grutasks.t takes multiple minutes within circleCI, only 6s locally (but errors but still succeeds?), and no log output visible in circleCI
- Description updated (diff)
- Status changed from Feedback to Blocked
- Priority changed from High to Low
PR merged. https://app.circleci.com/pipelines/github/os-autoinst/openQA/4451/workflows/2ba463f6-0465-47ae-b4a5-9c8022eef418/jobs/42666/steps is one example showing that we again have useful output. So we are ready to start with the actual work but I think it's easier if we make that in specific subtasks so that people are better motivated and know when they are done. Tracked in subtasks created.
Updated by okurz about 4 years ago
- Description updated (diff)
- Target version deleted (
Ready)
Updated by szarate about 4 years ago
- Tracker changed from action to coordination
- Status changed from Blocked to New
Updated by szarate about 4 years ago
See for the reason of tracker change: http://mailman.suse.de/mailman/private/qa-sle/2020-October/002722.html
Updated by okurz about 4 years ago
- Status changed from Blocked to Workable
- Assignee deleted (
okurz) - Target version changed from Ready to future
see subtask (in future)