Grokbase › Groups › Go › golang-nuts › June 2015
FAQ
Hi all,

We observe at least 10ms delay before receiving message from closed
buffered channel. We met this when we run some code basically like this:

```
chs := make([]chan struct{}, 10000)
// init
for i := range chs {
   chs[i] = make(chan struct{}, 1)
}
// close
for _, ch := range chs {
   close(ch)
}
// receive
for _, ch := range chs {
   select {
   case <-ch:
   case <-time.After(10 * time.Millisecond):
     t.Fatalf("")
   }
}
```

The test environment is under --cpu 4 --race on travis(2 bursted cpu) when
running `go test` for the whole test set. After I adjust the timeout to 1s,
I didn't observe this behavior anymore. Is this behavior expected?

I check the spec, which says that `After calling close, and after any
previously sent values have been received, receive operations will return
the zero value for the channel's type without blocking.`

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Search Discussions

  • Brad Fitzpatrick at Jun 25, 2015 at 2:01 am ⇧
    OS? Arch? Go version?

    I assume linux-amd64 from coreos.com and -race. But which Go version?

    I wonder if you're just generating lots of garbage and causing the GC to
    run, making that time.After channel 10000 times.


    On Wed, Jun 24, 2015 at 11:27 PM, Yicheng Qin wrote:

    Hi all,

    We observe at least 10ms delay before receiving message from closed
    buffered channel. We met this when we run some code basically like this:

    ```
    chs := make([]chan struct{}, 10000)
    // init
    for i := range chs {
    chs[i] = make(chan struct{}, 1)
    }
    // close
    for _, ch := range chs {
    close(ch)
    }
    // receive
    for _, ch := range chs {
    select {
    case <-ch:
    case <-time.After(10 * time.Millisecond):
    t.Fatalf("")
    }
    }
    ```

    The test environment is under --cpu 4 --race on travis(2 bursted cpu) when
    running `go test` for the whole test set. After I adjust the timeout to 1s,
    I didn't observe this behavior anymore. Is this behavior expected?

    I check the spec, which says that `After calling close, and after any
    previously sent values have been received, receive operations will return
    the zero value for the channel's type without blocking.`

    --
    You received this message because you are subscribed to the Google Groups
    "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an
    email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
  • Yicheng Qin at Jun 25, 2015 at 4:20 pm ⇧
    `uname -a`: Linux testing-worker-linux-docker-545af3bd-3302-linux-3
    3.13.0-40-generic #69-Ubuntu SMP Thu Nov 13 17:53:56 UTC 2014 x86_64 x86_64
    x86_64 GNU/Linux

    `lsb release -a`: Description: Ubuntu 12.04.5 LTS

    `go version`: go version go1.4 linux/amd64

    the test is run under `--race --cpu 1,2,4`

    I added the trace flag and got this:
    ```
    2015/06/25 15:58:49 TestWaitTestStress start
    gc3(1): 2+0+140+1 us, 0 -> 0 MB, 338 (392-54) objects, 6 goroutines, 32/0/0
    sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc4(1): 1+0+132+0 us, 0 -> 0 MB, 678 (877-199) objects, 6 goroutines,
    41/23/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc5(1): 1+0+141+0 us, 0 -> 0 MB, 1135 (1583-448) objects, 6 goroutines,
    42/34/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc6(1): 1+0+162+0 us, 0 -> 0 MB, 1786 (2593-807) objects, 6 goroutines,
    49/34/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc7(1): 1+0+232+0 us, 0 -> 0 MB, 2548 (3880-1332) objects, 6 goroutines,
    59/42/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc8(1): 1+1+365+0 us, 0 -> 0 MB, 5270 (7240-1970) objects, 6 goroutines,
    88/52/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc9(1): 2+1+362+1 us, 0 -> 1 MB, 10159 (13796-3637) objects, 6 goroutines,
    140/80/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    gc10(1): 2+1+568+0 us, 0 -> 1 MB, 12398 (19316-6918) objects, 6 goroutines,
    168/133/0 sweeps, 0(0) handoff, 0(0) steal, 0/0/0 yields
    --- FAIL: TestWaitTestStress (0.20s)
    wait_time_test.go:67: cannot receive from ch as expected
    ```

    If any channel failed to receive the response in 10ms, the test fails.
    On Wed, Jun 24, 2015 at 7:01 PM, Brad Fitzpatrick wrote:

    OS? Arch? Go version?

    I assume linux-amd64 from coreos.com and -race. But which Go version?

    I wonder if you're just generating lots of garbage and causing the GC to
    run, making that time.After channel 10000 times.


    On Wed, Jun 24, 2015 at 11:27 PM, Yicheng Qin wrote:

    Hi all,

    We observe at least 10ms delay before receiving message from closed
    buffered channel. We met this when we run some code basically like this:

    ```
    chs := make([]chan struct{}, 10000)
    // init
    for i := range chs {
    chs[i] = make(chan struct{}, 1)
    }
    // close
    for _, ch := range chs {
    close(ch)
    }
    // receive
    for _, ch := range chs {
    select {
    case <-ch:
    case <-time.After(10 * time.Millisecond):
    t.Fatalf("")
    }
    }
    ```

    The test environment is under --cpu 4 --race on travis(2 bursted cpu)
    when running `go test` for the whole test set. After I adjust the timeout
    to 1s, I didn't observe this behavior anymore. Is this behavior expected?

    I check the spec, which says that `After calling close, and after any
    previously sent values have been received, receive operations will return
    the zero value for the channel's type without blocking.`

    --
    You received this message because you are subscribed to the Google Groups
    "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an
    email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
  • Russ Cox at Jun 25, 2015 at 5:11 pm ⇧
    In this code:

       select {
       case <-ch:
       case <-time.After(10 * time.Millisecond):
         t.Fatalf("")
       }

    If the second case triggers, it does not imply that the channel is not
    closed (obviously it is closed, since you closed it before executing the
    select). It means that in the time between time.After setting the timer for
    its channel and the time that select looked at the channel, the timer went
    off. As Brad speculated, it could be garbage collection. It could also be
    that your process was interrupted by the operating system so that some
    other process could run. There are many possible reasons. I would not worry
    about it happening once in a while. It might be more interesting to check
    how many times it happens out of the 10000.

    Russ

    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
  • Yicheng Qin at Jun 25, 2015 at 5:34 pm ⇧
    Got it. So i will make it wait longer to pass every time.

    The long delay starts to happen when we set --cpu > 1. It happens once per
    100 tests, so the probability is 1 out of 1 million times.

    It confused me most due to its order. When it comes to the select
    statement, the `ch` has been closed, and `time.After` is not called. But it
    goes into the `time.After` case finally. I guess its internal
    implementation is to 1. execute `time.After` 2. wait for two channels 3.
    select one from ready channels randomly.
    On Thu, Jun 25, 2015 at 10:11 AM, Russ Cox wrote:

    In this code:

    select {
    case <-ch:
    case <-time.After(10 * time.Millisecond):
    t.Fatalf("")
    }

    If the second case triggers, it does not imply that the channel is not
    closed (obviously it is closed, since you closed it before executing the
    select). It means that in the time between time.After setting the timer for
    its channel and the time that select looked at the channel, the timer went
    off. As Brad speculated, it could be garbage collection. It could also be
    that your process was interrupted by the operating system so that some
    other process could run. There are many possible reasons. I would not worry
    about it happening once in a while. It might be more interesting to check
    how many times it happens out of the 10000.

    Russ
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
  • Brad Fitzpatrick at Jun 25, 2015 at 8:28 pm ⇧
    The time.After _is_ evaluated each time.

    From http://golang.org/ref/spec#Select_statements :

    `
    Execution of a "select" statement proceeds in several steps:

    1) For all the cases in the statement, the channel operands of receive
    operations and the channel and right-hand-side expressions of send
    statements are evaluated exactly once, in source order, upon entering the
    "select" statement.
    ...
    `


    On Thu, Jun 25, 2015 at 7:34 PM, Yicheng Qin wrote:

    Got it. So i will make it wait longer to pass every time.

    The long delay starts to happen when we set --cpu > 1. It happens once per
    100 tests, so the probability is 1 out of 1 million times.

    It confused me most due to its order. When it comes to the select
    statement, the `ch` has been closed, and `time.After` is not called. But it
    goes into the `time.After` case finally. I guess its internal
    implementation is to 1. execute `time.After` 2. wait for two channels 3.
    select one from ready channels randomly.
    On Thu, Jun 25, 2015 at 10:11 AM, Russ Cox wrote:

    In this code:

    select {
    case <-ch:
    case <-time.After(10 * time.Millisecond):
    t.Fatalf("")
    }

    If the second case triggers, it does not imply that the channel is not
    closed (obviously it is closed, since you closed it before executing the
    select). It means that in the time between time.After setting the timer for
    its channel and the time that select looked at the channel, the timer went
    off. As Brad speculated, it could be garbage collection. It could also be
    that your process was interrupted by the operating system so that some
    other process could run. There are many possible reasons. I would not worry
    about it happening once in a while. It might be more interesting to check
    how many times it happens out of the 10000.

    Russ
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.
  • Yicheng Qin at Jun 25, 2015 at 10:13 pm ⇧
    Exactly what I need to know.
    Thanks for the help to track down this!
    On Thu, Jun 25, 2015 at 1:28 PM, Brad Fitzpatrick wrote:

    The time.After _is_ evaluated each time.

    From http://golang.org/ref/spec#Select_statements :

    `
    Execution of a "select" statement proceeds in several steps:

    1) For all the cases in the statement, the channel operands of receive
    operations and the channel and right-hand-side expressions of send
    statements are evaluated exactly once, in source order, upon entering the
    "select" statement.
    ...
    `


    On Thu, Jun 25, 2015 at 7:34 PM, Yicheng Qin wrote:

    Got it. So i will make it wait longer to pass every time.

    The long delay starts to happen when we set --cpu > 1. It happens once
    per 100 tests, so the probability is 1 out of 1 million times.

    It confused me most due to its order. When it comes to the select
    statement, the `ch` has been closed, and `time.After` is not called. But it
    goes into the `time.After` case finally. I guess its internal
    implementation is to 1. execute `time.After` 2. wait for two channels 3.
    select one from ready channels randomly.
    On Thu, Jun 25, 2015 at 10:11 AM, Russ Cox wrote:

    In this code:

    select {
    case <-ch:
    case <-time.After(10 * time.Millisecond):
    t.Fatalf("")
    }

    If the second case triggers, it does not imply that the channel is not
    closed (obviously it is closed, since you closed it before executing the
    select). It means that in the time between time.After setting the timer for
    its channel and the time that select looked at the channel, the timer went
    off. As Brad speculated, it could be garbage collection. It could also be
    that your process was interrupted by the operating system so that some
    other process could run. There are many possible reasons. I would not worry
    about it happening once in a while. It might be more interesting to check
    how many times it happens out of the 10000.

    Russ
    --
    You received this message because you are subscribed to the Google Groups "golang-nuts" group.
    To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/d/optout.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupgolang-nuts @
categoriesgo
postedJun 24, '15 at 9:27p
activeJun 25, '15 at 10:13p
posts7
users3
websitegolang.org

3 users in discussion

Yicheng Qin: 4 posts Brad Fitzpatrick: 2 posts Russ Cox: 1 post

Content

People

Support

Translate

site design / logo © 2021 Grokbase