Bug fix: stats --no-stream always print zero values by WeiZhang555 · Pull Request #20803 · moby/moby

WeiZhang555 · 2016-03-01T07:29:09Z

Please provide the following information:

What did you do?

docker stats --no-stream always print zero values.

$ docker stats --no-stream
CONTAINER           CPU %               MEM USAGE / LIMIT   MEM %
NET I/O             BLOCK I/O
7f4ef234ca8c        0.00%               0 B / 0 B           0.00%
0 B / 0 B           0 B / 0 B
f05bd18819aa        0.00%               0 B / 0 B           0.00%
0 B / 0 B           0 B / 0 B

This commit will let docker client sleep a while to get correct stat
data before print it on screen.

How did you do it?

Let docker client sleep 1.5s before print it on screen

How do I see it or verify it?

Run some containers, then run docker stats --no-stream, you'll see it.

A picture of a cute animal (not mandatory but encouraged)

Signed-off-by: Zhang Wei [email protected]

WeiZhang555 · 2016-03-01T07:46:14Z

This is newly introduced, ping @icecrime @cpuguy83

WeiZhang555 · 2016-03-01T09:29:10Z

I believe this must be a flaky test because I've seen this twice, and this PR didn't touch that part of code the tests are failing on. https://jenkins.dockerproject.org/job/Docker-PRs-WoW-TP4/1826/console

08:40:58 ----------------------------------------------------------------------
08:40:58 FAIL: docker_cli_ps_test.go:475: DockerSuite.TestPsListContainersFilterExited
08:40:58 
08:40:58 docker_cli_ps_test.go:500:
08:40:58     c.Assert(ids, checker.HasLen, 2, check.Commentf("Should be 2 zero exited containers got %d: %s", len(ids), out))
08:40:58 ... obtained []string = []string{"2cfcdcf2679c820d07cadab00c5bf036d22a006efb2a4875d9ed7b23d2471549", "e7725046277fdc123d7b07ff30c8c0389ee6551bc108d72a0c005681bad5d521", "daac090101219251ae48749c204a731a339c81f47b63e65392ee981be603c9c7"}
08:40:58 ... n int = 2
08:40:58 ... Should be 2 zero exited containers got 3: 2cfcdcf2679c820d07cadab00c5bf036d22a006efb2a4875d9ed7b23d2471549
08:40:58 e7725046277fdc123d7b07ff30c8c0389ee6551bc108d72a0c005681bad5d521
08:40:58 daac090101219251ae48749c204a731a339c81f47b63e65392ee981be603c9c7
08:40:58 
08:40:58 
08:41:38 
08:41:38 ----------------------------------------------------------------------

This is a Windows test, so ping @jhowardmsft

calavera · 2016-03-02T00:48:14Z

LGTM

cpuguy83 · 2016-03-02T02:52:48Z

I'm not seeing the zeroed out stats on master.

WeiZhang555 · 2016-03-02T03:16:20Z

@cpuguy83 Just test on the latest master code, it happens all the time:

This is a racy problem, go routines will collect stat information for each container, when docker stats try to print it on screen while go routine didn't finish and return, it will print zeros.
I've tested it on two machines, always happens, maybe your hardware is too powerful.

For the streamed docker stats, you can see the first output is also all zeros, this is caused by same reason.

That's why I want docker client to sleep a while when user tried to use --no-stream because it will be meaningless if always empty. But for streaming stats, I feels that the first empty result doesn't harm anything because it will flush the screen soon.

PS: my machine is 4*CPU with 4G memory, if it helps.

thaJeztah · 2016-03-02T10:35:00Z

Since we already have a loop, could we check if the result contains actual data, and only print if it does? (or would that add too much complication)

WeiZhang555 · 2016-03-02T16:06:56Z

@thaJeztah I have improved it a little, add a WaitGroup to wait all collectors to get their first stat data, so it will help for the racy problem. But the time.Sleep is still necessary, believe me I have tried.

Also I found a potential bug that if we are running docker stats -a, then start a new contaner, two events will happen: "create" and "start", so there will be two go routine collector running for one container, I've fixed it here. It won't bring wrong result or big problem, but will waste some compute and network resources.

ping @calavera , sorry that code is changed, please help take another look. Thank you! 😄

coolljt0725 · 2016-03-03T03:21:24Z

Is this comment is necessary? It should be removed

Yup, you are right. 👍

WeiZhang555 · 2016-03-03T04:17:33Z

I just added some test cases, @cpuguy83 you can use these two test cases to verify, I hope it can help.

Master branch will fail these two test cases.

calavera · 2016-03-03T18:17:34Z

@cpuguy83 can you take a look?

WeiZhang555 · 2016-03-04T06:40:51Z

Just found a better way and updated the code. I think this bug is actually caused by this line:

go getContainerList()

change it to

getContainerList()

Plus WaitGroup can finally eliminate the race condition, and no need to sleep any more!
ping @cpuguy83

cpuguy83 · 2016-03-04T20:37:50Z

Doesn't this conflict with the later calls to waitFirst.Done?

I don't think so. This defer function is to make sure waitFirst.Done() will be called when the function returns, and getFirst is used to make sure waitFirst.Done() will be called only once, so that WaitGroup.Wait() won't block or error.

I would add a getFirst=true before this line to make it clearer, though it's OK without.

`docker stats --no-stream` always print zero values. ``` $ docker stats --no-stream CONTAINER CPU % MEM USAGE / LIMIT MEM % NET I/O BLOCK I/O 7f4ef234ca8c 0.00% 0 B / 0 B 0.00% 0 B / 0 B 0 B / 0 B f05bd18819aa 0.00% 0 B / 0 B 0.00% 0 B / 0 B 0 B / 0 B ``` This commit will let docker client wait until it gets correct stat data before print it on screen. Signed-off-by: Zhang Wei <[email protected]>

thaJeztah · 2016-03-05T12:25:37Z

Another problematic test? 😢
https://jenkins.dockerproject.org/job/Docker-PRs/24663/console

05:52:31 PASS: docker_cli_run_unix_test.go:28: DockerSuite.TestRunRedirectStdout    0.979s
05:52:37 
05:52:37 ----------------------------------------------------------------------
05:52:37 FAIL: docker_cli_run_test.go:1395: DockerSuite.TestRunResolvconfUpdate
05:52:37 
05:52:37 docker_cli_run_test.go:1475:
05:52:37     c.Fatalf("Container's resolv.conf should not have been updated with host resolv.conf: %q", string(containerResolv))
05:52:37 ... Error: Container's resolv.conf should not have been updated with host resolv.conf: "# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)\n#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN\nnameserver 172.31.0.2\nsearch us-west-2.compute.internal\n"
05:52:37 
05:52:40 
05:52:40 ----------------------------------------------------------------------

Edit: existing one: #19937

thaJeztah · 2016-03-05T12:32:19Z

And looks like network-connection issues on win2lin https://jenkins.dockerproject.org/job/Docker-PRs-Win2Lin/22791/console

05:32:34 PASS: docker_cli_build_test.go:979: DockerSuite.TestBuildAddFileWithWhitespace 5.418s
05:32:38 
05:32:38 ----------------------------------------------------------------------
05:32:38 FAIL: docker_cli_build_test.go:2936: DockerSuite.TestBuildAddLocalAndRemoteFilesWithCache
05:32:38 
05:32:38 docker_cli_build_test.go:2960:
05:32:38     c.Fatal(err)
05:32:38 ... Error: failed to build the image: Sending build context to Docker daemon 3.072 kB

05:32:38 Step 1 : FROM scratch
05:32:38  ---> 
05:32:38 Step 2 : MAINTAINER dockerio
05:32:38  ---> Running in 95751fcc29c9
05:32:38  ---> 6ec1cc6f252e
05:32:38 Removing intermediate container 95751fcc29c9
05:32:38 Step 3 : ADD foo /usr/lib/bla/bar
05:32:38  ---> a0aefe9db33e
05:32:38 Removing intermediate container 6e9fe423a319
05:32:38 Step 4 : ADD http://45.55.33.7:32768/baz /usr/lib/baz/quux
05:32:38 Get http://45.55.33.7:32768/baz: dial tcp 45.55.33.7:32768: connect: network is unreachable
05:32:38 
05:32:38 
05:32:44 
05:32:44 ----------------------------------------------------------------------
05:32:44 PASS: docker_cli_build_test.go:3021: DockerSuite.TestBuildAddLocalAndRemoteFilesWithoutCache   4.325s

WeiZhang555 · 2016-03-05T13:25:00Z

@thaJeztah Yup, they must be problematic. Thank you for restarting tests for me 😆

cpuguy83 · 2016-03-05T13:47:38Z

LGTM

Bug fix: stats --no-stream always print zero values

GordonTheTurtle added the status/0-triage label Mar 1, 2016

thaJeztah mentioned this pull request Mar 1, 2016

Flaky test: TestPsListContainersFilterExited #20819

Open

cpuguy83 added status/2-code-review and removed status/0-triage labels Mar 1, 2016

WeiZhang555 force-pushed the empty-stats-no-stream branch from d675ca1 to 9ffa626 Compare March 2, 2016 16:00

coolljt0725 reviewed Mar 3, 2016
View reviewed changes

WeiZhang555 force-pushed the empty-stats-no-stream branch 3 times, most recently from 11a3c76 to 96e1c80 Compare March 3, 2016 04:08

WeiZhang555 force-pushed the empty-stats-no-stream branch from 96e1c80 to 815a420 Compare March 4, 2016 06:36

cpuguy83 reviewed Mar 4, 2016
View reviewed changes

WeiZhang555 force-pushed the empty-stats-no-stream branch from 815a420 to ea86c30 Compare March 5, 2016 05:23

thaJeztah mentioned this pull request Mar 5, 2016

Flaky test: TestRunResolvconfUpdate #19937

Closed

cpuguy83 added a commit that referenced this pull request Mar 5, 2016

Merge pull request #20803 from WeiZhang555/empty-stats-no-stream

160abfb

Bug fix: stats --no-stream always print zero values

cpuguy83 merged commit 160abfb into moby:master Mar 5, 2016

Conversation

WeiZhang555 commented Mar 1, 2016

Uh oh!

WeiZhang555 commented Mar 1, 2016

Uh oh!

WeiZhang555 commented Mar 1, 2016

Uh oh!

calavera commented Mar 2, 2016

Uh oh!

cpuguy83 commented Mar 2, 2016

Uh oh!

WeiZhang555 commented Mar 2, 2016

Uh oh!

thaJeztah commented Mar 2, 2016

Uh oh!

WeiZhang555 commented Mar 2, 2016

Uh oh!

coolljt0725 Mar 3, 2016

Choose a reason for hiding this comment

Uh oh!

WeiZhang555 Mar 3, 2016

Choose a reason for hiding this comment

Uh oh!

WeiZhang555 commented Mar 3, 2016

Uh oh!

calavera commented Mar 3, 2016

Uh oh!

WeiZhang555 commented Mar 4, 2016

Uh oh!

cpuguy83 Mar 4, 2016

Choose a reason for hiding this comment

Uh oh!

WeiZhang555 Mar 5, 2016

Choose a reason for hiding this comment

Uh oh!

thaJeztah commented Mar 5, 2016

Uh oh!

thaJeztah commented Mar 5, 2016

Uh oh!

WeiZhang555 commented Mar 5, 2016

Uh oh!

cpuguy83 commented Mar 5, 2016

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants