Emit metric to track null build latency #337

imjasonh · 2018-09-05T23:20:25Z

Proposed Changes

Optionally emit a metric that tracks how long a simple no-op build takes to schedule, execute and finish watching. This should help us identify serious latency regressions that might affect all builds.

TODO

I'm pretty sure there's more I need to do here, to get these metrics displayed at http://testgrid.knative.dev/knative-build -- like knative/serving has. I'm not sure if that change happens in this repo somehow/somewhere, or in whatever config powers testgrid. /cc @jessiezcc

Release Note

NONE

/hold

knative-prow-robot · 2018-09-05T23:20:31Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: ImJasonH

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~test/OWNERS~~ [ImJasonH]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

adrcunha · 2018-09-05T23:26:33Z

Once this is in it's just a matter of creating an aggregation job and a testgrid config. ;)

imjasonh · 2018-09-06T14:44:06Z

Once this is in it's just a matter of creating an aggregation job and a testgrid config. ;)

@adrcunha does this mean this PR can be submitted as-is? Is this really all that's necessary to start emitting metrics? 🤞

adrcunha · 2018-09-06T17:26:19Z

Yes, this PR is mostly done. But I would run e2e-tests.sh --emit-metrics locally to make sure it's logging the metric you want. Then, like I said, it's just a matter of adding a job to Prow and a display config to testgrid (file an issue and assign it to me).

imjasonh · 2018-09-07T00:21:36Z

@adrcunha Am I supposed to see the metric data in logs?

$ EMIT_METRICS=1 ./test/e2e-tests.sh
...snip...
==============================
==== RUNNING GO E2E TESTS ====
==============================
ok  	github.com/knative/build/test/e2e	38.923s
================================
==== RUNNING YAML E2E TESTS ====
================================
...snip...

I don't see metrics data in logs when I run knative/serving's e2e-tests.sh either, but it's possible I'm just missing something.

adrcunha · 2018-09-07T02:08:41Z

Yes. But don't set the environment variable, use the --emit-metrics flag I mentioned.

imjasonh · 2018-09-11T18:43:40Z

@adrcunha I'm apparently unable to run e2e tests locally now, with or without the flag. Getting:

Error from server (Forbidden): clusterrolebindings.rbac.authorization.k8s.io is forbidden: User "system:anonymous" cannot create clusterrolebindings.rbac.authorization.k8s.io at the cluster scope: Unknown user "system:anonymous"

(This happens on this branch, and on a fresh checkout from master)

Any idea what I may have done to get into this state? I thought the script started from scratch each time, is it possible some of my local config has crept in somehow? Prow seems to be able to run the tests just fine.

adrcunha · 2018-09-11T19:14:17Z

I thought #286 was closed, let me take a look.

imjasonh · 2018-09-14T20:47:51Z

After rebasing to pick up the fix for #286 I ran ./test/e2e-tests.sh --emit-metrics and saw:

...
==============================
==== RUNNING GO E2E TESTS ====
==============================
ok          github.com/knative/build/test/e2e       303.314s
================================
==== RUNNING YAML E2E TESTS ====
================================
>> Starting tests
...

Am I supposed to see metrics in the logs? Or do metrics get sent somewhere during the test that I don't see?

(Also, wow, the tests take 5 minutes now, that's kinda annoying)

adrcunha · 2018-09-14T23:20:56Z

(Also, wow, the tests take 5 minutes now, that's kinda annoying)

Hummm... They took 9s on an execution on 9/7... With #335 they took 190s... And then with #344 it went up to 300s.

Am I supposed to see metrics in the logs?

My apologies, local runs shortcut the test execution, so --emit-metrics is ignored. Unfortunately the workaround is hackish, you need to comment lines 196-199 in vendor/github.com/knative/test-infra/scripts/library.sh.

adrcunha · 2018-09-14T23:40:57Z

The ugly hack above will be gone once knative/test-infra#120 is merged (and the vendored test-infra bumped again, of course).

adrcunha · 2018-09-17T03:45:03Z

I messed up my reply because I edited it, and now I can't even find your message... Ugh. Setting `PROW_JOB_ID` won't work because then `kubetest` will try to fetch a project fro boskos. That's why I updated the comment mentioning that you have to comment lines 196-199 in `vendor/github.com/knative/test-infra/scripts/library.sh`.

…

On Sun, Sep 16, 2018 at 2:40 PM, Jason Hall ***@***.***> wrote: $ PROW_JOB_ID=foo ./test/e2e-tests.sh --emit-metrics ... 2018/09/16 17:39:41 main.go:759: --gcp-project is missing, trying to fetch a project from boskos. (for local runs please set --gcp-project to your dev project) 2018/09/16 17:39:41 main.go:771: provider gke, will acquire project type gke-project from boskos 2018/09/16 17:39:41 main.go:307: Something went wrong: failed to prepare test environment: --provider=gke boskos failed to acquire project: Post http://boskos/acquire?type=gke-project&state=free&dest=busy&owner=: dial tcp: lookup boskos: no such host Test subprocess exited with code 1 Test result code is 1 Passing --gcp-project=bar to the script fails with an unrecognized flag.

adrcunha · 2018-09-17T05:26:15Z

I patched your PR and ran the tests:

$ sed -i -e '196,199d' vendor/github.com/knative/test-infra/scripts/library.sh
$ export PROJECT_ID=adrcunha-flex-test
$ ./test/e2e-tests.sh --emit-metrics 
===============================
==== CREATING TEST CLUSTER ====
===============================
...
==============================
==== RUNNING GO E2E TESTS ====
==============================
Running tests with 'go test -tags e2e ./test/e2e/... -count=1 -emitmetrics'
Finished run, return code is 0
Start parsing results, summary:
- TestSimpleBuild :PASS:
- TestFailingBuild :PASS:
- TestBuildLowTimeout :PASS:
- TestPendingBuild :PASS:
- TestPodAffinity :PASS:
- ok github.com/knative/build/test/e2e
Done parsing 5 tests
2018/09/16 22:11:35 Created namespace "build-tests"
=== RUN   TestSimpleBuild
--- PASS: TestSimpleBuild (6.17s)
=== RUN   TestFailingBuild
--- PASS: TestFailingBuild (5.37s)
=== RUN   TestBuildLowTimeout
--- PASS: TestBuildLowTimeout (78.85s)
=== RUN   TestPendingBuild
--- PASS: TestPendingBuild (121.24s)
=== RUN   TestPodAffinity
--- PASS: TestPodAffinity (120.33s)
PASS
2018/09/16 22:17:07 Deleted namespace "build-tests"
ok      github.com/knative/build/test/e2e       333.162s
================================
==== RUNNING YAML E2E TESTS ====
================================
...

Your test is not emitting metrics. From what I understand, the tests are not setting up logging in https://github.com/knative/serving/blob/2291c782bc3ef9f84a2b7eb37db4f745cfac26fa/test/e2e_flags.go#L59 like in

build/test/e2e/simple_test.go

Line 40 in 8576fc7

flag.Parse()

imjasonh · 2018-10-05T20:42:58Z

I got this to work 🎉

info	TestSimpleBuild	trace/trace.go:261	metric NullBuildLatency 1538772072387509233 1538772080954654257 8.567145024s

/hold cancel

imjasonh · 2018-10-05T21:11:48Z

/assign adrcunha

jessiezcc · 2018-10-05T21:26:10Z

/lgtm

imjasonh · 2018-10-05T22:56:40Z

@adrcunha Looks like all that's left is testgrid configs, as mentioned in #337 (comment)

Can you let me know when those are in and we'll have pretty graphs to 😍 over?

adrcunha · 2018-10-17T18:22:26Z

Metrics are now live, details in knative/test-infra#186.

* Emit metric to track null build latency * Emit metric to track null build latency * Support EMIT_METRICS in e2e-tests.sh * Attempt to set up metrics flags * Fix metric setup

knative-prow-robot added do-not-merge/hold do-not-merge/work-in-progress labels Sep 5, 2018

knative-prow-robot added approved size/XS labels Sep 5, 2018

knative-prow-robot requested review from adrcunha and steuhs September 5, 2018 23:20

knative-prow-robot added size/S and removed size/XS labels Sep 6, 2018

imjasonh mentioned this pull request Sep 14, 2018

Update test-infra vendor #355

Closed

imjasonh force-pushed the metrics branch from 9bbb778 to 38ad733 Compare September 14, 2018 20:53

imjasonh added 5 commits October 5, 2018 13:20

Emit metric to track null build latency

869e38e

Support EMIT_METRICS in e2e-tests.sh

e276ee3

Emit metric to track null build latency

a9cf54e

Attempt to set up metrics flags

8228c38

Fix metric setup

fdead41

imjasonh force-pushed the metrics branch from e57eff4 to fdead41 Compare October 5, 2018 20:42

knative-prow-robot removed the do-not-merge/hold label Oct 5, 2018

imjasonh changed the title ~~[WIP] Emit metric to track null build latency~~ Emit metric to track null build latency Oct 5, 2018

knative-prow-robot removed the do-not-merge/work-in-progress label Oct 5, 2018

knative-prow-robot assigned adrcunha Oct 5, 2018

knative-prow-robot assigned jessiezcc Oct 5, 2018

knative-prow-robot added the lgtm label Oct 5, 2018

knative-prow-robot merged commit 5d91877 into knative:master Oct 5, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Emit metric to track null build latency #337

Emit metric to track null build latency #337

imjasonh commented Sep 5, 2018 •

edited by adrcunha

Loading

knative-prow-robot commented Sep 5, 2018

adrcunha commented Sep 5, 2018

imjasonh commented Sep 6, 2018

adrcunha commented Sep 6, 2018

imjasonh commented Sep 7, 2018

adrcunha commented Sep 7, 2018

imjasonh commented Sep 11, 2018 •

edited

Loading

adrcunha commented Sep 11, 2018

imjasonh commented Sep 14, 2018

adrcunha commented Sep 14, 2018 •

edited

Loading

adrcunha commented Sep 14, 2018

adrcunha commented Sep 17, 2018 via email •

edited

Loading

adrcunha commented Sep 17, 2018

imjasonh commented Oct 5, 2018

imjasonh commented Oct 5, 2018

jessiezcc commented Oct 5, 2018

imjasonh commented Oct 5, 2018

adrcunha commented Oct 17, 2018

Emit metric to track null build latency #337

Emit metric to track null build latency #337

Conversation

imjasonh commented Sep 5, 2018 • edited by adrcunha Loading

Proposed Changes

TODO

knative-prow-robot commented Sep 5, 2018

adrcunha commented Sep 5, 2018

imjasonh commented Sep 6, 2018

adrcunha commented Sep 6, 2018

imjasonh commented Sep 7, 2018

adrcunha commented Sep 7, 2018

imjasonh commented Sep 11, 2018 • edited Loading

adrcunha commented Sep 11, 2018

imjasonh commented Sep 14, 2018

adrcunha commented Sep 14, 2018 • edited Loading

adrcunha commented Sep 14, 2018

adrcunha commented Sep 17, 2018 via email • edited Loading

adrcunha commented Sep 17, 2018

imjasonh commented Oct 5, 2018

imjasonh commented Oct 5, 2018

jessiezcc commented Oct 5, 2018

imjasonh commented Oct 5, 2018

adrcunha commented Oct 17, 2018

imjasonh commented Sep 5, 2018 •

edited by adrcunha

Loading

imjasonh commented Sep 11, 2018 •

edited

Loading

adrcunha commented Sep 14, 2018 •

edited

Loading

adrcunha commented Sep 17, 2018 via email •

edited

Loading