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

Add NewTicker to the Clock Interface #948

Merged
merged 9 commits into from
May 25, 2021

Conversation

moisesvega
Copy link
Contributor

Changes in this diff:

  • Move Clock interface to zapcore and re-exported from the top-level zap package
  • Add NewTicker method as part of Clock Interface

With this changes Clock interface will be available inside of zapcore and the NewTicker method will allow us to control time.Ticker when it is necessary.

This is a stacked PR to addressed the comments on #782 . Next PR will be doing a refactor of WriteSyncer.

@codecov
Copy link

codecov bot commented May 21, 2021

Codecov Report

Merging #948 (0839a6b) into master (3748251) will increase coverage by 0.00%.
The diff coverage is 100.00%.

Impacted file tree graph

@@           Coverage Diff           @@
##           master     #948   +/-   ##
=======================================
  Coverage   98.02%   98.02%           
=======================================
  Files          44       44           
  Lines        1974     1975    +1     
=======================================
+ Hits         1935     1936    +1     
  Misses         30       30           
  Partials        9        9           
Impacted Files Coverage Δ
clock.go 100.00% <100.00%> (ø)

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 3748251...0839a6b. Read the comment docs.

clock.go Outdated Show resolved Hide resolved
zapcore/clock.go Show resolved Hide resolved
clock_test.go Outdated
@@ -32,6 +32,9 @@ import (
type constantClock time.Time

func (c constantClock) Now() time.Time { return time.Time(c) }
func (c constantClock) NewTicker(d time.Duration) *time.Ticker {
return time.NewTicker(d)
Copy link
Collaborator

Choose a reason for hiding this comment

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

Behaviorally, I would assume that a constantClock will never advance the ticker since time never moves.

Comment on lines 32 to 41
type controlledClock struct {
mockClock *clock.Mock
}

func (c *controlledClock) Now() time.Time {
return c.mockClock.Now()
}

func (c *controlledClock) NewTicker(d time.Duration) *time.Ticker {
return &time.Ticker{C: c.mockClock.Ticker(d).C}
Copy link
Collaborator

Choose a reason for hiding this comment

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

This works but we can shorten this by embedding clock.Mock and only overriding NewTicker:

type controlledClock struct{
  *clock.Mock
}

func newControlledClock() *controlledClock

func (*controlledClock) NewTicker(...) *time.Ticker

Comment on lines 49 to 53
go func() {
ticker := ctrlMock.NewTicker(1 * time.Microsecond)
for {
<-ticker.C
atomic.AddInt32(&n, 1)
Copy link
Collaborator

Choose a reason for hiding this comment

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

This is a goroutine leak. If we use go.uber.org/goleak here (which we do in #782).
We need to create a second quit channel that this selects on.

for {
  select {
  case <-quit:
    ticker.Stop()
    return
    
  case <-ticker.C:
    // ...
  }
}

This might also have to use a second channel to indicate that the goroutine has finished to wait for it to exit.

done := make(chan struct{})
go func() {
    defer close(done)
    // ...
}()
defer func() { <-done }() // wait for end

atomic.AddInt32(&n, 1)
}
}()
time.Sleep(1 * time.Microsecond)
Copy link
Collaborator

Choose a reason for hiding this comment

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

This shouldn't be necessary. My guess is that it's to wait for the ticker to start up.
We can probably get rid of this by starting the ticker right above the go func(), or as an argument to go func.

go func(ticker *time.Ticker) {
  // ...
}(ctrlMock.NewTicker(..))


// Create a channel to increment every microsecond.
go func() {
ticker := ctrlMock.NewTicker(1 * time.Microsecond)
Copy link
Collaborator

Choose a reason for hiding this comment

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

code style: can be just time.Microsecond instead of 1 * time.Microsecond.

}

func TestMockClock(t *testing.T) {
var n int32
Copy link
Collaborator

Choose a reason for hiding this comment

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

Instead of using sync/atomic, we should use go.uber.org/atomic here.

var n atomic.Int32

// ...

<-ticker.C
n.Inc()

// ...

assert.Equal(t, 42, n.Load())

See also https://github.com/uber-go/guide/blob/master/style.md#use-gouberorgatomic

time.Sleep(1 * time.Microsecond)

// Move clock forward.
ctrlMock.mockClock.Add(10 * time.Microsecond)
Copy link
Collaborator

Choose a reason for hiding this comment

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

If we embed clock.MockClock inside ctrlMock as suggested above, this .mockClock can be dropped.


// Move clock forward.
ctrlMock.mockClock.Add(10 * time.Microsecond)
assert.Equal(t, atomic.LoadInt32(&n), int32(10))
Copy link
Collaborator

Choose a reason for hiding this comment

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

For assert.Equal, the arguments are (expected, got), not (got, expected).

// Move clock forward.
ctrlMock.Add(2 * time.Microsecond)
assert.Equal(t, int32(2), n.Load())
quit <- true
Copy link
Collaborator

Choose a reason for hiding this comment

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

For channels that'll only ever fire once, close the channel instead of posting to it. (See also this.)

Copy link
Collaborator

Choose a reason for hiding this comment

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

Separately, please also see this comment.

We need to wait for the goroutine to actually exit once we tell it to stop before the test finishes.

Consider incorporating goleak with a TestMain in zapcore to detect issues like this.

@abhinav
Copy link
Collaborator

abhinav commented May 24, 2021

RE: lint failures: you need to run go mod tidy if this is a new dependency.

Copy link
Contributor

@mh-park mh-park left a comment

Choose a reason for hiding this comment

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

LGTM!

zapcore/clock.go Outdated Show resolved Hide resolved
moisesvega and others added 2 commits May 24, 2021 18:22
Use double quotes in comments.

Co-authored-by: Minho Park <minho.park@uber.com>
clock.go Show resolved Hide resolved
clock_test.go Outdated Show resolved Hide resolved
@abhinav abhinav merged commit dedcdad into uber-go:master May 25, 2021
@abhinav abhinav mentioned this pull request May 25, 2021
abhinav added a commit that referenced this pull request May 25, 2021
In #948, we noticed that some `go.sum` files were outdated. To avoid
this in the future, add a `lint` check that verifies that `go mod tidy`
does not cause any changes.

This will fail with a dirty working tree as well, but in CI, we don't
expect that.
abhinav added a commit that referenced this pull request May 25, 2021
In #948, we noticed that some `go.sum` files were outdated. To avoid
this in the future, add a `lint` check that verifies that `go mod tidy`
does not cause any changes.

This will fail with a dirty working tree as well, but in CI, we don't
expect that.
abhinav added a commit that referenced this pull request May 25, 2021
In #948, we noticed that some `go.sum` files were outdated. To avoid
this in the future, add a `lint` check that verifies that `go mod tidy`
does not cause any changes.

This will fail with a dirty working tree as well, but in CI, we don't
expect that.
@abhinav abhinav mentioned this pull request May 25, 2021
abhinav added a commit that referenced this pull request May 25, 2021
This release v1.17.0 of Zap with all changes from `master` minus the following:

- #897
- #948
- #950

These changes were omitted because we're still in the process of
changing the interface introduced in #897. We will include that in the
next release.

Release changelog: https://github.com/uber-go/zap/blob/release-1-17/CHANGELOG.md#1170-25-may-2021

Using [apidiff], the surface area of this release compared to v1.16.0
is:

```
--- go.uber.org/zap ---
Compatible changes:
- Inline: added

--- go.uber.org/zap/zapcore ---
Compatible changes:
- InlineMarshalerType: added

--- go.uber.org/zap/zapgrpc ---
Compatible changes:
- (*Logger).Error: added
- (*Logger).Errorf: added
- (*Logger).Errorln: added
- (*Logger).Info: added
- (*Logger).Infof: added
- (*Logger).Infoln: added
- (*Logger).V: added
- (*Logger).Warning: added
- (*Logger).Warningf: added
- (*Logger).Warningln: added

--- go.uber.org/zap/zaptest/observer ---
Compatible changes:
- (*ObservedLogs).FilterFieldKey: added
```

  [apidiff]: https://github.com/golang/exp/blob/master/apidiff/README.md

Resolves #942
Refs GO-599
abhinav added a commit that referenced this pull request Sep 10, 2021
The TestSamplerConcurrent test frequently fails with the following error
in CI:

    --- FAIL: TestSamplerConcurrent (0.25s)
        sampler_test.go:198:
        	    Error Trace:	sampler_test.go:198
        	    Error:      	Max difference between 1250 and 1004 allowed is 125, but difference was 246
        	    Test:       	TestSamplerConcurrent
        	    Messages:   	Unexpected number of logs
    FAIL

The test is intended to verify that
despite an onsalught of messages from multiple goroutines,
we only allow at most `logsPerTick` messages per `tick`.

This was accompilshed by spin-looping 10 goroutines for `numTicks`,
each logging one of `numMessages` different messages,
and then verifying the final log count.

The source of flakiness here was the non-determinism in
how far a goroutine would get in logging enough messages such that
the sampler would be engaged.

In #948, we added a `zapcore.Clock` interface with a ticker and
a mock implementation.
Move that to `ztest` for use here.

To unflake the test, use the mock clock to control time and
for each goroutine, log `logsPerTick*2` messages `numTicks` times.
This gives us,

    for numGoroutines (10)
        for numTicks (25)
            log logsPerTick * 2 (50) messages

We end up attempting to log a total of,

    (numGoroutines * numTicks * logsPerTick * 2) messages
    = (10 * 25 * 50) messages
    = 12500 messages

Of these, the following should be sampled:

    numMessages * numTicks * logsPerTick
    = 5 * 10 * 25
    = 1250

Everything else should be dropped.

For extra confidence, use a SamplerHook (added in #813) to verify that
the number of sampled and dropped messages meet expectations.
abhinav added a commit that referenced this pull request Sep 10, 2021
The TestSamplerConcurrent test frequently fails with the following error
in CI:

    --- FAIL: TestSamplerConcurrent (0.25s)
        sampler_test.go:198:
        	    Error Trace:	sampler_test.go:198
        	    Error:      	Max difference between 1250 and 1004 allowed is 125, but difference was 246
        	    Test:       	TestSamplerConcurrent
        	    Messages:   	Unexpected number of logs
    FAIL

The test is intended to verify that
despite an onsalught of messages from multiple goroutines,
we only allow at most `logsPerTick` messages per `tick`.

This was accompilshed by spin-looping 10 goroutines for `numTicks`,
each logging one of `numMessages` different messages,
and then verifying the final log count.

The source of flakiness here was the non-determinism in
how far a goroutine would get in logging enough messages such that
the sampler would be engaged.

In #948, we added a `zapcore.Clock` interface with a ticker and
a mock implementation.
Move that to `ztest` for use here.

To unflake the test, use the mock clock to control time and
for each goroutine, log `logsPerTick*2` messages `numTicks` times.
This gives us,

    for numGoroutines (10)
        for numTicks (25)
            log logsPerTick * 2 (50) messages

We end up attempting to log a total of,

    (numGoroutines * numTicks * logsPerTick * 2) messages
    = (10 * 25 * 50) messages
    = 12500 messages

Of these, the following should be sampled:

    numMessages * numTicks * logsPerTick
    = 5 * 10 * 25
    = 1250

Everything else should be dropped.

For extra confidence, use a SamplerHook (added in #813) to verify that
the number of sampled and dropped messages meet expectations.
abhinav added a commit that referenced this pull request Sep 10, 2021
The TestSamplerConcurrent test frequently fails with the following error
in CI:

    --- FAIL: TestSamplerConcurrent (0.25s)
        sampler_test.go:198:
        	    Error Trace:	sampler_test.go:198
        	    Error:      	Max difference between 1250 and 1004 allowed is 125, but difference was 246
        	    Test:       	TestSamplerConcurrent
        	    Messages:   	Unexpected number of logs
    FAIL

The test is intended to verify that
despite an onsalught of messages from multiple goroutines,
we only allow at most `logsPerTick` messages per `tick`.

This was accompilshed by spin-looping 10 goroutines for `numTicks`,
each logging one of `numMessages` different messages,
and then verifying the final log count.

The source of flakiness here was the non-determinism in
how far a goroutine would get in logging enough messages such that
the sampler would be engaged.

In #948, we added a `zapcore.Clock` interface with a ticker and
a mock implementation.
Move that to `ztest` for use here.

To unflake the test, use the mock clock to control time and
for each goroutine, log `logsPerTick*2` messages `numTicks` times.
This gives us,

    for numGoroutines (10)
        for numTicks (25)
            log logsPerTick * 2 (50) messages

We end up attempting to log a total of,

    (numGoroutines * numTicks * logsPerTick * 2) messages
    = (10 * 25 * 50) messages
    = 12500 messages

Of these, the following should be sampled:

    numMessages * numTicks * logsPerTick
    = 5 * 10 * 25
    = 1250

Everything else should be dropped.

For extra confidence, use a SamplerHook (added in #813) to verify that
the number of sampled and dropped messages meet expectations.

Refs GO-873
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

Successfully merging this pull request may close these issues.

4 participants