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.

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

remove workaround code for resolving workqueue metrics loss by modifying import order #5945

Merged
merged 1 commit into from
Jan 2, 2025

Conversation

chaosi-zju
Copy link
Member

@chaosi-zju chaosi-zju commented Dec 13, 2024

What type of PR is this?

/kind cleanup

What this PR does / why we need it:

remove workaround code for resolving workqueue metrics loss by modifying import order

Which issue(s) this PR fixes:

Fixes part of #5954

Special notes for your reviewer:

Lastst test report:

click here to see test report
  • karmada-controller-manager:
/ # curl http://127.0.0.1:8080/metrics | grep workqueue_queue_duration_seconds_sum
...
workqueue_queue_duration_seconds_sum{controller="taint-manager",name="taint-manager"} 0.302839183
workqueue_queue_duration_seconds_sum{controller="unified-auth-controller",name="unified-auth-controller"} 0.080192647
workqueue_queue_duration_seconds_sum{controller="work-status",name="work-status"} 0.003801357
workqueue_queue_duration_seconds_sum{controller="work-status-controller",name="work-status-controller"} 0.104381849
...
  • karmada-agent
/ # curl http://127.0.0.1:8080/metrics | grep workqueue_queue_duration_seconds_sum
...
workqueue_queue_duration_seconds_sum{controller="service-export-controller",name="service-export-controller"} 3.1737e-05
workqueue_queue_duration_seconds_sum{controller="work-status",name="work-status"} 2.4132999999999997e-05
workqueue_queue_duration_seconds_sum{controller="work-status-controller",name="work-status-controller"} 0.21671174700000004
...
  • karmada-scheduler
/ # curl http://127.0.0.1:8080/metrics | grep workqueue_queue_duration_seconds_sum
...
workqueue_queue_duration_seconds_sum{controller="scheduler-estimator",name="scheduler-estimator"} 0.00017573
workqueue_queue_duration_seconds_sum{controller="scheduler-queue",name="scheduler-queue"} 0
...
  • karmada-descheduler
/ # curl http://127.0.0.1:8080/metrics | grep workqueue_queue_duration_seconds_sum
...
workqueue_queue_duration_seconds_sum{controller="descheduler",name="descheduler"} 0
workqueue_queue_duration_seconds_sum{controller="scheduler-estimator",name="scheduler-estimator"} 34.711164511
...
  • karmada-operator
/ # curl http://127.0.0.1:8080/metrics | grep workqueue_queue_duration_seconds_sum
...
workqueue_queue_duration_seconds_sum{controller="karmada-operator-controller",name="karmada-operator-controller"} 0.605636931
...
  • karmada-schedule-estimator
    not controller-runtime component, no related metrics.

Does this PR introduce a user-facing change?:


@karmada-bot karmada-bot added the kind/bug Categorizes issue or PR as related to a bug. label Dec 13, 2024
@karmada-bot karmada-bot added the size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. label Dec 13, 2024
@codecov-commenter
Copy link

codecov-commenter commented Dec 13, 2024

⚠️ Please install the 'codecov app svg image' to ensure uploads and comments are reliably processed by Codecov.

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 48.38%. Comparing base (ba1e68d) to head (eb9f295).

❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files
@@           Coverage Diff           @@
##           master    #5945   +/-   ##
=======================================
  Coverage   48.37%   48.38%           
=======================================
  Files         665      665           
  Lines       54795    54795           
=======================================
+ Hits        26507    26511    +4     
+ Misses      26569    26565    -4     
  Partials     1719     1719           
Flag Coverage Δ
unittests 48.38% <ø> (+<0.01%) ⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@chaosi-zju
Copy link
Member Author

chaosi-zju commented Dec 13, 2024

1. Why miss metrics

In Karmada controller, there are two workqueue metric registration, sigs.k8s.io/controller-runtime/pkg/metrics and k8s.io/component-base/metrics/prometheus/workqueue.

The simultaneous import of the two packages is not explicitly declared by us, we just want to use sigs.k8s.io/controller-runtime/pkg/metrics, while k8s.io/component-base/metrics/prometheus/workqueue is from the deep dependency.

They both register workqueue metric in init fucntion, but workqueue provider can only register once. So the import order becomes very important.

Now, you can check by go build --ldflags=--dumpdep github.com/karmada-io/karmada/cmd/controller-manager 2>&1 | grep inittask and find that k8s.io/component-base/metrics/prometheus/workqueue is imported earlier, so we set a unexpected workqueue provider which cause workqueue metrics missed.

func init() {
for _, m := range metrics {
legacyregistry.MustRegister(m)
}
workqueue.SetProvider(prometheusMetricsProvider{})
}

func init() {
Registry.MustRegister(depth)
Registry.MustRegister(adds)
Registry.MustRegister(latency)
Registry.MustRegister(workDuration)
Registry.MustRegister(unfinished)
Registry.MustRegister(longestRunningProcessor)
Registry.MustRegister(retries)
workqueue.SetProvider(workqueueMetricsProvider{})
}

// SetProvider sets the metrics provider for all subsequently created work
// queues. Only the first call has an effect.
func SetProvider(metricsProvider MetricsProvider) {
globalMetricsFactory.setProvider(metricsProvider)
}

func (f *queueMetricsFactory) setProvider(mp MetricsProvider) {
f.onlyOnce.Do(func() {
f.metricsProvider = mp
})
}

2. When introduced

In Karmada v1.9.9, we still use go v1.20, the Karmada controller didn't miss workqueue metrics:

➜  karmada git:(release-1.9) ✗ kh exec -it `kh get pods -n karmada-system | grep $comp | sed -n $i'p' | awk '{print $1}'` -n karmada-system -- sh
/ # curl http://127.0.0.1:8080/metrics | grep workqueue_work_duration_seconds_sum
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0workqueue_work_duration_seconds_sum{name="binding-eviction"} 0
workqueue_work_duration_seconds_sum{name="cluster"} 1.9943413949999997
workqueue_work_duration_seconds_sum{name="cluster-binding-eviction"} 0
workqueue_work_duration_seconds_sum{name="clusterPropagationPolicy reconciler"} 0
workqueue_work_duration_seconds_sum{name="clusterResourceBinding_status_controller"} 0
workqueue_work_duration_seconds_sum{name="clusterresourcebinding"} 0
workqueue_work_duration_seconds_sum{name="cronfederatedhpa"} 0
workqueue_work_duration_seconds_sum{name="dependencies resource detector"} 0
workqueue_work_duration_seconds_sum{name="endpointslice-collect"} 0
workqueue_work_duration_seconds_sum{name="federatedhpa"} 0
workqueue_work_duration_seconds_sum{name="federatedresourcequota"} 0
workqueue_work_duration_seconds_sum{name="hpa-replicas-syncer"} 0
workqueue_work_duration_seconds_sum{name="multiclusterservice"} 0
workqueue_work_duration_seconds_sum{name="namespace"} 0.005409679
100 95079    0 950workqueue_work_duration_seconds_sum{name="propagationPolicy reconciler"} 079
    0     0  14.2M      0workqueue_work_duration_seconds_sum{name="remedy-controller"} 0.394528854
 --:--:-- --:--:-- --:--workqueue_work_duration_seconds_sum{name="resource detector"} 0.35019135200000034
:-- 15.1M
workqueue_work_duration_seconds_sum{name="resourceBinding_status_controller"} 0
workqueue_work_duration_seconds_sum{name="resourcebinding"} 0
workqueue_work_duration_seconds_sum{name="scale ref worker"} 0
workqueue_work_duration_seconds_sum{name="service-export"} 0
workqueue_work_duration_seconds_sum{name="serviceimport"} 0
workqueue_work_duration_seconds_sum{name="work"} 0.9787631499999999
workqueue_work_duration_seconds_sum{name="work-status"} 0.32815969899999997

From Karmada v1.10.0, we use go v1.21, start introducing this problem, metrics missed:

➜  karmada git:(release-1.10) ✗ kh exec -it `kh get pods -n karmada-system | grep $comp | sed -n $i'p' | awk '{print $1}'` -n karmada-system -- sh
/ # curl http://127.0.0.1:8080/metrics | grep workqueue_work_duration_seconds_sum
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  6474    0  6474    0     0  1794k      0 --:--:-- --:--:-- --:--:-- 2107k

3. Why old version fine

In go 1.20, we actively prioritize the import of package "sigs.k8s.io/controller-runtime/pkg/metrics" to ensure its init function called earlier. Refer to:

But, as go 1.21 release a change, go 1.21 release note:

Package initialization order is now specified more precisely. The new algorithm is:

Sort all packages by import path.
Repeat until the list of packages is empty:
Find the first package in the list for which all imports are already initialized.
Initialize that package and remove it from the list.

We cannot explicitly specify the import order; the init fucntion of k8s.io/component-base/metrics/prometheus/workqueue will always be imported earlier.

@chaosi-zju chaosi-zju force-pushed the rt-metrics-provider branch 2 times, most recently from ed8263a to 46794dc Compare December 13, 2024 08:25
@karmada-bot karmada-bot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Dec 14, 2024
@karmada-bot karmada-bot added size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. and removed size/XXL Denotes a PR that changes 1000+ lines, ignoring generated files. labels Dec 31, 2024
@chaosi-zju chaosi-zju changed the title Fix the issue of missing workqueue metrics in the Karmada controller remove workaround code for resolving workqueue metrics loss by modifying import order Dec 31, 2024
@RainbowMango
Copy link
Member

Please rebase this PR as we just fixed a failing unit test in #5998.

Copy link
Member

@RainbowMango RainbowMango left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/assign

@RainbowMango
Copy link
Member

karmada-schedule-estimator
not controller-runtime component, no related metrics.

Any metrics would be emitted from the karmada-scheduler-estimator?

I see there is a --metrics-bind-address flags in karmada-scheduler-estimator:

--metrics-bind-address string                                                                                                                                                                                    
                The TCP address that the server should bind to for serving prometheus metrics(e.g. 127.0.0.1:8080, :8080). It can be set to "0" to disable the metrics serving. Defaults to 0.0.0.0:8080. (default ":8080")

@chaosi-zju
Copy link
Member Author

Any metrics would be emitted from the karmada-scheduler-estimator?

yes, as you see:

shedule-estimator metrics
/ # curl http://127.0.0.1:8080/metrics
# HELP certwatcher_read_certificate_errors_total Total number of certificate read errors
# TYPE certwatcher_read_certificate_errors_total counter
certwatcher_read_certificate_errors_total 0
# HELP certwatcher_read_certificate_total Total number of certificate reads
# TYPE certwatcher_read_certificate_total counter
certwatcher_read_certificate_total 0
# HELP controller_runtime_webhook_panics_total Total number of webhook panics
# TYPE controller_runtime_webhook_panics_total counter
controller_runtime_webhook_panics_total 0
# HELP go_gc_duration_seconds A summary of the pause duration of garbage collection cycles.
# TYPE go_gc_duration_seconds summary
go_gc_duration_seconds{quantile="0"} 3.5886e-05
go_gc_duration_seconds{quantile="0.25"} 4.4505e-05
go_gc_duration_seconds{quantile="0.5"} 5.8224e-05
go_gc_duration_seconds{quantile="0.75"} 7.9188e-05
go_gc_duration_seconds{quantile="1"} 0.002135572
go_gc_duration_seconds_sum 0.14119285
go_gc_duration_seconds_count 1520
# HELP go_goroutines Number of goroutines that currently exist.
# TYPE go_goroutines gauge
go_goroutines 47
# HELP go_info Information about the Go environment.
# TYPE go_info gauge
go_info{version="go1.22.9"} 1
# HELP go_memstats_alloc_bytes Number of bytes allocated and still in use.
# TYPE go_memstats_alloc_bytes gauge
go_memstats_alloc_bytes 3.6458e+06
# HELP go_memstats_alloc_bytes_total Total number of bytes allocated, even if freed.
# TYPE go_memstats_alloc_bytes_total counter
go_memstats_alloc_bytes_total 1.78009e+08
# HELP go_memstats_buck_hash_sys_bytes Number of bytes used by the profiling bucket hash table.
# TYPE go_memstats_buck_hash_sys_bytes gauge
go_memstats_buck_hash_sys_bytes 1.499327e+06
# HELP go_memstats_frees_total Total number of frees.
# TYPE go_memstats_frees_total counter
go_memstats_frees_total 1.953142e+06
# HELP go_memstats_gc_sys_bytes Number of bytes used for garbage collection system metadata.
# TYPE go_memstats_gc_sys_bytes gauge
go_memstats_gc_sys_bytes 3.309416e+06
# HELP go_memstats_heap_alloc_bytes Number of heap bytes allocated and still in use.
# TYPE go_memstats_heap_alloc_bytes gauge
go_memstats_heap_alloc_bytes 3.6458e+06
# HELP go_memstats_heap_idle_bytes Number of heap bytes waiting to be used.
# TYPE go_memstats_heap_idle_bytes gauge
go_memstats_heap_idle_bytes 5.840896e+06
# HELP go_memstats_heap_inuse_bytes Number of heap bytes that are in use.
# TYPE go_memstats_heap_inuse_bytes gauge
go_memstats_heap_inuse_bytes 5.726208e+06
# HELP go_memstats_heap_objects Number of allocated objects.
# TYPE go_memstats_heap_objects gauge
go_memstats_heap_objects 22138
# HELP go_memstats_heap_released_bytes Number of heap bytes released to OS.
# TYPE go_memstats_heap_released_bytes gauge
go_memstats_heap_released_bytes 5.480448e+06
# HELP go_memstats_heap_sys_bytes Number of heap bytes obtained from system.
# TYPE go_memstats_heap_sys_bytes gauge
go_memstats_heap_sys_bytes 1.1567104e+07
# HELP go_memstats_last_gc_time_seconds Number of seconds since 1970 of last garbage collection.
# TYPE go_memstats_last_gc_time_seconds gauge
go_memstats_last_gc_time_seconds 1.7357987677307944e+09
# HELP go_memstats_lookups_total Total number of pointer lookups.
# TYPE go_memstats_lookups_total counter
go_memstats_lookups_total 0
# HELP go_memstats_mallocs_total Total number of mallocs.
# TYPE go_memstats_mallocs_total counter
go_memstats_mallocs_total 1.97528e+06
# HELP go_memstats_mcache_inuse_bytes Number of bytes in use by mcache structures.
# TYPE go_memstats_mcache_inuse_bytes gauge
go_memstats_mcache_inuse_bytes 4800
# HELP go_memstats_mcache_sys_bytes Number of bytes used for mcache structures obtained from system.
# TYPE go_memstats_mcache_sys_bytes gauge
go_memstats_mcache_sys_bytes 15600
# HELP go_memstats_mspan_inuse_bytes Number of bytes in use by mspan structures.
# TYPE go_memstats_mspan_inuse_bytes gauge
go_memstats_mspan_inuse_bytes 141920
# HELP go_memstats_mspan_sys_bytes Number of bytes used for mspan structures obtained from system.
# TYPE go_memstats_mspan_sys_bytes gauge
go_memstats_mspan_sys_bytes 146880
# HELP go_memstats_next_gc_bytes Number of heap bytes when next garbage collection will take place.
# TYPE go_memstats_next_gc_bytes gauge
go_memstats_next_gc_bytes 7.933824e+06
# HELP go_memstats_other_sys_bytes Number of bytes used for other system allocations.
# TYPE go_memstats_other_sys_bytes gauge
go_memstats_other_sys_bytes 883249
# HELP go_memstats_stack_inuse_bytes Number of bytes in use by the stack allocator.
# TYPE go_memstats_stack_inuse_bytes gauge
go_memstats_stack_inuse_bytes 1.015808e+06
# HELP go_memstats_stack_sys_bytes Number of bytes obtained from system for stack allocator.
# TYPE go_memstats_stack_sys_bytes gauge
go_memstats_stack_sys_bytes 1.015808e+06
# HELP go_memstats_sys_bytes Number of bytes obtained from system.
# TYPE go_memstats_sys_bytes gauge
go_memstats_sys_bytes 1.8437384e+07
# HELP go_threads Number of OS threads created.
# TYPE go_threads gauge
go_threads 10
# HELP process_cpu_seconds_total Total user and system CPU time spent in seconds.
# TYPE process_cpu_seconds_total counter
process_cpu_seconds_total 50.64
# HELP process_max_fds Maximum number of open file descriptors.
# TYPE process_max_fds gauge
process_max_fds 1.048576e+06
# HELP process_open_fds Number of open file descriptors.
# TYPE process_open_fds gauge
process_open_fds 12
# HELP process_resident_memory_bytes Resident memory size in bytes.
# TYPE process_resident_memory_bytes gauge
process_resident_memory_bytes 1.7760256e+07
# HELP process_start_time_seconds Start time of the process since unix epoch in seconds.
# TYPE process_start_time_seconds gauge
process_start_time_seconds 1.7356166874e+09
# HELP process_virtual_memory_bytes Virtual memory size in bytes.
# TYPE process_virtual_memory_bytes gauge
process_virtual_memory_bytes 1.30875392e+09
# HELP process_virtual_memory_max_bytes Maximum amount of virtual memory available in bytes.
# TYPE process_virtual_memory_max_bytes gauge
process_virtual_memory_max_bytes 1.8446744073709552e+19
# HELP rest_client_requests_total Number of HTTP requests, partitioned by status code, method, and host.
# TYPE rest_client_requests_total counter
rest_client_requests_total{code="200",host="172.18.0.5:6443",method="GET"} 1648

Copy link
Member

@RainbowMango RainbowMango left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK. thanks for the confirmation.
/lgtm
/approve

@karmada-bot karmada-bot added the lgtm Indicates that a PR is ready to be merged. label Jan 2, 2025
@karmada-bot
Copy link
Collaborator

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: RainbowMango

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

@karmada-bot karmada-bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jan 2, 2025
@RainbowMango
Copy link
Member

/hold cancel

@karmada-bot karmada-bot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jan 2, 2025
@karmada-bot karmada-bot merged commit a891673 into karmada-io:master Jan 2, 2025
21 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. kind/bug Categorizes issue or PR as related to a bug. lgtm Indicates that a PR is ready to be merged. size/XS Denotes a PR that changes 0-9 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants