runtime: excessive memory fragmentation ; performance (investigation)

jgraettinger commented 3 years ago

( To be filled in with details )

jgraettinger commented 3 years ago

goroutine trace from a wedged pod which may be related:

``` {"id":"XXX/00000000-00000000","level":"info","msg":"stopping local shard","time":"2021-09-09T20:04:18Z"} {"id":"XXX/00000000-00000000","level":"info","msg":"stopping local shard","time":"2021-09-09T20:04:19Z"} {"err":"reading Load: EOF","fence":136,"keyBegin":0,"keyEnd":4294967295,"level":"error","load":292320,"loaded":0,"materialization":"XXX","msg":"Load failed","round":0,"time":"2021-09-09T20:04:19Z"} {"err":"reading Load: EOF","fence":136,"keyBegin":0,"keyEnd":4294967295,"level":"error","materialization":"XXX","msg":"RunTransactions failed","time":"2021-09-09T20:04:19Z"} {"lastRevision":30174,"level":"info","msg":"initialized catalog task term","range":"key:00000000-ffffffff;r-clock:00000000-ffffffff","revision":30174,"shard":"XXX/00000000-00000000","task":"XXX","time":"2021-09-09T20:06:57Z"} {"args":["docker","run","--rm","--mount","type=bind,source=/tmp/connector-file397236653,target=/tmp/config.json","--mount","type=bind,source=/tmp/connector-file347054376,target=/tmp/catalog.json","--mount","type=bind,source=/tmp/connector-file964337818,target=/tmp/state.json","ghcr.io/estuary/source-s3:4696f9a","read","--config","/tmp/config.json","--catalog","/tmp/catalog.json","--state","/tmp/state.json"],"level":"info","msg":"invoking connector","time":"2021-09-09T20:06:57Z"} {"err":"exit status 125 with stderr:\n\ndocker: Cannot connect to the Docker daemon at tcp://localhost:2376. Is the docker daemon running?.\nSee 'docker run --help'.\n","level":"info","msg":"connector exited","time":"2021-09-09T20:06:57Z"} {"err":"exit status 125 with stderr:\n\ndocker: Cannot connect to the Docker daemon at tcp://localhost:2376. Is the docker daemon running?.\nSee 'docker run --help'.\n","level":"error","msg":"capture connector failed","shard":"XXX/00000000-00000000","time":"2021-09-09T20:06:57Z"} {"id":"XXX/00000000-00000000","level":"info","msg":"stopping local shard","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"Allocate","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"server.ServeCMux","time":"2021-09-09T20:08:28Z"} {"lastRevision":30174,"level":"info","msg":"initialized catalog task term","range":"key:00000000-ffffffff;r-clock:00000000-ffffffff","revision":30174,"shard":"XXX/00000000-00000000","task":"XXX","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"server.ServeHTTP","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"journals.Watch","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"server.ServeGRPC","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"service.Watch","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"catalog.Watch","time":"2021-09-09T20:08:28Z"} {"level":"info","msg":"task completed","task":"lease.Close","time":"2021-09-09T20:08:28Z"} SIGQUIT: quit PC=0x5dc2c1 m=0 sigcode=0 goroutine 0 [idle]: runtime.futex(0x3655710, 0x80, 0x0, 0x0, 0x7fff00000000, 0x7fffca9757b2, 0x36555c0, 0x1, 0x7fffca879ef8, 0x5741df, ...) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/sys_linux_amd64.s:579 +0x21 runtime.futexsleep(0x3655710, 0x0, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/os_linux.go:44 +0x46 runtime.notesleep(0x3655710) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/lock_futex.go:159 +0x9f runtime.mPark() /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/proc.go:1340 +0x39 runtime.stopm() /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/proc.go:2301 +0x92 runtime.findrunnable(0xc00004c000, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/proc.go:2960 +0x72e runtime.schedule() /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/proc.go:3169 +0x2d7 [864/1803]runtime.park_m(0xc0005ce480) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/proc.go:3318 +0x9d runtime.mcall(0x21e3240) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/asm_amd64.s:327 +0x5b goroutine 1 [semacquire, 37 minutes]: sync.runtime_Semacquire(0xc0003c31b0) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/sema.go:56 +0x45 sync.(*WaitGroup).Wait(0xc0003c31a8) /opt/hostedtoolcache/go/1.16.6/x64/src/sync/waitgroup.go:130 +0x65 golang.org/x/sync/errgroup.(*Group).Wait(0xc0003c31a0, 0xc00099f670, 0x2) /home/runner/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:40 +0x31 go.gazette.dev/core/task.(*Group).Wait(...) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/task/group.go:89 go.gazette.dev/core/mainboilerplate/runconsumer.Cmd.Execute(0x2856c40, 0xc0002460f0, 0x2892be0, 0xc000397f80, 0xc0003ab760, 0x0, 0x16, 0x0, 0x0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/mainboilerplate/runconsumer/run_consumer.go:188 +0xeb9 github.com/estuary/flow/go/runtime.(*FlowConsumerConfig).Execute(0xc0002460f0, 0xc0003ab760, 0x0, 0x16, 0xc0002460f0, 0x1) /home/runner/work/flow/flow/go/runtime/flow_consumer.go:43 +0x7f github.com/jessevdk/go-flags.(*Parser).ParseArgs(0xc00036cee0, 0xc000001b10, 0x16, 0x17, 0xc000397b90, 0xc000777d58, 0xdec149, 0xc000285830, 0x18) /home/runner/go/pkg/mod/github.com/jessevdk/go-flags@v1.5.0/parser.go:335 +0x89d go.gazette.dev/core/mainboilerplate.MustParseArgs(0xc00036cee0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/mainboilerplate/config.go:49 +0x85 go.gazette.dev/core/mainboilerplate.MustParseConfig(0xc00036cee0, 0x259ce76, 0x8) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/mainboilerplate/config.go:44 +0x36e main.main() /home/runner/work/flow/flow/go/flowctl/main.go:70 +0x5ea goroutine 57 [select]: go.opencensus.io/stats/view.(*worker).start(0xc000324230) /home/runner/go/pkg/mod/go.opencensus.io@v0.22.3/stats/view/worker.go:154 +0xcd created by go.opencensus.io/stats/view.init.0 /home/runner/go/pkg/mod/go.opencensus.io@v0.22.3/stats/view/worker.go:32 +0x57 goroutine 114 [select, 37 minutes]: google.golang.org/grpc.(*ccBalancerWrapper).watcher(0xc0002d7c40) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/balancer_conn_wrappers.go:69 +0xac created by google.golang.org/grpc.newCCBalancerWrapper /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/balancer_conn_wrappers.go:60 +0x172 goroutine 115 [select]: go.gazette.dev/core/broker/protocol.(*dispatcher).servePeriodicSweeps(0xc0004333e0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/broker/protocol/dispatcher.go:307 +0x85 created by go.gazette.dev/core/broker/protocol.dispatcherBuilder.Build /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/broker/protocol/dispatcher.go:350 +0x145 goroutine 269 [chan receive]: github.com/estuary/flow/go/runtime.(*FlowConsumer).InitApplication.func6(0xc000397f80) /home/runner/work/flow/flow/go/runtime/flow_consumer.go:235 +0x66 created by github.com/estuary/flow/go/runtime.(*FlowConsumer).InitApplication /home/runner/work/flow/flow/go/runtime/flow_consumer.go:234 +0x79e goroutine 204 [syscall, 29 minutes]: os/signal.signal_recv(0x2876a68) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/sigqueue.go:168 +0xa5 os/signal.loop() /opt/hostedtoolcache/go/1.16.6/x64/src/os/signal/signal_unix.go:23 +0x25 created by os/signal.Notify.func1.1 /opt/hostedtoolcache/go/1.16.6/x64/src/os/signal/signal.go:151 +0x45 goroutine 178 [select]: google.golang.org/grpc/internal/transport.(*http2Client).keepalive(0xc0005ca000) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:1421 +0x17a created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:341 +0x178b goroutine 87 [select, 37 minutes]: google.golang.org/grpc.(*ccBalancerWrapper).watcher(0xc00060a500) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/balancer_conn_wrappers.go:69 +0xac created by google.golang.org/grpc.newCCBalancerWrapper /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/balancer_conn_wrappers.go:60 +0x172 goroutine 272 [select]: go.etcd.io/etcd/client/v3.(*lessor).sendKeepAliveLoop(0xc00022cb40, 0x2898590, 0xc00055fc70) /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/lease.go:579 +0x327 created by go.etcd.io/etcd/client/v3.(*lessor).resetRecv /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/lease.go:489 +0x227 goroutine 130 [select]: go.etcd.io/etcd/client/v3.(*Client).autoSync(0xc000636c40) /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/client.go:199 +0xea created by go.etcd.io/etcd/client/v3.newClient /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/client.go:432 +0xa30 goroutine 195 [IO wait]: internal/poll.runtime_pollWait(0x7ff5f46403f0, 0x72, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/netpoll.go:222 +0x55 internal/poll.(*pollDesc).wait(0xc000132518, 0x72, 0x8000, 0x8000, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc000132500, 0xc000908000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_unix.go:166 +0x1d5 net.(*netFD).Read(0xc000132500, 0xc000908000, 0x8000, 0x8000, 0xb3f13e, 0x800010601, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/fd_posix.go:55 +0x4f net.(*conn).Read(0xc000608058, 0xc000908000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/net.go:183 +0x91 bufio.(*Reader).Read(0xc000596780, 0xc0001a23b8, 0x9, 0x9, 0x14, 0x7ff61db10a68, 0x18) /opt/hostedtoolcache/go/1.16.6/x64/src/bufio/bufio.go:227 +0x222 io.ReadAtLeast(0x2855620, 0xc000596780, 0xc0001a23b8, 0x9, 0x9, 0x9, 0xc00055cce8, 0x5c3313, 0x288b05514c2d2) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:328 +0x87 io.ReadFull(...) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:347 golang.org/x/net/http2.readFrameHeader(0xc0001a23b8, 0x9, 0x9, 0x2855620, 0xc000596780, 0x0, 0x0, 0xc046b9c820cbaaf3, 0x204e7d4e71a) [761/1803] /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:237 +0x89 golang.org/x/net/http2.(*Framer).ReadFrame(0xc0001a2380, 0xc0020ac090, 0x36547c0, 0x0, 0x0) /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:492 +0xa5 google.golang.org/grpc/internal/transport.(*http2Client).reader(0xc0003261e0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:1347 +0x1a5 created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:346 +0xdd1 goroutine 196 [select]: google.golang.org/grpc/internal/transport.(*controlBuffer).get(0xc0006044b0, 0x1, 0x0, 0x0, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:407 +0xff google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc000596840, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:527 +0x1dd google.golang.org/grpc/internal/transport.newHTTP2Client.func3(0xc0003261e0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:396 +0x7b created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:394 +0x12ae goroutine 105 [select, 27 minutes]: google.golang.org/grpc.(*ccBalancerWrapper).watcher(0xc0006f7480) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/balancer_conn_wrappers.go:69 +0xac created by google.golang.org/grpc.newCCBalancerWrapper /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/balancer_conn_wrappers.go:60 +0x172 goroutine 194 [sync.Cond.Wait]: sync.runtime_notifyListWait(0xc000486490, 0xc000000010) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/sema.go:513 +0xf8 sync.(*Cond).Wait(0xc000486480) /opt/hostedtoolcache/go/1.16.6/x64/src/sync/cond.go:56 +0x99 google.golang.org/grpc/internal/transport.(*http2Client).keepalive(0xc0003261e0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:1455 +0x35d created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:341 +0x178b goroutine 271 [select, 37 minutes]: google.golang.org/grpc.newClientStreamWithParams.func4(0xc00035a000, 0xc0006e7560, 0x2889a30, 0xc0006eb650) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/stream.go:363 +0xaa created by google.golang.org/grpc.newClientStreamWithParams /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/stream.go:362 +0x965 goroutine 102 [chan receive, 37 minutes]: google.golang.org/grpc.(*addrConn).resetTransport(0xc0002aa840) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:1214 +0x465 created by google.golang.org/grpc.(*addrConn).connect /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:844 +0x12a goroutine 103 [chan receive, 37 minutes]: google.golang.org/grpc.(*addrConn).resetTransport(0xc0002aab00) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:1214 +0x465 created by google.golang.org/grpc.(*addrConn).connect /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:844 +0x12a goroutine 104 [chan receive, 37 minutes]: google.golang.org/grpc.(*addrConn).resetTransport(0xc0002aadc0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:1214 +0x465 created by google.golang.org/grpc.(*addrConn).connect /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:844 +0x12a goroutine 106 [select]: go.gazette.dev/core/broker/protocol.(*dispatcher).servePeriodicSweeps(0xc000432240) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/broker/protocol/dispatcher.go:307 +0x85 created by go.gazette.dev/core/broker/protocol.dispatcherBuilder.Build /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/broker/protocol/dispatcher.go:350 +0x145 goroutine 181 [sync.Cond.Wait]: sync.runtime_notifyListWait(0xc0005cc0d0, 0xc00000000a) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/sema.go:513 +0xf8 sync.(*Cond).Wait(0xc0005cc0c0) /opt/hostedtoolcache/go/1.16.6/x64/src/sync/cond.go:56 +0x99 google.golang.org/grpc/internal/transport.(*http2Client).keepalive(0xc0005ca1e0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:1455 +0x35d created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:341 +0x178b goroutine 179 [IO wait]: internal/poll.runtime_pollWait(0x7ff5f46404d8, 0x72, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/netpoll.go:222 +0x55 internal/poll.(*pollDesc).wait(0xc0001b7498, 0x72, 0x8000, 0x8000, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc0001b7480, 0xc0005ae000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_unix.go:166 +0x1d5 net.(*netFD).Read(0xc0001b7480, 0xc0005ae000, 0x8000, 0x8000, 0xb3f13e, 0x800010601, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/fd_posix.go:55 +0x4f net.(*conn).Read(0xc0005ac000, 0xc0005ae000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/net.go:183 +0x91 bufio.(*Reader).Read(0xc000090600, 0xc0000c4498, 0x9, 0x9, 0x14, 0x7ff61db113c8, 0x18) /opt/hostedtoolcache/go/1.16.6/x64/src/bufio/bufio.go:227 +0x222 io.ReadAtLeast(0x2855620, 0xc000090600, 0xc0000c4498, 0x9, 0x9, 0x9, 0xb25f45, 0xc00060c3b4, 0xc0006de000) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:328 +0x87 io.ReadFull(...) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:347 golang.org/x/net/http2.readFrameHeader(0xc0000c4498, 0x9, 0x9, 0x2855620, 0xc000090600, 0x0, 0x0, 0xc00060c3a8, 0x0) /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:237 +0x89 golang.org/x/net/http2.(*Framer).ReadFrame(0xc0000c4460, 0xc00060c3a8, 0x36547c0, 0x0, 0x0) /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:492 +0xa5 google.golang.org/grpc/internal/transport.(*http2Client).reader(0xc0005ca000) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:1347 +0x1a5 created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:346 +0xdd1 goroutine 180 [select]: google.golang.org/grpc/internal/transport.(*controlBuffer).get(0xc0005c6050, 0x1, 0x0, 0x0, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:407 +0xff google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc0000907e0, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:527 +0x1dd google.golang.org/grpc/internal/transport.newHTTP2Client.func3(0xc0005ca000) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:396 +0x7b created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:394 +0x12ae goroutine 182 [IO wait]: internal/poll.runtime_pollWait(0x7ff5f46405c0, 0x72, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/netpoll.go:222 +0x55 internal/poll.(*pollDesc).wait(0xc000570098, 0x72, 0x8000, 0x8000, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc000570080, 0xc0005d2000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_unix.go:166 +0x1d5 net.(*netFD).Read(0xc000570080, 0xc0005d2000, 0x8000, 0x8000, 0xb3f13e, 0x800010601, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/fd_posix.go:55 +0x4f net.(*conn).Read(0xc0005ac010, 0xc0005d2000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/net.go:183 +0x91 bufio.(*Reader).Read(0xc000090b40, 0xc0000c4578, 0x9, 0x9, 0x14, 0x7ff61db105b8, 0x18) /opt/hostedtoolcache/go/1.16.6/x64/src/bufio/bufio.go:227 +0x222 io.ReadAtLeast(0x2855620, 0xc000090b40, 0xc0000c4578, 0x9, 0x9, 0x9, 0xc00055ace8, 0x5c3313, 0x288a25cb73bb6) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:328 +0x87 io.ReadFull(...) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:347 golang.org/x/net/http2.readFrameHeader(0xc0000c4578, 0x9, 0x9, 0x2855620, 0xc000090b40, 0x0, 0x0, 0xc046b9b920b5137a, 0x1f6ef76f79b) /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:237 +0x89 golang.org/x/net/http2.(*Framer).ReadFrame(0xc0000c4540, 0xc002412030, 0x36547c0, 0x0, 0x0) /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:492 +0xa5 google.golang.org/grpc/internal/transport.(*http2Client).reader(0xc0005ca1e0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:1347 +0x1a5 created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:346 +0xdd1 goroutine 183 [select]: google.golang.org/grpc/internal/transport.(*controlBuffer).get(0xc0005c61e0, 0x1, 0x0, 0x0, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:407 +0xff google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc000090c00, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:527 +0x1dd google.golang.org/grpc/internal/transport.newHTTP2Client.func3(0xc0005ca1e0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:396 +0x7b created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:394 +0x12ae goroutine 276 [select, 25 minutes]: [610/1803]google.golang.org/grpc/internal/transport.(*recvBufferReader).readClient(0xc0006049b0, 0xc00000f270, 0x5, 0x5, 0xc000405930, 0x9ed8c7, 0xc0003e3080) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/transport.go:189 +0xb1 google.golang.org/grpc/internal/transport.(*recvBufferReader).Read(0xc0006049b0, 0xc00000f270, 0x5, 0x5, 0x0, 0xc00060d488, 0x2646548) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/transport.go:169 +0x190 google.golang.org/grpc/internal/transport.(*transportReader).Read(0xc0006eb6e0, 0xc00000f270, 0x5, 0x5, 0x7fffffffffffffff, 0xc0004059e8, 0xb6aa7c) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/transport.go:483 +0x55 io.ReadAtLeast(0x28583c0, 0xc0006eb6e0, 0xc00000f270, 0x5, 0x5, 0x5, 0x5fe2da, 0x36547c0, 0x613a69b8) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:328 +0x87 io.ReadFull(...) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:347 google.golang.org/grpc/internal/transport.(*Stream).Read(0xc0006e77a0, 0xc00000f270, 0x5, 0x5, 0xc000405ab0, 0x5ffb16, 0x7ffffffe7c1432b8) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/transport.go:467 +0xd2 google.golang.org/grpc.(*parser).recvMsg(0xc00000f260, 0x7fffffff, 0x57d1b2, 0xc0009eb618, 0xc0009eb650, 0xe0, 0xa4d666a282, 0x1996766b) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/rpc_util.go:558 +0x63 google.golang.org/grpc.recvAndDecompress(0xc00000f260, 0xc0006e77a0, 0x0, 0x0, 0x7fffffff, 0x0, 0x0, 0x0, 0x110000000015d2fa, 0x10100, ...) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/rpc_util.go:689 +0x4d google.golang.org/grpc.recv(0xc00000f260, 0x7ff5f4608be0, 0x3688490, 0xc0006e77a0, 0x0, 0x0, 0x252da00, 0xc055b06080, 0x7fffffff, 0x0, ...) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/rpc_util.go:757 +0x9b google.golang.org/grpc.(*csAttempt).recvMsg(0xc000571d80, 0x252da00, 0xc055b06080, 0x0, 0xc046b85319ac5f22, 0xa97e945330) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/stream.go:957 +0xee google.golang.org/grpc.(*clientStream).RecvMsg.func1(0xc000571d80, 0x8, 0xa663d9cca4) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/stream.go:808 +0x46 google.golang.org/grpc.(*clientStream).withRetry(0xc0006e7560, 0xc000405e88, 0xc000405e58, 0x40, 0x38) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/stream.go:662 +0x3df google.golang.org/grpc.(*clientStream).RecvMsg(0xc0006e7560, 0x252da00, 0xc055b06080, 0x0, 0xc00022cb40) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/stream.go:807 +0x105 go.etcd.io/etcd/api/v3/etcdserverpb.(*leaseLeaseKeepAliveClient).Recv(0xc00055fc70, 0xc03ee80ec0, 0x0, 0x0) /home/runner/go/pkg/mod/go.etcd.io/etcd/api/v3@v3.5.0/etcdserverpb/rpc.pb.go:6853 +0x62 go.etcd.io/etcd/client/v3.(*lessor).recvKeepAliveLoop(0xc00022cb40, 0x0, 0x0) /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/lease.go:447 +0xb3 created by go.etcd.io/etcd/client/v3.(*lessor).KeepAlive.func1 /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/lease.go:299 +0x45 goroutine 277 [select]: go.etcd.io/etcd/client/v3.(*lessor).deadlineLoop(0xc00022cb40) /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/lease.go:539 +0x17a created by go.etcd.io/etcd/client/v3.(*lessor).KeepAlive.func1 /home/runner/go/pkg/mod/go.etcd.io/etcd/client/v3@v3.5.0/lease.go:300 +0x67 goroutine 294 [semacquire, 25 minutes]: sync.runtime_Semacquire(0xc0003c2ec0) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/sema.go:56 +0x45 sync.(*WaitGroup).Wait(0xc0003c2eb8) /opt/hostedtoolcache/go/1.16.6/x64/src/sync/waitgroup.go:130 +0x65 go.gazette.dev/core/consumer.(*Service).QueueTasks.func2(0x0, 0x0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/service.go:114 +0xbc go.gazette.dev/core/task.(*Group).GoRun.func1(0x0, 0x0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/task/group.go:72 +0x43 golang.org/x/sync/errgroup.(*Group).Go.func1(0xc0003c31a0, 0xc000802620) /home/runner/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:57 +0x59 created by golang.org/x/sync/errgroup.(*Group).Go [559/1803] /home/runner/go/pkg/mod/golang.org/x/sync@v0.0.0-20210220032951-036812b2e83c/errgroup/errgroup.go:54 +0x66 goroutine 310 [chan receive, 27 minutes]: google.golang.org/grpc.(*addrConn).resetTransport(0xc00092c580) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:1214 +0x465 created by google.golang.org/grpc.(*addrConn).connect /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/clientconn.go:844 +0x12a goroutine 91141 [semacquire, 29 minutes]: sync.runtime_Semacquire(0xc008aff248) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/sema.go:56 +0x45 sync.(*WaitGroup).Wait(0xc008aff240) /opt/hostedtoolcache/go/1.16.6/x64/src/sync/waitgroup.go:130 +0x65 go.gazette.dev/core/consumer.waitAndTearDown(0xc008aff1e0, 0xc015ba7bc0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/shard.go:265 +0x31 created by go.gazette.dev/core/consumer.(*Resolver).cancelShards /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/resolver.go:375 +0xa5 goroutine 395 [IO wait, 37 minutes]: internal/poll.runtime_pollWait(0x7ff5f463ff68, 0x72, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/netpoll.go:222 +0x55 internal/poll.(*pollDesc).wait(0xc000f585b8, 0x72, 0x8001, 0x8000, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc000f585a0, 0xc000e30000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_unix.go:166 +0x1d5 os.(*File).read(...) /opt/hostedtoolcache/go/1.16.6/x64/src/os/file_posix.go:31 os.(*File).Read(0xc0001180e8, 0xc000e30000, 0x8000, 0x8000, 0x0, 0x0, 0xc0009a6d80) /opt/hostedtoolcache/go/1.16.6/x64/src/os/file.go:117 +0x77 io.copyBuffer(0x285b440, 0xc000bf1be0, 0x2858ec0, 0xc0001180e8, 0xc000e30000, 0x8000, 0x8000, 0x0, 0x21eea94, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:423 +0x12c io.Copy(...) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:382 os.genericReadFrom(0xc000010020, 0x2858ec0, 0xc0001180e8, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/os/file.go:160 +0x99 os.(*File).ReadFrom(0xc000010020, 0x2858ec0, 0xc0001180e8, 0x7ff5f4381fd8, 0xc000010020, 0x1) /opt/hostedtoolcache/go/1.16.6/x64/src/os/file.go:154 +0x250 bufio.(*Reader).WriteTo(0xc000f58900, 0x2858ee0, 0xc000010020, 0x7ff5f4381f98, 0xc000f58900, 0xc000486d01) /opt/hostedtoolcache/go/1.16.6/x64/src/bufio/bufio.go:512 +0x27a io.copyBuffer(0x2858ee0, 0xc000010020, 0x2855620, 0xc000f58900, 0x0, 0x0, 0x0, 0x100010000, 0xc000561aa0, 0xc000d34a20) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:405 +0x3ac io.Copy(0x2858ee0, 0xc000010020, 0x2855620, 0xc000f58900, 0x28, 0x50, 0x7ff5f434bf60) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:382 +0x5a created by github.com/estuary/flow/go/flow.StartCmdAndReadReady /home/runner/work/flow/flow/go/flow/js_worker.go:127 +0x8cc goroutine 172 [select, 37 minutes]: [510/1803]database/sql.(*DB).connectionOpener(0xc0006c5790, 0x2889988, 0xc0006e50c0) /opt/hostedtoolcache/go/1.16.6/x64/src/database/sql/sql.go:1133 +0xb5 created by database/sql.OpenDB /opt/hostedtoolcache/go/1.16.6/x64/src/database/sql/sql.go:740 +0x12a goroutine 467 [select, 37 minutes]: github.com/snowflakedb/gosnowflake.(*heartbeat).run(0xc000bf0510) /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:31 +0xca created by github.com/snowflakedb/gosnowflake.(*heartbeat).start /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:46 +0x74 goroutine 91557 [IO wait, 27 minutes]: internal/poll.runtime_pollWait(0x7ff5f463f9f8, 0x72, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/runtime/netpoll.go:222 +0x55 internal/poll.(*pollDesc).wait(0xc01fd88398, 0x72, 0x8000, 0x8000, 0xffffffffffffffff) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:87 +0x45 internal/poll.(*pollDesc).waitRead(...) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_poll_runtime.go:92 internal/poll.(*FD).Read(0xc01fd88380, 0xc0008c8000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/internal/poll/fd_unix.go:166 +0x1d5 net.(*netFD).Read(0xc01fd88380, 0xc0008c8000, 0x8000, 0x8000, 0xb3f13e, 0x800010601, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/fd_posix.go:55 +0x4f net.(*conn).Read(0xc03788c060, 0xc0008c8000, 0x8000, 0x8000, 0x0, 0x0, 0x0) /opt/hostedtoolcache/go/1.16.6/x64/src/net/net.go:183 +0x91 bufio.(*Reader).Read(0xc00d078f60, 0xc0000c5458, 0x9, 0x9, 0x14, 0x7ff61db10108, 0x18) /opt/hostedtoolcache/go/1.16.6/x64/src/bufio/bufio.go:227 +0x222 io.ReadAtLeast(0x2855620, 0xc00d078f60, 0xc0000c5458, 0x9, 0x9, 0x9, 0xc000037ce8, 0x5c3313, 0x2873c0081d922) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:328 +0x87 io.ReadFull(...) /opt/hostedtoolcache/go/1.16.6/x64/src/io/io.go:347 golang.org/x/net/http2.readFrameHeader(0xc0000c5458, 0x9, 0x9, 0x2855620, 0xc00d078f60, 0x0, 0x0, 0xc046b838580c4224, 0x909341c851) /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:237 +0x89 golang.org/x/net/http2.(*Framer).ReadFrame(0xc0000c5420, 0xc000ab8090, 0xc000ab8090, 0x0, 0x0) /home/runner/go/pkg/mod/golang.org/x/net@v0.0.0-20210405180319-a5a99cb37ef4/http2/frame.go:492 +0xa5 google.golang.org/grpc/internal/transport.(*http2Client).reader(0xc004d16780) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:1347 +0x1a5 created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:346 +0xdd1 goroutine 13392 [select, 32 minutes]: database/sql.(*DB).connectionOpener(0xc009ae6a90, 0x2889988, 0xc005d04e00) /opt/hostedtoolcache/go/1.16.6/x64/src/database/sql/sql.go:1133 +0xb5 created by database/sql.OpenDB /opt/hostedtoolcache/go/1.16.6/x64/src/database/sql/sql.go:740 +0x12a goroutine 73764 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09c2e0, 0xc009336a50, 0x24f6bc0, 0xc000605b80, 0x2919, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 13446 [select, 32 minutes]: [458/1803]github.com/snowflakedb/gosnowflake.(*heartbeat).run(0xc002e950f0) /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:31 +0xca created by github.com/snowflakedb/gosnowflake.(*heartbeat).start /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:46 +0x74 goroutine 73876 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34c00, 0xc009336a50, 0x24f6bc0, 0xc004554dc0, 0x2949, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73783 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d4a0, 0xc009336a50, 0x24f6bc0, 0xc008e69900, 0x292c, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 3008 [select, 37 minutes]: github.com/snowflakedb/gosnowflake.(*heartbeat).run(0xc00057dd00) /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:31 +0xca created by github.com/snowflakedb/gosnowflake.(*heartbeat).start /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:46 +0x74 goroutine 73776 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cba0, 0xc009336a50, 0x24f6bc0, 0xc007844b40, 0x2925, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 13243 [chan send, 31 minutes]: github.com/estuary/flow/go/shuffle.StartReadingMessages.func1(0xc00508fda0, 0xc0005d1b80, 0x2889988, 0xc00544f500) /home/runner/work/flow/flow/go/shuffle/reader.go:81 +0x1f2 created by github.com/estuary/flow/go/shuffle.StartReadingMessages /home/runner/work/flow/flow/go/shuffle/reader.go:69 +0x2ae goroutine 12367 [runnable]: [422/1803]github.com/estuary/flow/go/shuffle.(*read).next(0xc004a4bb80, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc00508f740, 0x0) /home/runner/work/flow/flow/go/shuffle/read.go:380 +0x85 github.com/estuary/flow/go/shuffle.StartReplayRead.func1(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0) /home/runner/work/flow/flow/go/shuffle/reader.go:108 +0x10e go.gazette.dev/core/message.IteratorFunc.Next(0xc044a2f400, 0x0, 0x0, 0x0, 0x0, 0x0, 0xb3, 0x100) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/message/reader.go:26 +0x6e go.gazette.dev/core/message.(*Sequencer).dequeNext(0xc0055c4e10, 0xc0001cea00, 0x1b2e9eac88, 0x1b2e9ec2d7, 0x28829e0, 0xc0110707e0, 0xc000b67498, 0xf6b43b) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/message/sequencer.go:339 +0x102 go.gazette.dev/core/message.(*Sequencer).DequeCommitted(0xc0055c4e10, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc003d6c700, 0x0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/message/sequencer.go:225 +0x85 go.gazette.dev/core/consumer.txnRead(0xc008aff1e0, 0xc000b67a40, 0xc000b67b60, 0xc0001cea00, 0x1b31756232, 0x1b31756277, 0x28829e0, 0xc056f9a620, 0x0, 0x0, ...) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/transaction.go:206 +0x21d go.gazette.dev/core/consumer.txnStep(0xc008aff1e0, 0xc00f881a40, 0xc00f881b60, 0x0, 0x0, 0x0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/transaction.go:153 +0x205 go.gazette.dev/core/consumer.txnRun(0xc008aff1e0, 0xc000b67a40, 0xc000b67b60, 0xc00508fda0, 0xc00508fe00) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/transaction.go:117 +0x85 go.gazette.dev/core/consumer.runTransactions(0xc008aff1e0, 0xc005fe4540, 0xc005fe45d0, 0xc00508fda0, 0xc00508fd40, 0xc005fe4540, 0xc005fe45d0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/transaction.go:62 +0x509 go.gazette.dev/core/consumer.servePrimary(0xc008aff1e0, 0x0, 0x0) /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/shard.go:245 +0x4e6 created by go.gazette.dev/core/consumer.glob..func1 /home/runner/go/pkg/mod/github.com/jgraettinger/gazette@v0.0.0-20210723215434-4a4814d42263/consumer/shard.go:146 +0x252 goroutine 73826 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09dd50, 0xc009336a50, 0x24f6bc0, 0xc0039a2aa0, 0x2937, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73837 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34790, 0xc009336a50, 0x24f6bc0, 0xc008c1d720, 0x2942, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73784 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d4b0, 0xc009336a50, 0x24f6bc0, 0xc008e69950, 0x292d, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73681 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09c2b0, 0xc009336a50, 0x24f6bc0, 0xc0006059a0, 0x2916, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73834 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a341f0, 0xc009336a50, 0x24f6bc0, 0xc008c1c1e0, 0x293f, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73780 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cfe0, 0xc009336a50, 0x24f6bc0, 0xc008e680a0, 0x2929, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73833 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a341e0, 0xc009336a50, 0x24f6bc0, 0xc008c1c190, 0x293e, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73770 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09c740, 0xc009336a50, 0x24f6bc0, 0xc00777b2c0, 0x291f, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73827 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09dd60, 0xc009336a50, 0x24f6bc0, 0xc0039a2af0, 0x2938, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73838 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a347a0, 0xc009336a50, 0x24f6bc0, 0xc008c1d770, 0x2943, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 23744 [select, 31 minutes]: github.com/snowflakedb/gosnowflake.(*heartbeat).run(0xc01225db40) /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:31 +0xca created by github.com/snowflakedb/gosnowflake.(*heartbeat).start /home/runner/go/pkg/mod/github.com/snowflakedb/gosnowflake@v1.4.2-0.20210318070613-b0c023e3afd7/heartbeat.go:46 +0x74 goroutine 73888 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a356b0, 0xc009336a50, 0x24f6bc0, 0xc0093fbd60, 0x2955, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73777 [select, 30 minutes]: [326/1803]github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cfb0, 0xc009336a50, 0x24f6bc0, 0xc007845f90, 0x2926, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73779 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cfd0, 0xc009336a50, 0x24f6bc0, 0xc008e68050, 0x2928, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73894 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f208330, 0xc009336a50, 0x24f6bc0, 0xc008bf4820, 0x295b, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73900 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f208790, 0xc009336a50, 0x24f6bc0, 0xc0077201e0, 0x2961, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73789 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d900, 0xc009336a50, 0x24f6bc0, 0xc000a0f360, 0x2932, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73787 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d8e0, 0xc009336a50, 0x24f6bc0, 0xc000a0f2c0, 0x2930, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73771 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cb50, 0xc009336a50, 0x24f6bc0, 0xc0078449b0, 0x2920, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73768 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09c720, 0xc009336a50, 0x24f6bc0, 0xc00777b220, 0x291d, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73903 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f2087c0, 0xc009336a50, 0x24f6bc0, 0xc0077202d0, 0x2964, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 91558 [select, 27 minutes]: google.golang.org/grpc/internal/transport.(*controlBuffer).get(0xc000aa0640, 0x1, 0x0, 0x0, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:407 +0xff google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc00d0791a0, 0x0, 0x0) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/controlbuf.go:527 +0x1dd google.golang.org/grpc/internal/transport.newHTTP2Client.func3(0xc004d16780) /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:396 +0x7b created by google.golang.org/grpc/internal/transport.newHTTP2Client /home/runner/go/pkg/mod/google.golang.org/grpc@v1.38.0/internal/transport/http2_client.go:394 +0x12ae goroutine 73887 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a356a0, 0xc009336a50, 0x24f6bc0, 0xc0093fbd10, 0x2954, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73896 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f208350, 0xc009336a50, 0x24f6bc0, 0xc008bf48c0, 0x295d, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73882 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35090, 0xc009336a50, 0x24f6bc0, 0xc0093fa3c0, 0x294f, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73832 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a341d0, 0xc009336a50, 0x24f6bc0, 0xc008c1c140, 0x293d, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73839 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a347b0, 0xc009336a50, 0x24f6bc0, 0xc008c1d7c0, 0x2944, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73895 [select, 30 minutes]: [232/1803]github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f208340, 0xc009336a50, 0x24f6bc0, 0xc008bf4870, 0x295c, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73840 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a347c0, 0xc009336a50, 0x24f6bc0, 0xc008c1d810, 0x2945, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73885 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35680, 0xc009336a50, 0x24f6bc0, 0xc0093fbbd0, 0x2952, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73889 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35e50, 0xc009336a50, 0x24f6bc0, 0xc044a2f1d0, 0x2956, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73778 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cfc0, 0xc009336a50, 0x24f6bc0, 0xc008e68000, 0x2927, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73881 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35070, 0xc009336a50, 0x24f6bc0, 0xc0093fa370, 0x294e, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73836 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34780, 0xc009336a50, 0x24f6bc0, 0xc008c1d6d0, 0x2941, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73890 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35e60, 0xc009336a50, 0x24f6bc0, 0xc044a2f220, 0x2957, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73897 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f208360, 0xc009336a50, 0x24f6bc0, 0xc008bf4910, 0x295e, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73841 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34bd0, 0xc009336a50, 0x24f6bc0, 0xc004554cd0, 0x2946, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73793 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09dd40, 0xc009336a50, 0x24f6bc0, 0xc0039a2a50, 0x2936, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73877 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34c10, 0xc009336a50, 0x24f6bc0, 0xc004554e10, 0x294a, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73875 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34bf0, 0xc009336a50, 0x24f6bc0, 0xc004554d70, 0x2948, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73883 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35660, 0xc009336a50, 0x24f6bc0, 0xc0093fbb30, 0x2950, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73786 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d4d0, 0xc009336a50, 0x24f6bc0, 0xc008e699f0, 0x292f, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73880 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35060, 0xc009336a50, 0x24f6bc0, 0xc0093fa320, 0x294d, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 [137/1803]goroutine 73878 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35030, 0xc009336a50, 0x24f6bc0, 0xc0093fa280, 0x294b, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73774 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cb80, 0xc009336a50, 0x24f6bc0, 0xc007844aa0, 0x2923, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73829 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09dd80, 0xc009336a50, 0x24f6bc0, 0xc0039a2b90, 0x293a, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73790 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d910, 0xc009336a50, 0x24f6bc0, 0xc000a0f3b0, 0x2933, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73886 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35690, 0xc009336a50, 0x24f6bc0, 0xc0093fbcc0, 0x2953, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73904 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f2087d0, 0xc009336a50, 0x24f6bc0, 0xc007720370, 0x2965, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73828 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09dd70, 0xc009336a50, 0x24f6bc0, 0xc0039a2b40, 0x2939, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73899 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f208780, 0xc009336a50, 0x24f6bc0, 0xc007720190, 0x2960, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73884 [select, 30 minutes]: [88/1803]github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35670, 0xc009336a50, 0x24f6bc0, 0xc0093fbb80, 0x2951, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73879 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35040, 0xc009336a50, 0x24f6bc0, 0xc0093fa2d0, 0x294c, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73773 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cb70, 0xc009336a50, 0x24f6bc0, 0xc007844a50, 0x2922, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73791 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d920, 0xc009336a50, 0x24f6bc0, 0xc000a0f400, 0x2934, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73898 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f208370, 0xc009336a50, 0x24f6bc0, 0xc008bf4960, 0x295f, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73901 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f2087a0, 0xc009336a50, 0x24f6bc0, 0xc007720230, 0x2962, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73902 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc03f2087b0, 0xc009336a50, 0x24f6bc0, 0xc007720280, 0x2963, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73893 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35e90, 0xc009336a50, 0x24f6bc0, 0xc044a2f310, 0x295a, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73892 [select, 30 minutes]: [40/1803]github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35e80, 0xc009336a50, 0x24f6bc0, 0xc044a2f2c0, 0x2959, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73782 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d490, 0xc009336a50, 0x24f6bc0, 0xc008e698b0, 0x292b, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73775 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09cb90, 0xc009336a50, 0x24f6bc0, 0xc007844af0, 0x2924, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73788 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d8f0, 0xc009336a50, 0x24f6bc0, 0xc000a0f310, 0x2931, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73767 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09c710, 0xc009336a50, 0x24f6bc0, 0xc00777b1d0, 0x291c, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73766 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09c700, 0xc009336a50, 0x24f6bc0, 0xc00777b180, 0x291b, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73874 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34be0, 0xc009336a50, 0x24f6bc0, 0xc004554d20, 0x2947, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73765 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09c2f0, 0xc009336a50, 0x24f6bc0, 0xc000605bd0, 0x291a, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73891 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a35e70, 0xc009336a50, 0x24f6bc0, 0xc044a2f270, 0x2958, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73835 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc003a34770, 0xc009336a50, 0x24f6bc0, 0xc008c1d680, 0x2940, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 goroutine 73785 [select, 30 minutes]: github.com/estuary/flow/go/bindings.(*trampolineServer).startTask.func2(0xc009336aa0, 0xc04c09d4c0, 0xc009336a50, 0x24f6bc0, 0xc008e699a0, 0x292e, 0xa0000000c) /home/runner/work/flow/flow/go/bindings/trampoline.go:109 +0x457 created by github.com/estuary/flow/go/bindings.(*trampolineServer).startTask /home/runner/work/flow/flow/go/bindings/trampoline.go:87 +0x3b5 rax 0xca rbx 0x36555c0 rcx 0x5dc2c3 rdx 0x0 rdi 0x3655710 rsi 0x80 rbp 0x7fffca879ec0 rsp 0x7fffca879e78 r8 0x0 r9 0x0 r10 0x0 r11 0x286 r12 0x0 r13 0x3641cf r14 0x1 r15 0x0 rip 0x5dc2c1 rflags 0x286 cs 0x33 fs 0x0 gs 0x0 ```

Update: this is a new shutdown race bug, but isn't the droid we're looking for.

Briefly, we're wedged in a tight loop here:

goroutine 12367 [runnable]:
  github.com/estuary/flow/go/shuffle.(*read).next(0xc004a4bb80, 0x0, 0x0, 0x0, 0x0, 0x0, 0xc00508f740, 0x0)
    /home/runner/work/flow/flow/go/shuffle/read.go:380 +0x85
  github.com/estuary/flow/go/shuffle.StartReplayRead.func1(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
    home/runner/work/flow/flow/go/shuffle/reader.go:108 +0x10e

It happens because we're pulling a zero-valued readResult from a closed channel. The channel was closed without delivering a final error, because we use a non-blocking and best-effort send of that final error. However, because no error was returned, we'll sit in a tight loop in this case.

psFried commented 3 years ago

I captured these from a recent build that's been getting oom killed:

heap.txt goroutines.txt allocs.txt

jgraettinger commented 3 years ago

Another suspicious trace in the shuffle package:

goroutine 511 [chan send, 40 minutes]:
github.com/estuary/flow/go/shuffle.StartReadingMessages.func1(0xc000a1f920, 0xc000fa3380, 0x2e27608, 0xc0008b70c0)
    /home/runner/work/flow/flow/go/shuffle/reader.go:81 +0x1f2
created by github.com/estuary/flow/go/shuffle.StartReadingMessages
    /home/runner/work/flow/flow/go/shuffle/reader.go:69 +0x2ae

It's blocking attempting to send into the channel of message envelope delivered to the consumer framework.

jgraettinger commented 3 years ago

I've got a pretty good reproduction using the citi-bike dataset. Findings so far:

Validation is taking way to long, and is most of the runtime cost -- not reduction or parsing, as I'd suspected.
My current theory is that the way we're using TinyVec is causing lots of branch mis-predictions and spillover small allocations into the heap. I'd like to try ripping it out and instead pooling regular Vec's, but first I'm spending some time re-studying this code.
Something funny is going on between Go & NodeJS HTTP/2 over unix domain sockets. On both node 10 (old) and current 16.9 I'm seeing lockups which look like the fault of the NodeJS server. I can't 100% say it isn't the Go client, but I see the Go code in an open read of the UDS descriptor, and blocked in an attempt to write to the descriptor, which tells me that Node isn't servicing / reading the transport.
The current reproduction amplifies citi rides into 3x as large documents, where 2x as many are produced. So there's much more heavy lifting after lambdas run. However they're combined on bike ID, which means the total amount of stuff in the combiner is relatively small. I still see way more memory usage than I'd expect, at ~4GB, though it's slow to increase and may be stable. I don't have a good handle on this happens yet (heap fragmentation? 🤷)

jgraettinger commented 3 years ago

Okay! Managed to wire up heaptrack to my reproduction and got some interesting results after letting it run for a while:

heaptrack stats:
        allocations:            277515513
        leaked allocations:     2346
        temporary allocations:  767061

Notably, the "leaks" are all compiled static constants like regex's. So there are no actual resource leak.

Analyzing the dump, heaptrack reports a peak usage of 300MB and a peak RSS of 2.1GB. We've got a very fragmented heap

Still analyzing output, but 99% of the allocation work is of course serde_json::Value.

psFried commented 3 years ago

I switched Flow over to using jemalloc in libbindings. I wrote a simple flow catalog that captures citibike rides from S3 and runs them through a derivation that's just an identity function. Here's some graphs!

Here's the drained document counts, which correlate directly to transactions. The left side of the graph shows it running with jemalloc, and the right side shows it running with the system allocator. cmp-drains

Here's a graph of allocated memory for the run that's using the system allocator. Notice how the drop in allocations is correlated with the commit of each derivation transaction. sys-alloc

Here's the allocated memory graph from the run using jemalloc. Again you can see how these correlate with the derive transactions. jem-alloc

Here's the resident set size, again with the jemalloc version on the left and system allocator on the right. With jemalloc, the RSS goes down immediately as allocations are freed. cmp-rss

At least in this example, I don't actually think heap fragmentation was a major factor, even with the system allocator. The RSS got up to 12.5GiB, which isn't much higher than the peak allocated memory of ~12GiB. It seems that in this case, the major benefit of jemalloc is just that it returns unused memory to the OS, whereas the system allocator keeps it. But there also seems to be a significant performance improvement with jemalloc, such that the throughput of the derivation was significantly higher.

jgraettinger commented 3 years ago

This issue has been a smorgasbord as we've knocked out little bugs, and investigated performance.

Key outcomes are:

Switching to jemalloc from the system allocator (massively reduces heap fragmentation ; improves performance ; lowers resident set size).
Diagnosing the (current) performance costs of schema validation, introducing benchmarks, and initial perf improvements.
Switching to http1 from http2 for runtime => nodejs lambda callouts. We've observed deadlocks in these callouts that strongly smells of an h2 implementation bug, likely in nodejs.

There's more to do here, but future work will be under separate issues.

estuary / flow

runtime: excessive memory fragmentation ; performance (investigation) #226