Fix stats collector spinning CPU if no stats are collected #36609

thaJeztah · 2018-03-15T17:01:35Z

Commit fd0e24b (#36519) changed the stats collection loop to use a sleep() instead of time.Tick() in the for-loop.

This change caused a regression in situations where no stats are being collected, or an error is hit in the loop (in which case the loop would continue, and the sleep() is not hit).

This patch puts the sleep at the start of the loop to guarantee it's always hit.

This will delay the sampling, which is similar to the behavior before fd0e24b.

- Description for the changelog

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

Commit fd0e24b changed the stats collection loop to use a `sleep()` instead of `time.Tick()` in the for-loop. This change caused a regression in situations where no stats are being collected, or an error is hit in the loop (in which case the loop would `continue`, and the `sleep()` is not hit). This patch puts the sleep at the start of the loop to guarantee it's always hit. This will delay the sampling, which is similar to the behavior before fd0e24b. Signed-off-by: Sebastiaan van Stijn <[email protected]>

thaJeztah · 2018-03-15T17:02:31Z

ping @stevvooe @jhowardmsft PTAL

lowenna

LGTM

cpuguy83

Not necessarily horrible, but this delays the initial collection.
What about a goto Sleep?

thaJeztah · 2018-03-15T23:02:15Z

@cpuguy83 I'm not a big fan of goto X, I think it's easier to forget adding a goto, and ending up in the same situation as we're now (because there's no error, and everything "works", you just can't do as much bitcoin mining on the machine)

The loop is started when the daemon starts, so it would be a 1 second delay once, after the daemon starts.

Situation before #36519 was applied (using time.Tick(s.interval))

diff --git a/daemon/stats/collector.go b/daemon/stats/collector.go
index 88e20984b..d8045710a 100644
--- a/daemon/stats/collector.go
+++ b/daemon/stats/collector.go
@@ -90,10 +90,12 @@ func (s *Collector) Run() {
        // it will grow enough in first iteration
        var pairs []publishersPair
 
-       for {
+       logrus.Debugf("starting to collect stats")
+       for range time.Tick(s.interval) {
                // Put sleep at the start so that it will always be hit,
                // preventing a tight loop if no stats are collected.
-               time.Sleep(s.interval)
+               //time.Sleep(s.interval)
+               logrus.Debugf("collecting stats")
 
                // it does not make sense in the first iteration,
                // but saves allocations in further iterations

INFO[2018-03-15T22:51:12.463038617Z] Loading containers: start.                   
DEBU[2018-03-15T22:51:12.463106540Z] Option Experimental: false                   
DEBU[2018-03-15T22:51:12.463185637Z] Option DefaultDriver: bridge                 
...
DEBU[2018-03-15T22:51:12.657985139Z] Registering DELETE, /networks/{id:.*}        
INFO[2018-03-15T22:51:12.658555097Z] API listen on /var/run/docker.sock           
DEBU[2018-03-15T22:51:13.463968808Z] collecting stats                             
DEBU[2018-03-15T22:51:14.463225328Z] collecting stats

Situation in this PR (time.Sleep(s.interval) at the start of the loop)

diff --git a/daemon/stats/collector.go b/daemon/stats/collector.go
index 88e20984b..7f9735293 100644
--- a/daemon/stats/collector.go
+++ b/daemon/stats/collector.go
@@ -90,10 +90,12 @@ func (s *Collector) Run() {
        // it will grow enough in first iteration
        var pairs []publishersPair
 
+       logrus.Debugf("starting to collect stats")
        for {
                // Put sleep at the start so that it will always be hit,
                // preventing a tight loop if no stats are collected.
                time.Sleep(s.interval)
+               logrus.Debugf("collecting stats")
 
                // it does not make sense in the first iteration,
                // but saves allocations in further iterations

DEBU[2018-03-15T22:57:01.096367667Z] starting to collect stats                    
INFO[2018-03-15T22:57:01.096571550Z] Loading containers: start.                   
DEBU[2018-03-15T22:57:01.096692096Z] Option Experimental: false                   
DEBU[2018-03-15T22:57:01.096746537Z] Option DefaultDriver: bridge                
...
DEBU[2018-03-15T22:57:01.287620703Z] Registering DELETE, /networks/{id:.*}        
INFO[2018-03-15T22:57:01.287997746Z] API listen on /var/run/docker.sock           
DEBU[2018-03-15T22:57:02.097046585Z] collecting stats                             
DEBU[2018-03-15T22:57:03.098938984Z] collecting stats

thaJeztah · 2018-03-16T10:56:15Z

The DockerSuite.TestPostContainersAttach test looks to be broken(ish) or flaky(ish) recently (also see #36606 (comment)), and #36611:

https://jenkins.dockerproject.org/job/Docker-PRs-experimental/39825/console

17:47:26 ----------------------------------------------------------------------
17:47:26 FAIL: docker_api_attach_test.go:98: DockerSuite.TestPostContainersAttach
17:47:26 
17:47:26 docker_api_attach_test.go:211:
17:47:26     c.Assert(actualStdout.Bytes(), checker.DeepEquals, []byte("hello\nsuccess"), check.Commentf("Attach didn't return the expected data from stdout"))
17:47:26 ... obtained []uint8 = []byte{0x73, 0x75, 0x63, 0x63, 0x65, 0x73, 0x73}
17:47:26 ... expected []uint8 = []byte{0x68, 0x65, 0x6c, 0x6c, 0x6f, 0xa, 0x73, 0x75, 0x63, 0x63, 0x65, 0x73, 0x73}
17:47:26 ... Attach didn't return the expected data from stdout
17:47:26

codecov · 2018-03-16T13:23:04Z

Codecov Report

❗ No coverage uploaded for pull request base (master@3d14173). Click here to learn what that means.
The diff coverage is n/a.

@@            Coverage Diff            @@
##             master   #36609   +/-   ##
=========================================
  Coverage          ?   34.69%           
=========================================
  Files             ?      612           
  Lines             ?    45424           
  Branches          ?        0           
=========================================
  Hits              ?    15759           
  Misses            ?    27603           
  Partials          ?     2062

cpuguy83

LGTM since this is happening at daemon start it seems fine.

GordonTheTurtle added the status/0-triage label Mar 15, 2018

thaJeztah added status/2-code-review and removed status/0-triage labels Mar 15, 2018

This was referenced Mar 15, 2018

#36519 causes daemon to continually spin CPU #36608

Closed

[18.03] daemon/stats: more resilient cpu sampling docker-archive/docker-ce#458

Merged

lowenna approved these changes Mar 15, 2018

View reviewed changes

cpuguy83 reviewed Mar 15, 2018

View reviewed changes

kolyshkin mentioned this pull request Mar 16, 2018

flaky test integration-cli/DockerSuite.TestPostContainersAttach() #36611

Closed

thaJeztah added the rebuild/* label Mar 16, 2018

GordonTheTurtle removed the rebuild/* label Mar 16, 2018

cpuguy83 approved these changes Mar 16, 2018

View reviewed changes

lowenna merged commit 72ba7f5 into moby:master Mar 16, 2018

thaJeztah deleted the fix-stats-loop branch March 16, 2018 17:51

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix stats collector spinning CPU if no stats are collected #36609

Fix stats collector spinning CPU if no stats are collected #36609

thaJeztah commented Mar 15, 2018 •

edited

Loading

thaJeztah commented Mar 15, 2018

lowenna left a comment

cpuguy83 left a comment

thaJeztah commented Mar 15, 2018

thaJeztah commented Mar 16, 2018 •

edited

Loading

codecov bot commented Mar 16, 2018 •

edited

Loading

cpuguy83 left a comment

Fix stats collector spinning CPU if no stats are collected #36609

Fix stats collector spinning CPU if no stats are collected #36609

Conversation

thaJeztah commented Mar 15, 2018 • edited Loading

thaJeztah commented Mar 15, 2018

lowenna left a comment

Choose a reason for hiding this comment

cpuguy83 left a comment

Choose a reason for hiding this comment

thaJeztah commented Mar 15, 2018

thaJeztah commented Mar 16, 2018 • edited Loading

codecov bot commented Mar 16, 2018 • edited Loading

Codecov Report

cpuguy83 left a comment

Choose a reason for hiding this comment

thaJeztah commented Mar 15, 2018 •

edited

Loading

thaJeztah commented Mar 16, 2018 •

edited

Loading

codecov bot commented Mar 16, 2018 •

edited

Loading