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

Zero values from CPU usageNanoCores stats #9531

Open
knabben opened this issue Dec 13, 2023 · 11 comments · May be fixed by #10010
Open

Zero values from CPU usageNanoCores stats #9531

knabben opened this issue Dec 13, 2023 · 11 comments · May be fixed by #10010
Labels
area/cri Container Runtime Interface (CRI) kind/bug

Comments

@knabben
Copy link

knabben commented Dec 13, 2023 •
edited

Description

Upstream kubelet test that checks /stats/summary endpoint is flaky, returning a 0 value for usageNanoCores in a non deterministic way.

kubernetes/kubernetes#122092

Steps to reproduce the issue

  1. Install containerd 1.7.6 on Windows
  2. Create a CPU-consuming pod (i.e. https://github.com/kubernetes/kubernetes/blob/master/test/e2e/windows/cpu_limits.go#L139)
  3. Check the crictl stats -o json in loop and observe the fluctuation of values, bringing usageNanoCores=0 in a few requests

Describe the results you received and expected

From RPC call:

https://github.com/kubernetes/kubernetes/blob/0c645922edcc06adff43c70c02fb56751364bbb5/pkg/kubelet/stats/cri_stats_provider.go#L168

resp, err := p.runtimeService.ListContainerStats(ctx, &runtimeapi.ContainerStatsFilter{})
resp object:

[&ContainerStats{Cpu:&CpuUsage{Timestamp:1702432868648795300,UsageCoreNanoSeconds:&UInt64Value{Value:13010906250000,},UsageNanoCores:&UInt64Value{Value:0,},},
&ContainerStats{Cpu:&CpuUsage{Timestamp:1702432868653306800,UsageCoreNanoSeconds:&UInt64Value{Value:3068906250000,},UsageNanoCores:&UInt64Value{Value:0,},}]

powershell> crictl stats with -o yaml..
...
- attributes:
  cpu:
    timestamp: "1702433310289755400"
    usageCoreNanoSeconds:
      value: "3292031250000"
    usageNanoCores:
      value: "0"

What version of containerd are you using?

containerd 1.7.0

Any other relevant information

Windows 2022 - with Kubernetes v1.23.7

Show configuration if it is related to CRI plugin.

No response
@jsturtevant
Copy link
Contributor

fyi @kiashok

@kiashok
Copy link
Contributor

kiashok commented Dec 13, 2023

@knabben Have you seen this with previous releases of 1.7.* as well or has this started happening only with 1.7.6?

@knabben
Copy link
Author

knabben commented Dec 13, 2023

@kiashok I went from 1.6 to 1.7.6 directly

@kiashok
Copy link
Contributor

kiashok commented Dec 13, 2023

@kiashok I went from 1.6 to 1.7.6 directly

What version of 1.6 were you on?
I can start looking into this early next week (as I will be oof this week) and share an update

@knabben
Copy link
Author

knabben commented Dec 13, 2023 •
edited

@kiashok I went from 1.6 to 1.7.6 directly

What version of 1.6 were you on? I can start looking into this early next week (as I will be oof this week) and share an update

UPDATE: Tried on 1.6.26 and it's still passing, the value is consistent with .5 limit and never returns 0 on CPU used tasks.

Confirming it's broken on 1.7.0+

@fuweid fuweid added the area/cri Container Runtime Interface (CRI) label Dec 17, 2023
@knabben
Copy link
Author

knabben commented Jan 1, 2024

That's curious, from 1.6.26, the usageNanoCores field is null. Kubelet should be filling the value with the correct data.

Using the command: .\crictl.exe stats -o json | ./jq.exe '.stats[] | [ .attributes.metadata.name,.cpu.usageNanoCores.value ] | @csv'

On 1.6.26 running crictl stats directly returns null

"cpulimittest-f157260b-4e6d-4f7c-81ac-57cab09f6fac,"
"cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120,"
...

On - 1.7.0, the getUsageNanoCores was introduced, returning the value.

"cpulimittest-f157260b-4e6d-4f7c-81ac-57cab09f6fac","482723941"
"cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120","495311532"

"cpulimittest-f157260b-4e6d-4f7c-81ac-57cab09f6fac","0"
"cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120","0"

"cpulimittest-f157260b-4e6d-4f7c-81ac-57cab09f6fac","0"
"cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120","0"

"cpulimittest-f157260b-4e6d-4f7c-81ac-57cab09f6fac","474698623"
"cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120","818312098"

@knabben
Copy link
Author

knabben commented Jan 1, 2024

The error is on getUsageNanoCores and newUsageNanoCores variable calculation; it's expected that currentUsageCoreNanoSeconds will be lesser than oldStats.UsageCoreNanoSeconds, what is NOT true when >1 operations are updating the containerStats concurrently.

For this test, I have printed the currentUsage ensuring its equal the oldstats usage, and the reason its returning 0 as newNanoCores;

Kubelet/containerd (?) is calling the CRI API by default every 10 seconds and the reason of this inconsistent behavior in the tests.

time="2024-01-01T11:51:04.809688400-08:00" newusagenanocores: 784996914    currentusage: 7388156250000   oldusage: 7387562500000
time="2024-01-01T11:51:05.167099900-08:00" newusagenanocores: 0            currentusage: 7388156250000   oldusage: 7388156250000
time="2024-01-01T11:51:06.005670800-08:00" newusagenanocores: 661992760    currentusage: 7388703125000   oldusage: 7388156250000
time="2024-01-01T11:51:06.264280600-08:00" newusagenanocores: 173723645    currentusage: 7388750000000   oldusage: 7388703125000
time="2024-01-01T11:51:07.113866000-08:00" newusagenanocores: 678618410    currentusage: 7389328125000   oldusage: 7388750000000
time="2024-01-01T11:51:07.363939800-08:00" newusagenanocores: 0            currentusage: 7389328125000   oldusage: 7389328125000
time="2024-01-01T11:51:08.361238700-08:00" newusagenanocores: 707081972    currentusage: 7390031250000   oldusage: 7389328125000
time="2024-01-01T11:51:08.478596300-08:00" newusagenanocores: 0            currentusage: 7390031250000   oldusage: 7390031250000
time="2024-01-01T11:51:08.925643000-08:00" newusagenanocores: 420321313    currentusage: 7390218750000   oldusage: 7390031250000
time="2024-01-01T11:51:09.553239400-08:00" newusagenanocores: 521174744    currentusage: 7390546875000   oldusage: 7390218750000
time="2024-01-01T11:51:09.614259100-08:00" newusagenanocores: 0            currentusage: 7390546875000   oldusage: 7390546875000
time="2024-01-01T11:51:10.789567600-08:00" newusagenanocores: 507066175    currentusage: 7391140625000   oldusage: 7390546875000
time="2024-01-01T11:51:10.792568100-08:00" newusagenanocores: 0            currentusage: 7391140625000   oldusage: 7391140625000
time="2024-01-01T11:51:11.924844100-08:00" newusagenanocores: 563803701    currentusage: 7391781250000   oldusage: 7391140625000

--

The first loop of curling /stats/summary for this node and filtering only the container

559851131       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
557534273       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
664091996       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120

The second loop running in parallel

0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
543254743       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
505895139       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
536849438       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
799156810       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
353953356       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
621161108       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
280610488       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
548034965       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120
0       cpulimittest-b71b81c1-9ffa-4078-9ae4-aecbe4bf9120

@knabben
Copy link
Author

knabben commented Jan 2, 2024

This 0 return behavior in the usageNanoCores field can also be observed in the Linux gRPC CRI endpoint.

The difference between Linux and Windows in Kubelet is that Linux uses cAdvisor to overwrite the value from the CRI for final stats/summary serialization, while Windows forwards the value directly.

@fuweid fuweid added the platform/windows Windows label Jan 2, 2024
@jsturtevant
Copy link
Contributor

@fuweid this seems to occur on Linux as well, could we add that label as well?

This 0 return behavior in the usageNanoCores field can also be observed in the Linux gRPC CRI endpoint.

fyi @bobbypage @haircommander - This doesn't seem to affect Linux today since kubelet replaces the value with cAdvisor value but might be more of an issue once cri-only metrics moves to beta?

@fuweid fuweid removed the platform/windows Windows label Jan 3, 2024
@jsturtevant jsturtevant mentioned this issue Jan 11, 2024
Closed
@jsturtevant
Copy link
Contributor

jsturtevant commented Feb 13, 2024 •
edited

The error is on getUsageNanoCores and newUsageNanoCores variable calculation; it's expected that currentUsageCoreNanoSeconds will be lesser than oldStats.UsageCoreNanoSeconds, what is NOT true when >1 operations are updating the containerStats concurrently.

@knabben and I looked into this a bit more and found that since this is calculated value and the value is calculated from last time it stored, and it gets store each time, when two calls come in back to back we get 0 (as would be expected since the value hasn't changed between the two calls as they were run at essentially the same time, this partly due to the granularity of the value recorded as well)

So while I don't think this is necessarily a bug it does lead to an inconsistent value that is being returned for usagenanocores depending on when/how often the cri endpoint is called. This is handled in kubelet via only one caller being able to update the cache that kubelet use to manage:

https://github.com/kubernetes/kubernetes/blob/7ec1a89a509906dad9fd6a4635d7bfc157b47790/pkg/kubelet/stats/cri_stats_provider.go#L112-L122

// ListPodStatsAndUpdateCPUNanoCoreUsage updates the cpu nano core usage for
// the containers and returns the stats for all the pod-managed containers.
// This is a workaround because CRI runtimes do not supply nano core usages,
// so this function calculate the difference between the current and the last
// (cached) cpu stats to calculate this metrics. The implementation assumes a
// single caller to periodically invoke this function to update the metrics. If
// there exist multiple callers, the period used to compute the cpu usage may
// vary and the usage could be incoherent (e.g., spiky). If no caller calls
// this function, the cpu usage will stay nil. Right now, eviction manager is
// the only caller, and it calls this function every 10s.

@jsturtevant jsturtevant mentioned this issue Feb 13, 2024
Open
@jsturtevant
Copy link
Contributor

Since this is related to come changes from k/k I've also written up explanation from kubelet perspective with a few options to solve it. Please comment on kubernetes/kubernetes#122092 (comment) to avoid splitting conversation

@jsturtevant jsturtevant linked a pull request Mar 28, 2024 that will close this issue
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
area/cri Container Runtime Interface (CRI) kind/bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Add stats monitor for calculating UsageNanoCores periodically jsturtevant/containerd
4 participants
@jsturtevant @knabben @fuweid @kiashok