Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Enhance client-go url timing logging with http statistics #105156

Merged
merged 1 commit into from Oct 5, 2021
Merged

Enhance client-go url timing logging with http statistics #105156

merged 1 commit into from Oct 5, 2021

Conversation

aojea
Copy link
Member

@aojea aojea commented Sep 20, 2021 •
edited

client-go httpstats

enhance client-go DebugURLTiming roundtripper using golang httptrace
to provide timing statistics for:

  • dns lookup
  • tcp dialing
  • tls handshake
  • time to get a connection from the pool
  • time to process a request

and trace information for DNSLookups and Dials

client-go, using log level 9, trace the following events of an http request:
    - dns lookup
    - tcp dialing
    - tls handshake
    - time to get a connection from the pool
    - time to process a request

Example:

kubectl describe pods -v9 -A 2>&1  | grep -E "(Statis|Trace)"
I1005 16:20:59.452509 3475625 round_trippers.go:492] HTTP Trace: Dial to tcp:127.0.0.1:45993 succeed
I1005 16:20:59.535828 3475625 round_trippers.go:552] HTTP Statistics: DNSLookup 0 ms Dial 0 ms TLSHandshake 6 ms ServerProcessing 76 ms Duration 83 ms
I1005 16:20:59.562798 3475625 round_trippers.go:552] HTTP Statistics: GetConnection 0 ms ServerProcessing 10 ms Duration 11 ms
I1005 16:20:59.571939 3475625 round_trippers.go:552] HTTP Statistics: GetConnection 0 ms ServerProcessing 3 ms Duration 3 ms
I1005 16:20:59.575082 3475625 round_trippers.go:552] HTTP Statistics: GetConnection 0 ms ServerProcessing 1 ms Duration 1 ms
I1005 16:20:59.578570 3475625 round_trippers.go:552] HTTP Statistics: GetConnection 0 ms ServerProcessing 2 ms Duration 2 ms
I1005 16:20:59.580999 3475625 round_trippers.go:552] HTTP Statistics: GetConnection 0 ms ServerProcessing 1 ms Duration 1 ms
I1005 16:20:59.584423 3475625 round_trippers.go:552] HTTP Statistics: GetConnection 0 ms ServerProcessing 2 ms Duration 3 ms
I1005 16:20:59.586591 3475625 round_trippers.go:552] HTTP Statistics: GetConnection 0 ms ServerProcessing 1 ms Duration 1 ms

@k8s-ci-robot k8s-ci-robot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. do-not-merge/release-note-label-needed Indicates that a PR should not merge because it's missing one of the release note labels. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. do-not-merge/needs-kind Indicates a PR lacks a `kind/foo` label and requires one. do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. labels Sep 20, 2021
@aojea aojea marked this pull request as draft September 20, 2021 22:27
@k8s-ci-robot k8s-ci-robot added sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Sep 20, 2021
@aojea aojea marked this pull request as ready for review September 20, 2021 22:31
@aojea aojea force-pushed the clientgo_trace branch 4 times, most recently from 5572a0c to 7258999 Compare September 21, 2021 14:16
@aojea aojea changed the title [WIP] [DO NOT REVIEW]Clientgo trace Improve client-go logging with http statistics Sep 21, 2021
@k8s-ci-robot k8s-ci-robot added release-note Denotes a PR that will be considered when it comes time to generate release notes. and removed do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. do-not-merge/release-note-label-needed Indicates that a PR should not merge because it's missing one of the release note labels. labels Sep 21, 2021
@aojea
Copy link
Member Author

aojea commented Sep 21, 2021

/kind feature
/sig api-machinery
/assign @wojtek-t @liggitt

@k8s-ci-robot k8s-ci-robot added kind/feature Categorizes issue or PR as related to a new feature. and removed do-not-merge/needs-kind Indicates a PR lacks a `kind/foo` label and requires one. labels Sep 21, 2021
@aojea aojea changed the title Improve client-go logging with http statistics Enhance client-go url timing logging with http statistics Sep 21, 2021
@k8s-ci-robot k8s-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Sep 21, 2021
@aojea
Copy link
Member Author

aojea commented Sep 21, 2021

it interleaves the logging

0921 17:57:35.942411 2650084 round_trippers.go:548]     Content-Length: 745
I0921 17:57:35.942417 2650084 round_trippers.go:548]     Date: Tue, 21 Sep 2021 15:57:35 GMT
I0921 17:57:35.942423 2650084 round_trippers.go:548]     Audit-Id: 81b55e03-2e69-4ba5-a83c-991bab95d792
I0921 17:57:35.942429 2650084 round_trippers.go:548]     Cache-Control: no-cache, private
I0921 17:57:35.942278 2650084 round_trippers.go:534]     Get Connection:    0 ms
I0921 17:57:35.942450 2650084 round_trippers.go:537]     Server Processing: 0 ms
I0921 17:57:35.942459 2650084 round_trippers.go:539]     Total Duration:    3 ms
I0921 17:57:35.942468 2650084 round_trippers.go:545] Response Headers:
I0921 17:57:35.942477 2650084 round_trippers.go:548]     Content-Length: 202
I0921 17:57:35.942485 2650084 round_trippers.go:548]     Date: Tue, 21 Sep 2021 15:57:35 GMT
I0921 17:57:35.942496 2650084 round_trippers.go:548]     Audit-Id: 40e95d37-6ed0-4dda-a4bc-b96cd29bc209
I0921 17:57:35.941828 2650084 round_trippers.go:539]     Total Duration:    3 ms
I0921 17:57:35.942506 2650084 round_trippers.go:548]     Cache-Control: no-cache, private
I0921 17:57:35.942516 2650084 round_trippers.go:548]     Content-Type: application/json
I0921 17:57:35.942527 2650084 round_trippers.go:548]     X-Kubernetes-Pf-Flowschema-Uid: ae869303-78c0-4ccd-978d-4b8e0c48202b
I0921 17:57:35.942538 2650084 round_trippers.go:548]     X-Kubernetes-Pf-Prioritylevel-Uid: 895b5d81-fb3c-471e-a69c-f8e3809e6110
I0921 17:57:35.942517 2650084 round_trippers.go:545] Response Headers:
I0921 17:57:35.942578 2650084 round_trippers.go:548]     Date: Tue, 21 Sep 2021 15:57:35 GMT
I0921 17:57:35.942585 2650084 round_trippers.go:548]     Audit-Id: 5c31a81b-ff48-4733-8b7f-0ff01cf79a80
I0921 17:57:35.942591 2650084 round_trippers.go:548]     Cache-Control: no-cache, private
I0921 17:57:35.942597 2650084 round_trippers.go:548]     Content-Type: application/json

,so I've added a new commit to use structured logging , but I can't make it to look pretty :/

I0921 19:22:38.900545 1047110 round_trippers.go:538] "HTTP" trace={DNSLookup:0s Dial:0s GetConnection:0s TLSHandshake:0s ServerProcessing:1.485255ms ConnectionIdle:2.086310275s Duration:1.611043ms ConnectionReused:true}

@aojea
Copy link
Member Author

aojea commented Sep 21, 2021

@thockin @liggitt what logging format do you prefer?

@caesarxuchao
Copy link
Member

/triage accepted

@k8s-ci-robot k8s-ci-robot added triage/accepted Indicates an issue or PR is ready to be actively worked on. and removed needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Sep 21, 2021
@aojea
Copy link
Member Author

aojea commented Sep 21, 2021

structured require more work, and the format is not great, I'll keep using the current format

@k8s-ci-robot k8s-ci-robot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Sep 21, 2021
@aojea aojea force-pushed the clientgo_trace branch 2 times, most recently from e3d3dfb to 800810c Compare September 22, 2021 07:16
@aojea
Copy link
Member Author

aojea commented Sep 22, 2021 •
edited

I think that this is ready, it provides all the necessary info for debugging client-go transport problems, easy to grep and is limited to V9 loglevel.

@liggitt
Copy link
Member

liggitt commented Oct 5, 2021

one comment about the trace var locking, lgtm otherwise

client-go httpstats
72c35be 
enhance client-go DebugURLTiming roundtripper using golang httptrace
to provide timing statistics for:
- dns lookup
- tcp dialing
- tls handshake
- time to get a connection from the pool
- time to process a request
@k8s-ci-robot k8s-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Oct 5, 2021
@liggitt
Copy link
Member

liggitt commented Oct 5, 2021

/lgtm
/approve

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Oct 5, 2021
@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: aojea, liggitt

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:

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

@k8s-ci-robot k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 5, 2021
@k8s-ci-robot k8s-ci-robot merged commit b7da9ef into kubernetes:master Oct 5, 2021
@k8s-ci-robot k8s-ci-robot added this to the v1.23 milestone Oct 5, 2021
@aojea aojea mentioned this pull request Feb 20, 2022
Merged
@aojea aojea mentioned this pull request Jan 27, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@liggitt liggitt liggitt left review comments

@lojies lojies Awaiting requested review from lojies

@resouer resouer Awaiting requested review from resouer

Assignees

@liggitt liggitt

@wojtek-t wojtek-t

Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. kind/feature Categorizes issue or PR as related to a new feature. lgtm "Looks good to me", indicates that a PR is ready to be merged. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. release-note Denotes a PR that will be considered when it comes time to generate release notes. sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. triage/accepted Indicates an issue or PR is ready to be actively worked on.
Projects
None yet
Milestone
v1.23
Development

Successfully merging this pull request may close these issues.

None yet
5 participants
@aojea @caesarxuchao @liggitt @k8s-ci-robot @wojtek-t