Add trace from k/k repo #65

dims · 2019-01-23T18:58:30Z

per discussion in kubernetes/kubernetes#73209

Automatic merge from submit-queue (batch tested with PRs 41597, 42185, 42075, 42178, 41705) stop spamming logs on restart of api server **What this PR does / why we need it**: This PR reduces an excessive amount of log spam on startup of any API server with larger amounts of content. We have experienced server restart times ~5 minutes that is a consequence of us tracing each directory in etcd during our initial decoding. This spams the journald process, and results in much of those messages getting rate limited and dropped, and making actual problems much harder to debug. This stops us logging discrete keys in favor of just knowing that an operation was slow for the particular object type (which is enough information!) this PR also makes it so we know what trace operation was ended in our log messages! sample log now: ``` Trace "decodeNodeList *[]api.PolicyBinding" (started 2017-02-20 22:20:33.98771112 +0000 UTC) Decoded 10718 nodes decodeNodeList *[]api.PolicyBinding [500ms] END ```

Automatic merge from submit-queue (batch tested with PRs 47484, 47904, 48034) prioritize messages for long steps This pull prioritizes the trace messages, so steps that are unusually large come out at the info level and all details come out a v(4) level.

- Move from the old github.com/golang/glog to k8s.io/klog - klog as explicit InitFlags() so we add them as necessary - we update the other repositories that we vendor that made a similar change from glog to klog * github.com/kubernetes/repo-infra * k8s.io/gengo/ * k8s.io/kube-openapi/ * github.com/google/cadvisor - Entirely remove all references to glog - Fix some tests by explicit InitFlags in their init() methods Change-Id: I92db545ff36fcec83afe98f550c9e630098b3135

…or-klog-take-2 Update cadvisor and other repos for klog

fix golint problem of volume cephfs/iscsi/nfs

…arch

fluentd-elasticsearch - update fluentd to 1.3.3 & added filter_parser for json fields in es

…om-k/k-repo

k8s-ci-robot · 2019-01-23T18:58:41Z

Thanks for your pull request. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please follow instructions at https://git.k8s.io/community/CLA.md#the-contributor-license-agreement to sign the CLA.

It may take a couple minutes for the CLA signature to be fully registered; after that, please reply here with a new comment and we'll verify. Thanks.

If you've already signed a CLA, it's possible we don't have your GitHub username or you're using a different email address. Check your existing CLA data and verify that your email is set on your git commits.
If you signed the CLA as a corporation, please sign in with your organization's credentials at https://identity.linuxfoundation.org/projects/cncf to be authorized.
If you have done the above and are still having issues with the CLA being reported as unsigned, please email the CNCF helpdesk: helpdesk@rt.linuxfoundation.org

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

dims · 2019-01-23T19:34:54Z

/override cla/linuxfoundation

Change-Id: I8d2ad6e80131048441b73c90d5cf9b1f40c69f4e

Change-Id: I02c0fb44ad09876a33b84d8ec325d97c9894232a

mcrute · 2019-01-23T22:24:30Z

It would be nice to have some tests for this but since it's just an extraction...

/lgtm

k8s-ci-robot · 2019-01-23T22:24:37Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: dims, mcrute

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:

~~OWNERS~~ [dims]

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

mcrute · 2019-01-23T22:45:11Z

Looks like only an admin can override. Ping @thockin @liggitt

dims · 2019-01-23T23:50:12Z

/override cla/linuxfoundation

k8s-ci-robot · 2019-01-23T23:50:13Z

@dims: Overrode contexts on behalf of dims: cla/linuxfoundation

In response to this:

/override cla/linuxfoundation

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

k8s-ci-robot · 2019-01-23T23:50:17Z

Thanks for your pull request. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please follow instructions at https://git.k8s.io/community/CLA.md#the-contributor-license-agreement to sign the CLA.

It may take a couple minutes for the CLA signature to be fully registered; after that, please reply here with a new comment and we'll verify. Thanks.

If you've already signed a CLA, it's possible we don't have your GitHub username or you're using a different email address. Check your existing CLA data and verify that your email is set on your git commits.
If you signed the CLA as a corporation, please sign in with your organization's credentials at https://identity.linuxfoundation.org/projects/cncf to be authorized.
If you have done the above and are still having issues with the CLA being reported as unsigned, please email the CNCF helpdesk: helpdesk@rt.linuxfoundation.org

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

wojtek-t · 2019-01-24T08:01:33Z

Thanks @dims !

@krzysied - FYI

thockin · 2019-01-24T19:07:10Z

trace/trace.go

+	for _, step := range t.steps {
+		stepDuration := step.stepTime.Sub(lastStepTime)
+		if stepThreshold == 0 || stepDuration > stepThreshold || klog.V(4) {
+			buffer.WriteString(fmt.Sprintf("Trace[%d]: [%v] [%v] %v\n", tracenum, step.stepTime.Sub(t.startTime), stepDuration, step.msg))


@DirectXMan12 This is an "interesting" use of logs - how do we think we would convert this to logr-style?

it's not entirely clear to me why it's written to a buffer first, except perhaps performance. If we remove that constraint, it looks fairly straightforward:

log.Info("trace", "trace id", tracenum, "since start", step.stepTime.Sub(t.startTime), "step duration", stepDuration, "message", step.msg)

or better yet

log := log.WithValues("trace id", tracenum) log.Info("trace", "since start", step.stepTime.Sub(t.startTime), "step duration", stepDuration, "message", step.msg)

Individual traces can easily be reconstituted by filtering on "id" == ${TRACE_ID} or somesuch.

In the long term? This is probably a good candidate for actual tracing ;-).

It's at least mildly unclear what the motivation for this package is though, except to reduce logging throughput though -- it seems like a decent amount of this could be replaced with "normal" logging plus structured filtering.

@DirectXMan12 this is extremely useful especially in the performance scaling tests. A variation of this helped me find the nil panic propagation problem ( see https://github.com/kubernetes/kubernetes/pull/72820/files )

cc @wojtek-t

Amount of logs is one example. If something is happening 100 millions of times but it's only 100 times it's relatively slow, I don't want to see 100 millions of logs - I want to have 100.

Yes - once we have proper tracing, we probably should at least consider replacing those.

sttts and others added 12 commits January 29, 2017 21:41

pkg/util: move trace.go to k8s.io/apiserver/pkg/util/trace

81f029f

stop spamming logs on restart of api server

5043bf8

prioritize messages for long steps

1387e05

Merge pull request #70889 from dims/update-cadvisor-and-other-repos-f…

cf4b235

…or-klog-take-2 Update cadvisor and other repos for klog

Merge branch 'master' into jlx201811031619

fcd932d

Merge pull request #70613 from jianglingxia/jlx201811031619

bcc5c02

fix golint problem of volume cephfs/iscsi/nfs

Merge remote-tracking branch 'upstream/master' into fluentd-elasticse…

9253d6c

…arch

Merge pull request #71180 from monotek/fluentd-elasticsearch

5fa6d20

fluentd-elasticsearch - update fluentd to 1.3.3 & added filter_parser for json fields in es

Merge remote-tracking branch 'trace/filtered-trace' into add-trace-fr…

3a89267

…om-k/k-repo

k8s-ci-robot requested review from dashpole and lavalamp January 23, 2019 18:58

k8s-ci-robot added approved Indicates a PR has been approved by an approver from all required OWNERS files. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Jan 23, 2019

k8s-ci-robot added the cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. label Jan 23, 2019

dims added 2 commits January 23, 2019 16:48

Move trace.go to correct location

0ed692b

Change-Id: I8d2ad6e80131048441b73c90d5cf9b1f40c69f4e

add comments to public methods

3f4bf62

Change-Id: I02c0fb44ad09876a33b84d8ec325d97c9894232a

k8s-ci-robot assigned mcrute Jan 23, 2019

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Jan 23, 2019

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. and removed cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. labels Jan 23, 2019

k8s-ci-robot removed the cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. label Jan 23, 2019

k8s-ci-robot added the cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. label Jan 23, 2019

dims merged commit ca2bd90 into kubernetes:master Jan 24, 2019

dims mentioned this pull request Jan 24, 2019

Need tests for trace package #69

Closed

thockin reviewed Jan 24, 2019

View reviewed changes

andrewsykim mentioned this pull request Jan 24, 2019

Update vendor k8s.io/utils and remove internal utils kubernetes/kubernetes#73243

Merged

spiffxp mentioned this pull request Jan 28, 2019

Update the cla plugin to allow overriding the CLA check kubernetes/test-infra#11004

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add trace from k/k repo #65

Add trace from k/k repo #65

dims commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

dims commented Jan 23, 2019

mcrute commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

mcrute commented Jan 23, 2019

dims commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

wojtek-t commented Jan 24, 2019

thockin Jan 24, 2019

DirectXMan12 Jan 29, 2019

DirectXMan12 Jan 29, 2019

dims Jan 29, 2019

dims Jan 29, 2019

wojtek-t Jan 30, 2019

Add trace from k/k repo #65

Add trace from k/k repo #65

Conversation

dims commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

dims commented Jan 23, 2019

mcrute commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

mcrute commented Jan 23, 2019

dims commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

k8s-ci-robot commented Jan 23, 2019

wojtek-t commented Jan 24, 2019

thockin Jan 24, 2019

Choose a reason for hiding this comment

DirectXMan12 Jan 29, 2019

Choose a reason for hiding this comment

DirectXMan12 Jan 29, 2019

Choose a reason for hiding this comment

dims Jan 29, 2019

Choose a reason for hiding this comment

dims Jan 29, 2019

Choose a reason for hiding this comment

wojtek-t Jan 30, 2019

Choose a reason for hiding this comment