I can apply the patch at https://go-review.googlesource.com/#/c/24706/1/src/runtime/mgcmark.go to an updated master source and test it.
Could it be useful for you?

@genez, thanks for offering. There's no harm in testing with that patch, but I'm not sure it would be useful.

I explored this problem more today. The rpc benchmark from gcbench shows this off particularly well. This benchmark fires up trivial client and server processes, which communicate over a set of TCP sockets. The client uses open-loop control to send requests according to a Poisson process, which models the behavior of real RPC systems.

This is what the execution trace looks like during a GC:

G18 and G19 are the background workers. You can see that they always run for a full quantum, and often run simultaneously, blocking both Ps. Also, even though there's only a little overall idle time, together they're clearly taking up much more than 25% of the total CPU. In the goroutines row, you can see the system regularly falling behind throughout the GC cycle, and in the network row, you can see it mostly falls back to the periodic sysmon network poll.

CL 30031 is an experiment that changes the idle worker to constantly poll for either run queue work or network wake-ups. With this CL, the trace looks very different (trace file):

In this trace, G8 and G9 are the background workers. There are still large regions where they're running the fractional worker, but there's only one at a time, and they add up to almost exactly 25% of the CPU. In the goroutines and network rows, you can see that it still falls behind at the beginning of GC and switches to the sysmon network poll. However, about 80ms in to the cycle, it catches up and things run quite smoothly for the rest of the cycle: the goroutine queue stays short, and network events are coming in rapidly.

There are a few extra colors in this trace. In the lower half of each proc row, red means "syscall" (which means user code in this case), teal means "assist", and blue means "idle worker". At the beginning of GC, when the system is falling behind, there are a lot of assists. In fact, this phase lasts about 70ms, which is right around the P99.9 and max latencies of this run. Eventually, however, the background workers get ahead, the assists stop, the runnable goroutine queue drains, we start having idle time again, and we start seeing the idle worker kicking in for very brief periods.

CL https://golang.org/cl/32433 mentions this issue.

@aclements just as an additional data point, I got around to running the small micro benchmark that I wrote for: #17341

So I ran it with few different versions of GO, something like:

Go1.7
GODEBUG=gctrace=1 ./net_gctest_GO17 -port=5001 -nroutines=30000 -sleep_t=3s -max_latency=30ms -total_qps=5000000 &> gcbench_5mln_go17.txt

Go: d70b0fe...
GODEBUG=gctrace=1 ./net_gctest_GOd70b0fe -port=5001 -nroutines=30000 -sleep_t=3s -max_latency=30ms -total_qps=5000000 &> gcbench_5mln_god70b0fe.txt

Go: 8ddf8d4ea...
GODEBUG=gctrace=1 ./net_gctest_GO8ddf8d4ea -port=5001 -nroutines=30000 -sleep_t=3s -max_latency=30ms -total_qps=5000000 &> gcbench_5mln_go8ddf8d4ea.txt

So each one does 5mln QPS total in the benchmark, and then I checked how many out of these 5mln QPS took more than 30ms.

cat gcbench_5mln_go17.txt | grep "STALL" | wc -l
12298

cat gcbench_5mln_god70b0fe.txt | grep "STALL" | wc -l
27679

cat gcbench_5mln_go8ddf8d4ea.txt | grep "STALL" | wc -l
30877

So overall it looks like, there are actually more requests that are slowed down/stuck than there were before.

Note that this experiment is running on a pretty beefy machine in general, so there is almost no CPU utilization, since it is only doing 10k QPS. Also as before the GC lines look something like:

gc 31 @314.612s 0%: 0.35+174+1.1 ms clock, 10+590/1383/3164+35 ms cpu, 1411->1415->723 MB, 1447 MB goal, 32 P
gc 32 @330.130s 0%: 0.32+174+1.4 ms clock, 10+595/1358/3004+45 ms cpu, 1411->1415->723 MB, 1447 MB goal, 32 P

So there is almost no STW gc time, it is all in the concurrent phase.

I can also try to augment the benchmark to to get the perf traces too if that will be helpful.

Actually looks like I made a mistake of not properly rebuilding things with GO master, so I have rebuilt it properly and thinks do look better with the patch compared to Go1.7:

Finishing Up. GO Version: devel +8ddf8d4 Sun Oct 30 20:27:14 2016 -0400,
Total Queries: 2000000, STALLS: 2301

Finishing Up. GO Version: devel +d70b0fe Fri Oct 28 18:07:30 2016 +0000,
TOTAL Queries: 2000000, STALLS: 11606

Finishing Up. GO Version: go1.7.1, Total Queries: 2000000, STALLS: 6952

So there are almost 3 times less stalls with +8ddf8d4 compared to GO 1.7. But it looks like at d70b0fe things got worse with related to stalls compared to GO 1.7.

Thanks for the data points @zviadm. Just to clarify, do you mean commit d70b0fe specifically made the stalls worse (compared to d70b0fe^), or just that they got worse between go1.7.1 and d70b0fe?

I only did tests with Go1.7 and d70b0fe. So things just got worse sometime between Go 1.7.1 and d70b0fe.

One more data point, I ran a more real/complex application experiment with: 8ddf8d4. There is definitely improvement, but having lots of go routines is still quite problematic.
Here are some numbers from experiment for a RPC call (times are end to end measured from client side):

• p75: ~0.5ms (which is great)
• p95: ~27ms (which is quite bad for low latency service)
• p99: ~100ms

The p75 times are great, however because of huge p95/p99 times, even average latency is at ~5ms.

This real application also has similar GC situation where actual STW times are <1-2ms. The concurrent part of GC is taking 100-150ms, and it still causes massive p95/p99 request spikes.

Some more numbers from scale perspective:
-> there were ~60k open mostly idle connections per process.
-> single process was doing ~40-45k QPS.
-> single process runs on a single NUMA socket with 16 hyperthreaded cores.

When same experiment is done with 6k total connections, but same exact QPS (i.e. less clients that are more active), performance is significantly better, with p99 times in <=5ms range, because concurrent GC time is much smaller.

@zviadm, thanks for the data. Hopefully the commit I just pushed helps, but it sounds like there are other latency issues affecting your benchmark. This isn't too surprising; we're aware there are other issues. I also have an RPC microbenchmark that shows similar tail latency behavior to yours. I don't completely understand what's going on in my benchmark, but I've analyzed it enough to determine that it's something subtler than the GC just taking away long time slices.

You might want to follow #14812, though it's possible that issue has been fixed (waiting on confirmation). If it has, I'll open up a new tracking bug.