Yes, this sounds a lot like https://golang.org/issue/16293, where goroutines that allocate memory while the garbage collector is running can end up stalled for nearly the entire GC cycle, in programs where a large amount of the memory is in a single allocation. For the program you've shared, that would be the "channel" map. The bug is present in Go 1.5–1.7, and is fixed in tip (via CL 23540).
Do you still see the problem if you run the program with the current development version of Go? On Wednesday, October 19, 2016 at 6:10:23 AM UTC-7, r...@golang.org wrote: > > This is likely 23540 <https://go-review.googlesource.com/#/c/23540/>. > > > On Wednesday, October 19, 2016 at 8:32:18 AM UTC-4, Will Sewell wrote: >> >> Hey, I previously posted this on StackOverflow, but I was told this >> mailing list would be a better forum for discussion. >> >> I am attempting to benchmark the maximum STW GC pause time for different >> numbers of heap objects. To do this I have written a simple benchmark that >> pushes and pops messages from a map: >> >> package main >> >> type message []byte >> >> type channel map[int]message >> >> const ( >> windowSize = 200000 >> msgCount = 1000000 >> ) >> >> func mkMessage(n int) message { >> m := make(message, 1024) >> for i := range m { >> m[i] = byte(n) >> } >> return m >> } >> >> >> func pushMsg(c *channel, highID int) { >> lowID := highID - windowSize >> m := mkMessage(highID) >> (*c)[highID] = m >> if lowID >= 0 { >> delete(*c, lowID) >> } >> } >> >> >> func main() { >> c := make(channel) >> for i := 0; i < msgCount; i++ { >> pushMsg(&c, i) >> } >> } >> >> I ran this with GODEBUG=gctrace=1 <https://golang.org/pkg/runtime/>, and >> on my machine the output is: >> >> gc 1 @0.004s 2%: 0.007+0.44+0.032 ms clock, 0.029+0.22/0.20/0.28+0.12 ms >> cpu, 4->4->3 MB, 5 MB goal, 4 P >> gc 2 @0.009s 3%: 0.007+0.64+0.042 ms clock, 0.030+0/0.53/0.18+0.17 ms cpu >> , 7->7->7 MB, 8 MB goal, 4 P >> gc 3 @0.019s 1%: 0.007+0.99+0.037 ms clock, 0.031+0/0.13/1.0+0.14 ms cpu, >> 13->13->13 MB, 14 MB goal, 4 P >> gc 4 @0.044s 2%: 0.009+2.3+0.032 ms clock, 0.039+0/2.3/0.30+0.13 ms cpu, >> 25->25->25 MB, 26 MB goal, 4 P >> gc 5 @0.081s 1%: 0.009+9.2+0.082 ms clock, 0.039+0/0.32/9.7+0.32 ms cpu, >> 49->49->48 MB, 50 MB goal, 4 P >> gc 6 @0.162s 0%: 0.020+10+0.078 ms clock, 0.082+0/0.28/11+0.31 ms cpu, 93 >> ->93->91 MB, 96 MB goal, 4 P >> gc 7 @0.289s 0%: 0.020+27+0.092 ms clock, 0.080+0/0.95/28+0.37 ms cpu, >> 178->178->173 MB, 182 MB goal, 4 P >> gc 8 @0.557s 1%: 0.023+38+0.086 ms clock, 0.092+0/38/10+0.34 ms cpu, 337 >> ->339->209 MB, 346 MB goal, 4 P >> gc 9 @0.844s 1%: 0.008+40+0.077 ms clock, 0.032+0/5.6/46+0.30 ms cpu, 407 >> ->409->211 MB, 418 MB goal, 4 P >> gc 10 @1.100s 1%: 0.009+43+0.047 ms clock, 0.036+0/6.6/50+0.19 ms cpu, >> 411->414->212 MB, 422 MB goal, 4 P >> gc 11 @1.378s 1%: 0.008+45+0.093 ms clock, 0.033+0/6.5/52+0.37 ms cpu, >> 414->417->213 MB, 425 MB goal, 4 P >> >> My version of Go is: >> >> $ go version >> go version go1.7.1 darwin/amd64 >> >> From the above results, the longest wall clock STW pause time is 0.093ms. >> Great! >> >> However as a sanity check I also manually timed how long it took to >> create a new message by wrapping mkMessage with >> >> start := time.Now() >> m := mkMessage(highID) >> elapsed := time.Since(start) >> >> and printed the slowest `elapsed` time. The time I get for this was >> 38.573036ms! >> >> I was instantly suspicious because this correlated strongly with the wall >> clock times in the supposedly concurrent mark/scan phase, and in particular >> with "idle GC time". >> >> *My question is: why does this supposedly concurrent phase of the GC >> appear to block the mutator?* >> >> If I force the GC to run at regular intervals, my manually calculated >> pause times go way down to <1ms, so it appears to be hitting some kind of >> limit of non-live heap objects. If so, I'm not sure what that limit is, and >> why it would cause a concurrent phase of the GC to appear to block the >> mutator. >> >> Thanks! >> > -- 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+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.
