runtime: allow preemption-disable around critical section

[donovanhide]

Go version

go version go1.22.0 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN='/Users/***/gopath/bin'
GOCACHE='/Users/***/Library/Caches/go-build'
GOENV='/Users/***/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/***/gopath/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/***/gopath'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.22.0/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.22.0/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.0'
GCCGO='gccgo'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/0q/57ygjhqj3k59y4b8txgw839r0000gn/T/go-build2558853606=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

Running my application I have been investigating some long tail latency which is causing backlogs in the processing of incoming message. The application processes between 4,000 to 50,0000 incoming JSON messages a second, delivered over websocket connections. These messages are unmarshalled on between 8 and 16 separate sockets with a goroutine doing the reading on each. All unmarshalled messages are sent over a single channel to another goroutine that does time sensitive calculations on the resultant state of those messages. There are virtually no memory allocations and GC pauses typically happen once every 30 seconds. This goroutine running its calculation in a speedy manner is critical to the success of the application.

What did you see happen?

Under normal compilation using go 1.22, there is significant long tail (0.9999 percentile) latency of 5-15 ms on the time taken to complete the calculation which typically takes 30-90µs (0.99 percentile). With the asyncpreemptoff flag set on GODEBUG, this latency (0.9999 percentile) falls below 1ms. The following image graphs the changed before and after setting the flag:

What did you expect to see?

I understand why preemption is useful for long running goroutines that starve other goroutines of access to the CPU, but I would not expect there to be such latency from its use. Being able to disable preemption for specific goroutines might be one solution. If you would like any more specific traces or profiles, happy to provide them. It would be difficult for me to provide a reproducer as the timings of all involved goroutines are very dependent on third party external state.

[mauri870]

cc @golang/runtime

[prattmic]

Interesting issue. The purpose of asynchronous preemption is to reduce tail latency, so seeing it increase tail latency instead isn't great.

One way I could imagine this happening would be if you have many goroutines, but they fall into two buckets: high priority, latency sensitive or low priority, latency tolerant. If the high priority goroutines happen to have tight loops that don't have synchronous preemption points, then asynchronous preemption would preempt them more often. This would improve latency of the low priority goroutines at the expense of the high priority goroutines latency. Does this describe your application?

One piece of data I'd like to see is /sched/latencies:seconds from https://pkg.go.dev/runtime/metrics with and without asyncpreemptoff. Note that this histogram is cumulative since process start, so you only need to collect it once at the end. https://go.dev/cl/513115 has some code you can copy to format the data into a ASCII graph.

[prattmic]

cc @golang/runtime @mknyszek @aclements

[donovanhide]

Hi again.

I think I may have used some bad PromQL (irate vs rate with a push gateway and inconsistent intervals) in Grafana to generate that seemingly conclusive graph above. It seems like asyncpreemptoff is not related to my issue as perhaps the /sched/latencies:seconds data below perhaps demonstrates. I could not reproduce the effects of asyncpreemptoff affecting latency again.

What I am still seeing with asyncpreemptoff enabled or disabled is that the CPU bound function in the crucial goroutine is, once every 10,000 messages or so, taking many milliseconds to complete, despite the actual processing parts taking microseconds to complete. This then creates a backlog in a queue, which has knock on effects for the subsequent iterations of the crucial goroutine. As you describe there are two sets of goroutines, a latency sensitive one, which does not want to be interrupted, and many asynchronous ones waiting on bytes to come in over the network. Another scheduler in another language discusses the issues and possible solutions better than I can:

https://docs.rs/tokio/latest/tokio/#cpu-bound-tasks-and-blocking-code

It's not necessarily a priority problem, just a "please do not interrupt me until I reach a channel send or receive op, which I will probably do very soon". If such a flag could be set at the start of the goroutine, that would help my use case. If that flag was set for all goroutines, then I guess CPU starvation is likely....

Anyway, thanks for your time! Any tips gladly received! Please feel free to close the issue if desired.

Results with:
GODEBUG=asyncpreemptoff=1

                    |      0 [  -Inf,    0.0)
********************| 611508 [   0.0,   64.0)
                    |  23961 [  64.0,  128.0)
                 ***| 102487 [ 128.0,  192.0)
                  **|  74167 [ 192.0,  256.0)
                    |  19521 [ 256.0,  320.0)
                   *|  38501 [ 320.0,  384.0)
           *********| 295493 [ 384.0,  448.0)
            ********| 266913 [ 448.0,  512.0)
               *****| 174287 [ 512.0,  640.0)
                  **|  84142 [ 640.0,  768.0)
                 ***| 119178 [ 768.0,  896.0)
                  **|  89576 [ 896.0, 1024.0)
                 ***|  92763 [1024.0, 1280.0)
                   *|  37674 [1280.0, 1536.0)
                    |  18239 [1536.0, 1792.0)
                    |  16608 [1792.0, 2048.0)
                    |  26630 [2048.0, 2560.0)
                    |  20516 [2560.0, 3072.0)
                    |  17352 [3072.0, 3584.0)
                    |  19656 [3584.0, 4096.0)
                    |  29331 [4096.0, 5120.0)
                    |  20887 [5120.0, 6144.0)
                   *|  33623 [6144.0, 7168.0)
                   *|  41952 [7168.0, 8192.0)
                  **|  70560 [8192.0, 10240.0)
                   *|  43181 [10240.0, 12288.0)
                   *|  44811 [12288.0, 14336.0)
                   *|  43833 [14336.0, 16384.0)
                   *|  44537 [16384.0, 20480.0)
                    |  30200 [20480.0, 24576.0)
                    |  28594 [24576.0, 28672.0)
                    |  24048 [28672.0, 32768.0)
                 ***| 107010 [32768.0, 40960.0)
                   *|  59413 [40960.0, 49152.0)
                    |  29004 [49152.0, 57344.0)
                    |  13850 [57344.0, 65536.0)
                    |  11805 [65536.0, 81920.0)
                    |   4973 [81920.0, 98304.0)
                    |   2553 [98304.0, 114688.0)
                    |   1749 [114688.0, 131072.0)
                    |   2346 [131072.0, 163840.0)
                    |   1385 [163840.0, 196608.0)
                    |    949 [196608.0, 229376.0)
                    |    694 [229376.0, 262144.0)
                    |    958 [262144.0, 327680.0)
                    |    562 [327680.0, 393216.0)
                    |    415 [393216.0, 458752.0)
                    |    229 [458752.0, 524288.0)
                    |    289 [524288.0, 655360.0)
                    |    167 [655360.0, 786432.0)
                    |     85 [786432.0, 917504.0)
                    |     60 [917504.0, 1048576.0)
                    |     69 [1048576.0, 1310720.0)
                    |     59 [1310720.0, 1572864.0)
                    |     41 [1572864.0, 1835008.0)
                    |     33 [1835008.0, 2097152.0)
                    |     51 [2097152.0, 2621440.0)
                    |     12 [2621440.0, 3145728.0)
                    |     14 [3145728.0, 3670016.0)
                    |     10 [3670016.0, 4194304.0)
                    |     22 [4194304.0, 5242880.0)
                    |     15 [5242880.0, 6291456.0)
                    |     11 [6291456.0, 7340032.0)
                    |      5 [7340032.0, 8388608.0)
                    |     15 [8388608.0, 10485760.0)
                    |      4 [10485760.0, 12582912.0)
                    |      7 [12582912.0, 14680064.0)
                    |      2 [14680064.0, 16777216.0)
                    |      6 [16777216.0, 20971520.0)
                    |      2 [20971520.0, 25165824.0)
                    |      1 [25165824.0, 29360128.0)
                    |      0 [29360128.0, 33554432.0)
                    |      1 [33554432.0, 41943040.0)
                    |      0 [41943040.0, 50331648.0)
                    |      0 [50331648.0, 58720256.0)
                    | ...
                    |      0 [105553116266496.0, 123145302310912.0)
                    |      0 [123145302310912.0, 140737488355328.0)
                    |      0 [140737488355328.0,   +Inf)

Results without

                     |      0 [  -Inf,    0.0)
********************| 636929 [   0.0,   64.0)
                    |  24445 [  64.0,  128.0)
                 ***|  99320 [ 128.0,  192.0)
                  **|  82062 [ 192.0,  256.0)
                    |  22599 [ 256.0,  320.0)
                   *|  37629 [ 320.0,  384.0)
            ********| 273426 [ 384.0,  448.0)
            ********| 275386 [ 448.0,  512.0)
               *****| 185945 [ 512.0,  640.0)
                  **|  80218 [ 640.0,  768.0)
                ****| 128796 [ 768.0,  896.0)
                  **|  85224 [ 896.0, 1024.0)
                  **|  83437 [1024.0, 1280.0)
                   *|  34046 [1280.0, 1536.0)
                    |  17497 [1536.0, 1792.0)
                    |  17253 [1792.0, 2048.0)
                    |  27411 [2048.0, 2560.0)
                    |  20776 [2560.0, 3072.0)
                    |  17502 [3072.0, 3584.0)
                    |  21533 [3584.0, 4096.0)
                    |  28812 [4096.0, 5120.0)
                    |  19218 [5120.0, 6144.0)
                    |  30163 [6144.0, 7168.0)
                   *|  39716 [7168.0, 8192.0)
                  **|  70413 [8192.0, 10240.0)
                   *|  43146 [10240.0, 12288.0)
                   *|  46100 [12288.0, 14336.0)
                   *|  46865 [14336.0, 16384.0)
                   *|  45291 [16384.0, 20480.0)
                    |  30861 [20480.0, 24576.0)
                    |  28138 [24576.0, 28672.0)
                    |  24143 [28672.0, 32768.0)
                 ***| 114946 [32768.0, 40960.0)
                   *|  58894 [40960.0, 49152.0)
                    |  30010 [49152.0, 57344.0)
                    |  13650 [57344.0, 65536.0)
                    |  11804 [65536.0, 81920.0)
                    |   5049 [81920.0, 98304.0)
                    |   2803 [98304.0, 114688.0)
                    |   1888 [114688.0, 131072.0)
                    |   2275 [131072.0, 163840.0)
                    |   1445 [163840.0, 196608.0)
                    |    988 [196608.0, 229376.0)
                    |    728 [229376.0, 262144.0)
                    |    879 [262144.0, 327680.0)
                    |    558 [327680.0, 393216.0)
                    |    355 [393216.0, 458752.0)
                    |    228 [458752.0, 524288.0)
                    |    244 [524288.0, 655360.0)
                    |    143 [655360.0, 786432.0)
                    |     66 [786432.0, 917504.0)
                    |     55 [917504.0, 1048576.0)
                    |     74 [1048576.0, 1310720.0)
                    |     35 [1310720.0, 1572864.0)
                    |     36 [1572864.0, 1835008.0)
                    |     29 [1835008.0, 2097152.0)
                    |     45 [2097152.0, 2621440.0)
                    |     39 [2621440.0, 3145728.0)
                    |      9 [3145728.0, 3670016.0)
                    |      7 [3670016.0, 4194304.0)
                    |     14 [4194304.0, 5242880.0)
                    |     15 [5242880.0, 6291456.0)
                    |      6 [6291456.0, 7340032.0)
                    |      4 [7340032.0, 8388608.0)
                    |     14 [8388608.0, 10485760.0)
                    |      6 [10485760.0, 12582912.0)
                    |      4 [12582912.0, 14680064.0)
                    |      6 [14680064.0, 16777216.0)
                    |      3 [16777216.0, 20971520.0)
                    |      1 [20971520.0, 25165824.0)
                    |      2 [25165824.0, 29360128.0)
                    |      3 [29360128.0, 33554432.0)
                    |      0 [33554432.0, 41943040.0)
                    |      1 [41943040.0, 50331648.0)
                    |      0 [50331648.0, 58720256.0)
                    |      0 [58720256.0, 67108864.0)
                    | ...
                    |      0 [105553116266496.0, 123145302310912.0)
                    |      0 [123145302310912.0, 140737488355328.0)
                    |      0 [140737488355328.0,   +Inf)

[prattmic]

Thanks, I'm glad the problem is better understood now.

What you are asking for is a mechanism to disable preemption when executing some critical section. I don't think we have an existing issue for that, so this can serve that purpose, though I don't think it is something we clearly want to do.

I figured we would also have an issue for goroutine priorities, though I can't seem to find one.