Google-cloud-go: pubsub: inconsistently receiving less messages after v0.24.0
User @fastest963 reports that using v0.24.0 works as expected, but bumping to HEAD causes what appears to be rate limiting to happen.
See: https://github.com/GoogleCloudPlatform/google-cloud-go/issues/1163#issuecomment-429323268
Continuing the conversation from that thread here, since the original issue there seems quite different.
jadekler
All 47 comments
@fastest963 You mentioned:
The settings are
MaxOutstandingMessages: 1000
MaxExtension: 15 seconds
NumGoroutines: 40 (each server has 4 cores)
The ack deadline is 15 seconds.
Just to be clear, are both your MaxExtension _and_ AckDeadline 15s? I ask because we changed in v0.26.0 how we use AckDeadline. It may be that if you were setting this value quite high, you would now be sending much more ModAck RPCs (we now calculate how frequently to send based off your processing time, and in your case it would be the lower limit of 10s).
I'm going to try deploying a v0.24.0 of the library and a v0.30.0 of the library to see whether we're seeing a lot more RPCs from the latter, which might explain your rate limiting.
jadekler
on 12 Oct 2018
Yes, both of the values are the same. Would you recommend setting the MaxExtension to something higher or just disabling it completely (setting to less than 0)?
jameshartig
on 12 Oct 2018
Here is the API console's graphs for the ModAckDeadline statuses. I don't see any rate limit responses. There are some 499's and I'm not sure how relevant that is but those seem to always happen. I'm also not seeing a lot more calls before or after switching back to v0.24.0. In this graph I switched back around 8:11AM
Here's the same graph for StreamingPull. 503's are hidden but I don't see anything in these graphs to show any difference between v0.30.0 and v0.24.0.
jameshartig
on 12 Oct 2018
In the latest in this weird issue... I deployed:
cloud.google.com/go (git) - 777200c README.md: v0.24.0 release notes
google.golang.org/grpc (git) - c05280c cleanup: remove unused channel ready (#2353)
Two 2 servers (out of 8), purple and pink, at 18:22 UTC and at 19:23 UTC they both dropped to receiving 0 messages. The other (v0.24.0 and 1.13.0) servers were unaffected this time.
Hopefully this doesn't mean I've run into #1163 :/
Not sure if this helps, but if I zoom in on the opencensus metrics when the two dropped to 0 and then the rest briefly dropped then spiked back up, you can see a spike in retries at both times. The first retry spike is from the pink/purple servers (when they dropped to 0) and the second retry spike is from the rest of the servers (when they briefly nosedived).
I was able to get a goroutine dump:
807 @ 0x42de9b 0x4291d9 0x428886 0x49c60a 0x49c71d 0x49d469 0x52956f 0x53c7e8 0x645c49 0x64614d 0x6496d1 0x558c8f 0x465d18 0x465eb8 0x972f6b 0x9737d3 0x98e926 0x45bc81
# 0x428885 internal/poll.runtime_pollWait+0x65 /usr/local/go/src/runtime/netpoll.go:173
# 0x49c609 internal/poll.(*pollDesc).wait+0x99 /usr/local/go/src/internal/poll/fd_poll_runtime.go:85
# 0x49c71c internal/poll.(*pollDesc).waitRead+0x3c /usr/local/go/src/internal/poll/fd_poll_runtime.go:90
# 0x49d468 internal/poll.(*FD).Read+0x178 /usr/local/go/src/internal/poll/fd_unix.go:169
# 0x52956e net.(*netFD).Read+0x4e /usr/local/go/src/net/fd_unix.go:202
# 0x53c7e7 net.(*conn).Read+0x67 /usr/local/go/src/net/net.go:177
# 0x645c48 crypto/tls.(*block).readFromUntil+0x88 /usr/local/go/src/crypto/tls/conn.go:492
# 0x64614c crypto/tls.(*Conn).readRecord+0xdc /usr/local/go/src/crypto/tls/conn.go:593
# 0x6496d0 crypto/tls.(*Conn).Read+0xf0 /usr/local/go/src/crypto/tls/conn.go:1145
# 0x558c8e bufio.(*Reader).Read+0x22e /usr/local/go/src/bufio/bufio.go:216
# 0x465d17 io.ReadAtLeast+0x87 /usr/local/go/src/io/io.go:310
# 0x465eb7 io.ReadFull+0x57 /usr/local/go/src/io/io.go:329
# 0x972f6a golang.org/x/net/http2.readFrameHeader+0x7a /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/golang.org/x/net/http2/frame.go:237
# 0x9737d2 golang.org/x/net/http2.(*Framer).ReadFrame+0xa2 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/golang.org/x/net/http2/frame.go:492
# 0x98e925 google.golang.org/grpc/internal/transport.(*http2Client).reader+0x175 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/internal/transport/http2_client.go:1207
807 @ 0x42de9b 0x43dcfd 0x981a93 0x9821ac 0x994cfb 0x45bc81
# 0x981a92 google.golang.org/grpc/internal/transport.(*controlBuffer).get+0x102 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/internal/transport/controlbuf.go:317
# 0x9821ab google.golang.org/grpc/internal/transport.(*loopyWriter).run+0x1ab /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/internal/transport/controlbuf.go:435
# 0x994cfa google.golang.org/grpc/internal/transport.newHTTP2Client.func3+0x7a /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/internal/transport/http2_client.go:319
41 @ 0x42de9b 0x42df43 0x405abe 0x4057ab 0xa771e8 0x45bc81
# 0xa771e7 cloud.google.com/go/pubsub.(*Subscription).receive.func1+0x47 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/subscription.go:475
40 @ 0x42de9b 0x43dcfd 0x9b5407 0x45bc81
# 0x9b5406 google.golang.org/grpc.newClientStream.func5+0xd6 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:287
39 @ 0x42de9b 0x43dcfd 0x9a9d37 0x9a4fb0 0x9b0a3e 0x9afd33 0x9a101c 0x9a0dd3 0xa5b9c2 0xa69e98 0x9b8ba0 0x9b8976 0xa663b4 0xa768d6 0xa6fa5d 0xa6f812 0xa6eaf2 0xa74b00 0xa77177 0xa6b507 0x45bc81
# 0x9a9d36 google.golang.org/grpc.(*pickerWrapper).pick+0x556 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x9a4faf google.golang.org/grpc.(*ClientConn).getTransport+0x6f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/clientconn.go:719
# 0x9b0a3d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:309
# 0x9afd32 google.golang.org/grpc.newClientStream+0x712 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:269
# 0x9a101b google.golang.org/grpc.invoke+0x9b /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:66
# 0x9a0dd2 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:37
# 0xa5b9c1 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).ModifyAckDeadline+0xd1 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3036
# 0xa69e97 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).ModifyAckDeadline.func1+0x77 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:313
# 0x9b8b9f github.com/googleapis/gax-go.invoke+0x8f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:70
# 0x9b8975 github.com/googleapis/gax-go.Invoke+0xf5 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:48
# 0xa663b3 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).ModifyAckDeadline+0x1a3 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:311
# 0xa768d5 cloud.google.com/go/pubsub.(*streamingMessageIterator).sendModAck.func1+0xc5 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:331
# 0xa6fa5c cloud.google.com/go/pubsub.(*streamingMessageIterator).sendAckIDRPC+0x22c /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:347
# 0xa6f811 cloud.google.com/go/pubsub.(*streamingMessageIterator).sendModAck+0x71 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:329
# 0xa6eaf1 cloud.google.com/go/pubsub.(*streamingMessageIterator).receive+0x4a1 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:201
# 0xa74aff cloud.google.com/go/pubsub.(*Subscription).receive+0x3ef /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/subscription.go:483
# 0xa77176 cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x56 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/subscription.go:449
# 0xa6b506 golang.org/x/sync/errgroup.(*Group).Go.func1+0x56 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/golang.org/x/sync/errgroup/errgroup.go:58
21 @ 0x42de9b 0x43dcfd 0x9a9d37 0x9a4fb0 0x9b0a3e 0x9afd33 0x9a101c 0x9a0dd3 0xa5bb02 0xa69f48 0x9b8ba0 0x9b8976 0xa66617 0xa767a8 0xa6fa5d 0xa6f778 0xa6f1d5 0x45bc81
# 0x9a9d36 google.golang.org/grpc.(*pickerWrapper).pick+0x556 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x9a4faf google.golang.org/grpc.(*ClientConn).getTransport+0x6f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/clientconn.go:719
# 0x9b0a3d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:309
# 0x9afd32 google.golang.org/grpc.newClientStream+0x712 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:269
# 0x9a101b google.golang.org/grpc.invoke+0x9b /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:66
# 0x9a0dd2 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:37
# 0xa5bb01 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).Acknowledge+0xd1 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3045
# 0xa69f47 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).Acknowledge.func1+0x77 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:331
# 0x9b8b9f github.com/googleapis/gax-go.invoke+0x8f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:70
# 0x9b8975 github.com/googleapis/gax-go.Invoke+0xf5 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:48
# 0xa66616 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).Acknowledge+0x1a6 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:329
# 0xa767a7 cloud.google.com/go/pubsub.(*streamingMessageIterator).sendAck.func1+0xb7 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:321
# 0xa6fa5c cloud.google.com/go/pubsub.(*streamingMessageIterator).sendAckIDRPC+0x22c /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:347
# 0xa6f777 cloud.google.com/go/pubsub.(*streamingMessageIterator).sendAck+0x57 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:319
# 0xa6f1d4 cloud.google.com/go/pubsub.(*streamingMessageIterator).sender+0x4c4 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:276
12 @ 0x42de9b 0x43dcfd 0x9a9d37 0x9a4fb0 0x9b0a3e 0x9afd33 0x9a101c 0x9a0dd3 0xa5b9c2 0xa69e98 0x9b8ba0 0x9b8976 0xa663b4 0xa768d6 0xa6fa5d 0xa6f812 0xa6f147 0x45bc81
# 0x9a9d36 google.golang.org/grpc.(*pickerWrapper).pick+0x556 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x9a4faf google.golang.org/grpc.(*ClientConn).getTransport+0x6f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/clientconn.go:719
# 0x9b0a3d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:309
# 0x9afd32 google.golang.org/grpc.newClientStream+0x712 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:269
# 0x9a101b google.golang.org/grpc.invoke+0x9b /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:66
# 0x9a0dd2 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:37
# 0xa5b9c1 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).ModifyAckDeadline+0xd1 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3036
# 0xa69e97 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).ModifyAckDeadline.func1+0x77 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:313
# 0x9b8b9f github.com/googleapis/gax-go.invoke+0x8f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:70
# 0x9b8975 github.com/googleapis/gax-go.Invoke+0xf5 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:48
# 0xa663b3 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).ModifyAckDeadline+0x1a3 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:311
# 0xa768d5 cloud.google.com/go/pubsub.(*streamingMessageIterator).sendModAck.func1+0xc5 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:331
# 0xa6fa5c cloud.google.com/go/pubsub.(*streamingMessageIterator).sendAckIDRPC+0x22c /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:347
# 0xa6f811 cloud.google.com/go/pubsub.(*streamingMessageIterator).sendModAck+0x71 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:329
# 0xa6f146 cloud.google.com/go/pubsub.(*streamingMessageIterator).sender+0x436 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:287
7 @ 0x42de9b 0x43dcfd 0x98f0f3 0x45bc81
# 0x98f0f2 google.golang.org/grpc/internal/transport.(*http2Client).keepalive+0x112 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/internal/transport/http2_client.go:1258
7 @ 0x42de9b 0x43dcfd 0xa6ef97 0x45bc81
# 0xa6ef96 cloud.google.com/go/pubsub.(*streamingMessageIterator).sender+0x286 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:222
2 @ 0x42de9b 0x42df43 0x405abe 0x4057ab 0x9da39a 0x99b3c7 0x9b3e3b 0x45bc81
# 0x9da399 google.golang.org/api/internal.(*PoolResolver).Next+0x49 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/api/internal/pool.go:54
# 0x99b3c6 google.golang.org/grpc.(*roundRobin).watchAddrUpdates+0x56 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/balancer.go:145
# 0x9b3e3a google.golang.org/grpc.(*roundRobin).Start.func1+0x2a /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/balancer.go:220
2 @ 0x42de9b 0x42df43 0x405abe 0x4057eb 0x99e7fc 0x45bc81
# 0x99e7fb google.golang.org/grpc.(*balancerWrapper).lbWatcher+0xeb /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/balancer_v1_wrapper.go:124
2 @ 0x42de9b 0x43dcfd 0x99d42f 0x45bc81
# 0x99d42e google.golang.org/grpc.(*ccBalancerWrapper).watcher+0x10e /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/balancer_conn_wrappers.go:122
2 @ 0x42de9b 0x43dcfd 0x9ab892 0x45bc81
# 0x9ab891 google.golang.org/grpc.(*ccResolverWrapper).watcher+0x141 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/resolver_conn_wrapper.go:111
1 @ 0x42de9b 0x42df43 0x43e8ac 0x43e5dd 0x46461f 0xa70a8b 0xa70ed8 0xa7120e 0xa6e72a 0xa74b00 0xa77177 0xa6b507 0x45bc81
# 0x43e5dc sync.runtime_SemacquireMutex+0x3c /usr/local/go/src/runtime/sema.go:71
# 0x46461e sync.(*Mutex).Lock+0xfe /usr/local/go/src/sync/mutex.go:134
# 0xa70a8a cloud.google.com/go/pubsub.(*pullStream).get+0x4a /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:69
# 0xa70ed7 cloud.google.com/go/pubsub.(*pullStream).call+0x67 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:126
# 0xa7120d cloud.google.com/go/pubsub.(*pullStream).Recv+0x6d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:168
# 0xa6e729 cloud.google.com/go/pubsub.(*streamingMessageIterator).receive+0xd9 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:171
# 0xa74aff cloud.google.com/go/pubsub.(*Subscription).receive+0x3ef /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/subscription.go:483
# 0xa77176 cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x56 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/subscription.go:449
# 0xa6b506 golang.org/x/sync/errgroup.(*Group).Go.func1+0x56 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/golang.org/x/sync/errgroup/errgroup.go:58
1 @ 0x42de9b 0x43dcfd 0x993b3c 0x993c1b 0x9b3220 0x9b590d 0x9b18cf 0x9b24cd 0xa5bf02 0xa76e81 0xa70f3c 0xa7120e 0xa6e72a 0xa74b00 0xa77177 0xa6b507 0x45bc81
# 0x993b3b google.golang.org/grpc/internal/transport.(*Stream).waitOnHeader+0xcb /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/internal/transport/transport.go:241
# 0x993c1a google.golang.org/grpc/internal/transport.(*Stream).RecvCompress+0x2a /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/internal/transport/transport.go:252
# 0x9b321f google.golang.org/grpc.(*csAttempt).recvMsg+0x5bf /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:748
# 0x9b590c google.golang.org/grpc.(*clientStream).RecvMsg.func1+0x3c /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:648
# 0x9b18ce google.golang.org/grpc.(*clientStream).withRetry+0x7e /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:534
# 0x9b24cc google.golang.org/grpc.(*clientStream).RecvMsg+0x8c /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:647
# 0xa5bf01 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberStreamingPullClient).Recv+0x61 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3086
# 0xa76e80 cloud.google.com/go/pubsub.(*pullStream).Recv.func1+0x70 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:171
# 0xa70f3b cloud.google.com/go/pubsub.(*pullStream).call+0xcb /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:131
# 0xa7120d cloud.google.com/go/pubsub.(*pullStream).Recv+0x6d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:168
# 0xa6e729 cloud.google.com/go/pubsub.(*streamingMessageIterator).receive+0xd9 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:171
# 0xa74aff cloud.google.com/go/pubsub.(*Subscription).receive+0x3ef /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/subscription.go:483
# 0xa77176 cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x56 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/subscription.go:449
# 0xa6b506 golang.org/x/sync/errgroup.(*Group).Go.func1+0x56 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/golang.org/x/sync/errgroup/errgroup.go:58
1 @ 0x42de9b 0x43dcfd 0x9a9d37 0x9a4fb0 0x9b0a3e 0x9afd33 0x9a101c 0x9a0dd3 0xa5ae82 0xa68684 0x9b8ba0 0x9b8976 0xa6880e 0xa6898a 0x94da99 0x94d970 0x94dc6a 0xa639bf 0xa773ba 0xa7514f 0xa8ceef 0xa90b8a 0x45bc81
# 0x9a9d36 google.golang.org/grpc.(*pickerWrapper).pick+0x556 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x9a4faf google.golang.org/grpc.(*ClientConn).getTransport+0x6f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/clientconn.go:719
# 0x9b0a3d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:309
# 0x9afd32 google.golang.org/grpc.newClientStream+0x712 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:269
# 0x9a101b google.golang.org/grpc.invoke+0x9b /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:66
# 0x9a0dd2 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/call.go:37
# 0xa5ae81 google.golang.org/genproto/googleapis/pubsub/v1.(*publisherClient).ListTopics+0xd1 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:2615
# 0xa68683 cloud.google.com/go/pubsub/apiv1.(*PublisherClient).ListTopics.func1.1+0x83 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:247
# 0x9b8b9f github.com/googleapis/gax-go.invoke+0x8f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:70
# 0x9b8975 github.com/googleapis/gax-go.Invoke+0xf5 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:48
# 0xa6880d cloud.google.com/go/pubsub/apiv1.(*PublisherClient).ListTopics.func1+0x12d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:245
# 0xa68989 cloud.google.com/go/pubsub/apiv1.(*PublisherClient).ListTopics.func2+0x69 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:256
# 0x94da98 google.golang.org/api/iterator.(*PageInfo).fill+0x48 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/api/iterator/iterator.go:143
# 0x94d96f google.golang.org/api/iterator.(*PageInfo).next+0xbf /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/api/iterator/iterator.go:122
# 0x94dc69 google.golang.org/api/iterator.(*PageInfo).next-fm+0x29 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/api/iterator/iterator.go:100
# 0xa639be cloud.google.com/go/pubsub/apiv1.(*TopicIterator).Next+0x2e /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:384
# 0xa773b9 cloud.google.com/go/pubsub.(*Client).Topics.func1+0x29 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/topic.go:146
# 0xa7514e cloud.google.com/go/pubsub.(*TopicIterator).Next+0x2e /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/topic.go:163
# 0xa8ceee bitbucket.org/levenlabs/llib/ldb.(*PubSubConsumer).refreshTopics+0x7e /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/bitbucket.org/levenlabs/llib/ldb/pubsub.go:586
# 0xa90b89 bitbucket.org/levenlabs/llib/ldb.(*PubSubConsumer).Consume.func2+0x229 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/bitbucket.org/levenlabs/llib/ldb/pubsub.go:655
1 @ 0x42de9b 0x43dcfd 0x9a9d37 0x9a4fb0 0x9b0a3e 0x9afd33 0x9af45f 0xa5bd58 0xa6a0de 0x9b8ba0 0x9b8976 0xa66b8b 0xa77b03 0xa76b3b 0xa70d38 0xa70b3c 0xa70ed8 0xa71171 0xa6fb0f 0xa6f0b8 0x45bc81
# 0x9a9d36 google.golang.org/grpc.(*pickerWrapper).pick+0x556 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x9a4faf google.golang.org/grpc.(*ClientConn).getTransport+0x6f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/clientconn.go:719
# 0x9b0a3d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:309
# 0x9afd32 google.golang.org/grpc.newClientStream+0x712 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:269
# 0x9af45e google.golang.org/grpc.(*ClientConn).NewStream+0x17e /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/grpc/stream.go:145
# 0xa5bd57 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).StreamingPull+0xa7 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3062
# 0xa6a0dd cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull.func1+0x7d /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:374
# 0x9b8b9f github.com/googleapis/gax-go.invoke+0x8f /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:70
# 0x9b8975 github.com/googleapis/gax-go.Invoke+0xf5 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/github.com/googleapis/gax-go/invoke.go:48
# 0xa66b8a cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull+0x1ca /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:372
# 0xa77b02 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull-fm+0x62 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:32
# 0xa76b3a cloud.google.com/go/pubsub.newPullStream.func1+0x1fa /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:47
# 0xa70d37 cloud.google.com/go/pubsub.(*pullStream).openWithRetry+0x77 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:107
# 0xa70b3b cloud.google.com/go/pubsub.(*pullStream).get+0xfb /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:99
# 0xa70ed7 cloud.google.com/go/pubsub.(*pullStream).call+0x67 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:126
# 0xa71170 cloud.google.com/go/pubsub.(*pullStream).Send+0x60 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/pullstream.go:151
# 0xa6fb0e cloud.google.com/go/pubsub.(*streamingMessageIterator).pingStream+0x3e /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:365
# 0xa6f0b7 cloud.google.com/go/pubsub.(*streamingMessageIterator).sender+0x3a7 /opt/TeamCityBuild/work/wombat-3/c23cc9760fd462e1/.deps/src/cloud.google.com/go/pubsub/iterator.go:292
Bizarre.. That still looks like a gRPC issue (noting that picker_wrapper seems stuck on StreamingPull as well as number of other RPCs). Could you try grpc-go=v1.13.0 and google-cloud-go=HEAD? Perhaps it is indeed gRPC. If you see no problems with that combination, then we can go hunt in gRPC alone.
jadekler
on 12 Oct 2018
@jadekler can do. Also want to make sure that this didn't get lost:
Yes, both of the values are the same. Would you recommend setting the MaxExtension to something higher or just disabling it completely (setting to less than 0)?
jameshartig
on 12 Oct 2018
Ah, apologies. I think your settings look fine; I don't recall the semantics of MaxExtension changing. I'll keep an eye out for it whilst I go digging, though. Thanks again for sticking with this.
jadekler
on 12 Oct 2018
Just to follow up, I've deployed an app at HEAD and an app at v0.24.0 and I'm seeing about equivalent amount of RPCs being sent. So, that's a dead end as to why you might have been rate limited. I'll keep running the app to see if I experience the deadlock and await further word about whether grpc=v1.13.0 and google-cloud-go=HEAD worked for you.
(orange is v0.24.0, blue is HEAD)
jadekler
on 12 Oct 2018
I deployed to 2 servers at 20:00 UTC:
cloud.google.com/go (git) - 5f0ffe7 pubsub: Fix a possible deadlock in pstest
google.golang.org/grpc (git) - 168a619 Change version to 1.13.0
There hasn't been any issues yet and it's been a bit over 90 minutes.
I'm still confused how last night the old instances were somehow affected by the new instances so that's still bizarre to me but at least we might have narrowed it down to a grpc-go issue. I'll leave these 2 servers on these commits for a while longer and report if anything happens.
jameshartig
on 12 Oct 2018
Right on. That solidifies that it's likely a grpc-go problem. Thanks for helping us look into this. I _think_ I have a repro, though my app only sees to go down for 5 minutes or so at a time. Anyways, we'll start looking in grpc to see what we can find. Will update here when I know more.
jadekler
on 13 Oct 2018
@fastest963 Updates:
- I've tried unsuccessfully to reproduce this problem by pushing a subscriber with your receive settings and watching it successfully receive 150M messages over three days.
- grpc-go team and I have discussed this. Would it be possible for you to help us figure out which commit is at fault, starting by deploying v1.15.0 to establish a lower bound? Then, if you do not see a problem, could you try right before and right after
35c3afad17f705e725ca04bff658932689920154? This commit - as you saw in my original PR a while ago - is definitely suspect.
We're also discussing how we can help users diagnose problems like this more easily by adding logging and tracing options.
Finally, if you are at all able to provide the holy grail - a reproduction - we'd love that, too!
jadekler
on 15 Oct 2018
@jadekler I can try to. It takes a while for the problem to happen so it might be a while until I can narrow it down. Not sure what I'm doing different. The only thing I can think of is that the jobs take anywhere from 300-500ms to ack so maybe try sleeping inside your test to see if that somehow is the cause?
jameshartig
on 15 Oct 2018
FYI, keeping grpc-go=v1.13.0 is getting harder (e.g. https://github.com/googleapis/google-api-go-client/commit/625cd1887957946515db468ce519bb71fa31fc7f went in this morning, and depends on a later grpc-go).
dsymonds
on 15 Oct 2018
Yeah I noticed that. Hopefully I can narrow down the issue tonight and report back what commit it breaks on. Just deployed v0.15.0.
jameshartig
on 15 Oct 2018
Thanks, much appreciate y'all. I can roll that commit back if we need to buy more time at an older version.
jadekler
on 16 Oct 2018
Yes, a rollback while this bug gets sorted out would be nice. Thanks.
dsymonds
on 16 Oct 2018
Done. Thanks for mentioning.
jadekler
on 16 Oct 2018
The preliminary results are showing that v1.15.0 is good. Testing out grpc-go=0baa067 now with google-cloud-go=HEAD.
jameshartig
on 16 Oct 2018
Great to hear - thanks for doing that. Look forward to hearing the results.
jadekler
on 16 Oct 2018
I made a small program to try and simulate what we're doing and I ran it with grpc-go=8997b5fa0 and google-cloud-go=HEAD on 6 n1-standard-4 (this might be overkill) instances by just making the startup-script fetch the binary from gcs and then run it.
https://gist.github.com/fastest963/e9ff2774926f864d06e3be1f9edd4000
With grpc-go=8997b5fa0:
-- Logs begin at Thu 2017-10-12 16:41:07 UTC, end at Tue 2018-10-16 00:23:16 UTC. --
Oct 16 00:12:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="51925"
Oct 16 00:13:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="150052"
Oct 16 00:14:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="138931"
Oct 16 00:15:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="18416"
Oct 16 00:16:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="16154"
Oct 16 00:17:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="86790"
Oct 16 00:18:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="25170"
Oct 16 00:19:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="39642"
Oct 16 00:20:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="650"
Oct 16 00:21:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="134982"
Oct 16 00:22:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="115602"
Oct 16 00:23:16 base.11-e.ninja startup-script[789]: INFO startup-script: ~ INFO -- count received last minute -- count="45946"
And the stackdriver metrics for number of streaming pull ack message count:
But with grpc-go=0baa0671:
Oct 16 00:26:56 INFO startup-script: ~ INFO -- count received last minute -- count="3000"
Oct 16 00:27:56 INFO startup-script: ~ INFO -- count received last minute -- count="48852"
Oct 16 00:28:56 INFO startup-script: ~ INFO -- count received last minute -- count="103216"
Oct 16 00:29:56 INFO startup-script: ~ INFO -- count received last minute -- count="150099"
Oct 16 00:30:56 INFO startup-script: ~ INFO -- count received last minute -- count="62855"
Oct 16 00:31:56 INFO startup-script: ~ INFO -- count received last minute -- count="67261"
Oct 16 00:32:56 INFO startup-script: ~ INFO -- count received last minute -- count="133007"
Oct 16 00:33:56 INFO startup-script: ~ INFO -- count received last minute -- count="40492"
Oct 16 00:34:56 INFO startup-script: ~ INFO -- count received last minute -- count="128203"
Oct 16 00:35:56 INFO startup-script: ~ INFO -- count received last minute -- count="141586"
Oct 16 00:36:56 INFO startup-script: ~ INFO -- count received last minute -- count="150077"
Oct 16 00:37:56 INFO startup-script: ~ INFO -- count received last minute -- count="150145"
Oct 16 00:38:56 INFO startup-script: ~ INFO -- count received last minute -- count="150022"
Oct 16 00:39:56 INFO startup-script: ~ INFO -- count received last minute -- count="150123"
Oct 16 00:40:56 INFO startup-script: ~ INFO -- count received last minute -- count="150120"
Oct 16 00:41:56 INFO startup-script: ~ INFO -- count received last minute -- count="150157"
Oct 16 00:42:56 INFO startup-script: ~ INFO -- count received last minute -- count="150157"
Oct 16 00:43:56 INFO startup-script: ~ INFO -- count received last minute -- count="150110"
Oct 16 00:44:56 INFO startup-script: ~ INFO -- count received last minute -- count="150144"
Oct 16 00:45:56 INFO startup-script: ~ INFO -- count received last minute -- count="150056"
Oct 16 00:46:56 INFO startup-script: ~ INFO -- count received last minute -- count="150161"
Oct 16 00:47:56 INFO startup-script: ~ INFO -- count received last minute -- count="150080"
Oct 16 00:48:56 INFO startup-script: ~ INFO -- count received last minute -- count="150130"
Oct 16 00:49:56 INFO startup-script: ~ INFO -- count received last minute -- count="150153"
Oct 16 00:50:56 INFO startup-script: ~ INFO -- count received last minute -- count="150054"
Oct 16 00:51:56 INFO startup-script: ~ INFO -- count received last minute -- count="150096"
Oct 16 00:52:56 INFO startup-script: ~ INFO -- count received last minute -- count="150072"
Oct 16 00:53:56 INFO startup-script: ~ INFO -- count received last minute -- count="149966"
Oct 16 00:54:56 INFO startup-script: ~ INFO -- count received last minute -- count="150157"
Oct 16 00:55:56 INFO startup-script: ~ INFO -- count received last minute -- count="150266"
I'd expect it to stay around 150k a minute (except for slow ramp up) but with the newer commit it fluctuates a lot and falls below 20k (even 1k at one point).
I didn't run either of them for long enough to fully prove that the issue is between those commits but at least it seems like something that _could_ reproduce what we're seeing. I thought I'd at least get something up for you to try and reproduce yourself as well.
I'll continue running our regular subscribers with the older commit overnight and switch to the newer one in the morning.
jameshartig
on 16 Oct 2018
I started up the reproduction program above with grpc-go=HEAD and after 70 minutes it stopped receiving barely anything:
Oct 16 12:40:11 INFO startup-script: ~ INFO -- count received last minute -- count="150136"
Oct 16 12:41:11 INFO startup-script: ~ INFO -- count received last minute -- count="150165"
Oct 16 12:42:11 INFO startup-script: ~ INFO -- count received last minute -- count="150263"
Oct 16 12:43:11 INFO startup-script: ~ INFO -- count received last minute -- count="150128"
Oct 16 12:44:11 INFO startup-script: ~ INFO -- count received last minute -- count="150156"
Oct 16 12:45:11 INFO startup-script: ~ INFO -- count received last minute -- count="150027"
Oct 16 12:46:11 INFO startup-script: ~ INFO -- count received last minute -- count="150179"
Oct 16 12:47:11 INFO startup-script: ~ INFO -- count received last minute -- count="150069"
Oct 16 12:48:11 INFO startup-script: ~ INFO -- count received last minute -- count="150187"
Oct 16 12:49:11 INFO startup-script: ~ INFO -- count received last minute -- count="150110"
Oct 16 12:50:11 INFO startup-script: ~ INFO -- count received last minute -- count="150010"
Oct 16 12:51:11 INFO startup-script: ~ INFO -- count received last minute -- count="150120"
Oct 16 12:52:11 INFO startup-script: ~ INFO -- count received last minute -- count="150072"
Oct 16 12:53:11 INFO startup-script: ~ INFO -- count received last minute -- count="150134"
Oct 16 12:54:11 INFO startup-script: ~ INFO -- count received last minute -- count="146847"
Oct 16 12:55:11 INFO startup-script: ~ INFO -- count received last minute -- count="149124"
Oct 16 12:56:11 INFO startup-script: ~ INFO -- count received last minute -- count="147338"
Oct 16 12:57:11 INFO startup-script: ~ INFO -- count received last minute -- count="148088"
Oct 16 12:58:11 INFO startup-script: ~ INFO -- count received last minute -- count="150038"
Oct 16 12:59:11 INFO startup-script: ~ INFO -- count received last minute -- count="150145"
Oct 16 13:00:11 INFO startup-script: ~ INFO -- count received last minute -- count="150152"
Oct 16 13:01:11 INFO startup-script: ~ INFO -- count received last minute -- count="150217"
Oct 16 13:02:11 INFO startup-script: ~ INFO -- count received last minute -- count="150092"
Oct 16 13:03:11 INFO startup-script: ~ INFO -- count received last minute -- count="150120"
Oct 16 13:04:11 INFO startup-script: ~ INFO -- count received last minute -- count="149731"
Oct 16 13:05:11 INFO startup-script: ~ INFO -- count received last minute -- count="150098"
Oct 16 13:06:11 INFO startup-script: ~ INFO -- count received last minute -- count="150114"
Oct 16 13:07:11 INFO startup-script: ~ INFO -- count received last minute -- count="149135"
Oct 16 13:08:11 INFO startup-script: ~ INFO -- count received last minute -- count="136649"
Oct 16 13:09:11 INFO startup-script: ~ INFO -- count received last minute -- count="149484"
Oct 16 13:10:11 INFO startup-script: ~ INFO -- count received last minute -- count="103983"
Oct 16 13:11:11 INFO startup-script: ~ INFO -- count received last minute -- count="2655"
Oct 16 13:12:11 INFO startup-script: ~ INFO -- count received last minute -- count="567"
Oct 16 13:13:11 INFO startup-script: ~ INFO -- count received last minute -- count="2233"
Oct 16 13:14:11 INFO startup-script: ~ INFO -- count received last minute -- count="1309"
Oct 16 13:15:11 INFO startup-script: ~ INFO -- count received last minute -- count="2814"
Oct 16 13:16:11 INFO startup-script: ~ INFO -- count received last minute -- count="5389"
Oct 16 13:17:11 INFO startup-script: ~ INFO -- count received last minute -- count="9409"
Oct 16 13:18:11 INFO startup-script: ~ INFO -- count received last minute -- count="4282"
Oct 16 13:19:11 INFO startup-script: ~ INFO -- count received last minute -- count="2729"
Oct 16 13:20:11 INFO startup-script: ~ INFO -- count received last minute -- count="14089"
Oct 16 13:21:11 INFO startup-script: ~ INFO -- count received last minute -- count="50539"
Oct 16 13:22:11 INFO startup-script: ~ INFO -- count received last minute -- count="3899"
Oct 16 13:23:11 INFO startup-script: ~ INFO -- count received last minute -- count="0"
Oct 16 13:24:11 INFO startup-script: ~ INFO -- count received last minute -- count="4383"
Oct 16 13:25:11 INFO startup-script: ~ INFO -- count received last minute -- count="1225"
Oct 16 13:26:11 INFO startup-script: ~ INFO -- count received last minute -- count="3102"
Oct 16 13:27:11 INFO startup-script: ~ INFO -- count received last minute -- count="3783"
Oct 16 13:28:11 INFO startup-script: ~ INFO -- count received last minute -- count="6891"
Oct 16 13:29:11 INFO startup-script: ~ INFO -- count received last minute -- count="2520"
Oct 16 13:30:11 INFO startup-script: ~ INFO -- count received last minute -- count="3047"
Oct 16 13:31:11 INFO startup-script: ~ INFO -- count received last minute -- count="8370"
Unfortunately I couldn't get a goroutine dump because I did:
mux.HandleFunc("/pprof", pprof.Index)
馃槥
I was also running our usual subscriber with grpc-go=8997b5fa0 on 2 servers (blue and pink) and it ran into a problem after ~70 minutes as well:
So it definitely seems like the issue is the commit you mentioned but it somehow also affects our other subscribers that are still running the older grpc-go code. I'm not sure if the Pub/Sub team has any metrics that they can look into to see what happened at 1:19pm UTC to help. As soon as I deployed the older grpc-go=0baa0671 to those 2 servers things immediately went back to normal on all of the instances.
jameshartig
on 16 Oct 2018
Here's a goroutine dump from the latest grpc-go=HEAD test (running the gist I posted earlier) after it started receiving barely any messages:
goroutine profile: total 203
40 @ 0x42db9b 0x42dc43 0x405a6e 0x40575b 0x847cf8 0x45b831
# 0x847cf7 cloud.google.com/go/pubsub.(*Subscription).receive.func1+0x47 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:512
38 @ 0x42db9b 0x43d9ad 0x7f739d 0x7f2748 0x7fe09e 0x7fd393 0x7ee78c 0x7ee543 0x8280d2 0x839a38 0x8070a0 0x806e76 0x835f97 0x847081 0x83fced 0x83fa08 0x83f40c 0x45b831
# 0x7f739c google.golang.org/grpc.(*pickerWrapper).pick+0x56c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x7f2747 google.golang.org/grpc.(*ClientConn).getTransport+0x97 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/clientconn.go:721
# 0x7fe09d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:309
# 0x7fd392 google.golang.org/grpc.newClientStream+0x712 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:269
# 0x7ee78b google.golang.org/grpc.invoke+0x9b C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:66
# 0x7ee542 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:37
# 0x8280d1 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).Acknowledge+0xd1 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:2864
# 0x839a37 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).Acknowledge.func1+0x77 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:333
# 0x80709f github.com/googleapis/gax-go.invoke+0x8f C:/Users/james/go/src/github.com/googleapis/gax-go/invoke.go:70
# 0x806e75 github.com/googleapis/gax-go.Invoke+0xf5 C:/Users/james/go/src/github.com/googleapis/gax-go/invoke.go:48
# 0x835f96 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).Acknowledge+0x1a6 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:331
# 0x847080 cloud.google.com/go/pubsub.(*messageIterator).sendAck.func1+0x100 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:384
# 0x83fcec cloud.google.com/go/pubsub.(*messageIterator).sendAckIDRPC+0x22c C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:448
# 0x83fa07 cloud.google.com/go/pubsub.(*messageIterator).sendAck+0x57 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:379
# 0x83f40b cloud.google.com/go/pubsub.(*messageIterator).sender+0x3fb C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:336
31 @ 0x42db9b 0x43d9ad 0x7e04de 0x7e02aa 0x7e1035 0x4729a8 0x472b48 0x7e0f7f 0x7f99b5 0x7fa62d 0x7facdb 0x8003a4 0x802dcd 0x7ff131 0x7ffb2d 0x8284d2 0x847991 0x84126c 0x84153e 0x83ef93 0x83ece3 0x844dd2 0x847c87 0x83b3a7 0x45b831
# 0x7e04dd google.golang.org/grpc/internal/transport.(*recvBufferReader).read+0x1ad C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:142
# 0x7e02a9 google.golang.org/grpc/internal/transport.(*recvBufferReader).Read+0x59 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:131
# 0x7e1034 google.golang.org/grpc/internal/transport.(*transportReader).Read+0x54 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:401
# 0x4729a7 io.ReadAtLeast+0x87 c:/go/src/io/io.go:310
# 0x472b47 io.ReadFull+0x57 c:/go/src/io/io.go:329
# 0x7e0f7e google.golang.org/grpc/internal/transport.(*Stream).Read+0xbe C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:385
# 0x7f99b4 google.golang.org/grpc.(*parser).recvMsg+0x64 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/rpc_util.go:476
# 0x7fa62c google.golang.org/grpc.recvAndDecompress+0x4c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/rpc_util.go:602
# 0x7facda google.golang.org/grpc.recv+0x9a C:/Users/james/Dropbox/go/src/google.golang.org/grpc/rpc_util.go:645
# 0x8003a3 google.golang.org/grpc.(*csAttempt).recvMsg+0xe3 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:762
# 0x802dcc google.golang.org/grpc.(*clientStream).RecvMsg.func1+0x3c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:648
# 0x7ff130 google.golang.org/grpc.(*clientStream).withRetry+0x280 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:530
# 0x7ffb2c google.golang.org/grpc.(*clientStream).RecvMsg+0x8c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:647
# 0x8284d1 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberStreamingPullClient).Recv+0x61 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:2905
# 0x847990 cloud.google.com/go/pubsub.(*pullStream).Recv.func1+0x70 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:172
# 0x84126b cloud.google.com/go/pubsub.(*pullStream).call+0xcb C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:132
# 0x84153d cloud.google.com/go/pubsub.(*pullStream).Recv+0x6d C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:169
# 0x83ef92 cloud.google.com/go/pubsub.(*messageIterator).recvMessages+0x32 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:251
# 0x83ece2 cloud.google.com/go/pubsub.(*messageIterator).receive+0x602 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:194
# 0x844dd1 cloud.google.com/go/pubsub.(*Subscription).receive+0x401 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:545
# 0x847c86 cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x56 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:489
# 0x83b3a6 golang.org/x/sync/errgroup.(*Group).Go.func1+0x56 C:/Users/james/go/src/golang.org/x/sync/errgroup/errgroup.go:58
31 @ 0x42db9b 0x43d9ad 0x8028c7 0x45b831
# 0x8028c6 google.golang.org/grpc.newClientStream.func5+0xd6 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:287
25 @ 0x42db9b 0x43d9ad 0x8465a5 0x849b53 0x45b831
# 0x8465a4 cloud.google.com/go/pubsub.(*PublishResult).Get+0xe4 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/topic.go:380
# 0x849b52 main.main.func2+0x122 C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:72
9 @ 0x42db9b 0x43d9ad 0x7f739d 0x7f2748 0x7fe09e 0x7fd393 0x7fcabf 0x828328 0x839bce 0x8070a0 0x806e76 0x83650b 0x848683 0x847651 0x841068 0x840e6c 0x841208 0x84153e 0x83ef93 0x83ece3 0x844dd2 0x847c87 0x83b3a7 0x45b831
# 0x7f739c google.golang.org/grpc.(*pickerWrapper).pick+0x56c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x7f2747 google.golang.org/grpc.(*ClientConn).getTransport+0x97 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/clientconn.go:721
# 0x7fe09d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:309
# 0x7fd392 google.golang.org/grpc.newClientStream+0x712 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:269
# 0x7fcabe google.golang.org/grpc.(*ClientConn).NewStream+0x17e C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:145
# 0x828327 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).StreamingPull+0xa7 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:2881
# 0x839bcd cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull.func1+0x7d C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:371
# 0x80709f github.com/googleapis/gax-go.invoke+0x8f C:/Users/james/go/src/github.com/googleapis/gax-go/invoke.go:70
# 0x806e75 github.com/googleapis/gax-go.Invoke+0xf5 C:/Users/james/go/src/github.com/googleapis/gax-go/invoke.go:48
# 0x83650a cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull+0x1ca C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:369
# 0x848682 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull-fm+0x62 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:77
# 0x847650 cloud.google.com/go/pubsub.newPullStream.func1+0x1f0 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:47
# 0x841067 cloud.google.com/go/pubsub.(*pullStream).openWithRetry+0x77 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:108
# 0x840e6b cloud.google.com/go/pubsub.(*pullStream).get+0xfb C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:100
# 0x841207 cloud.google.com/go/pubsub.(*pullStream).call+0x67 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:127
# 0x84153d cloud.google.com/go/pubsub.(*pullStream).Recv+0x6d C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:169
# 0x83ef92 cloud.google.com/go/pubsub.(*messageIterator).recvMessages+0x32 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:251
# 0x83ece2 cloud.google.com/go/pubsub.(*messageIterator).receive+0x602 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:194
# 0x844dd1 cloud.google.com/go/pubsub.(*Subscription).receive+0x401 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:545
# 0x847c86 cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x56 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:489
# 0x83b3a6 golang.org/x/sync/errgroup.(*Group).Go.func1+0x56 C:/Users/james/go/src/golang.org/x/sync/errgroup/errgroup.go:58
4 @ 0x42db9b 0x428ed9 0x428586 0x4900ea 0x4901fd 0x490f49 0x5830cf 0x596128 0x5e0e29 0x5e132d 0x5e48b1 0x54105f 0x4729a8 0x472b48 0x7c0a4b 0x7c12b3 0x7db566 0x45b831
# 0x428585 internal/poll.runtime_pollWait+0x65 c:/go/src/runtime/netpoll.go:173
# 0x4900e9 internal/poll.(*pollDesc).wait+0x99 c:/go/src/internal/poll/fd_poll_runtime.go:85
# 0x4901fc internal/poll.(*pollDesc).waitRead+0x3c c:/go/src/internal/poll/fd_poll_runtime.go:90
# 0x490f48 internal/poll.(*FD).Read+0x178 c:/go/src/internal/poll/fd_unix.go:169
# 0x5830ce net.(*netFD).Read+0x4e c:/go/src/net/fd_unix.go:202
# 0x596127 net.(*conn).Read+0x67 c:/go/src/net/net.go:177
# 0x5e0e28 crypto/tls.(*block).readFromUntil+0x88 c:/go/src/crypto/tls/conn.go:492
# 0x5e132c crypto/tls.(*Conn).readRecord+0xdc c:/go/src/crypto/tls/conn.go:593
# 0x5e48b0 crypto/tls.(*Conn).Read+0xf0 c:/go/src/crypto/tls/conn.go:1145
# 0x54105e bufio.(*Reader).Read+0x22e c:/go/src/bufio/bufio.go:216
# 0x4729a7 io.ReadAtLeast+0x87 c:/go/src/io/io.go:310
# 0x472b47 io.ReadFull+0x57 c:/go/src/io/io.go:329
# 0x7c0a4a golang.org/x/net/http2.readFrameHeader+0x7a C:/Users/james/go/src/golang.org/x/net/http2/frame.go:237
# 0x7c12b2 golang.org/x/net/http2.(*Framer).ReadFrame+0xa2 C:/Users/james/go/src/golang.org/x/net/http2/frame.go:492
# 0x7db565 google.golang.org/grpc/internal/transport.(*http2Client).reader+0x175 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/http2_client.go:1209
4 @ 0x42db9b 0x43d9ad 0x7ce6c3 0x7ceddc 0x7e193b 0x45b831
# 0x7ce6c2 google.golang.org/grpc/internal/transport.(*controlBuffer).get+0x102 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/controlbuf.go:317
# 0x7ceddb google.golang.org/grpc/internal/transport.(*loopyWriter).run+0x1ab C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/controlbuf.go:435
# 0x7e193a google.golang.org/grpc/internal/transport.newHTTP2Client.func3+0x7a C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/http2_client.go:319
4 @ 0x42db9b 0x43d9ad 0x7dbd33 0x45b831
# 0x7dbd32 google.golang.org/grpc/internal/transport.(*http2Client).keepalive+0x112 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/http2_client.go:1260
2 @ 0x42db9b 0x43d9ad 0x83f248 0x45b831
# 0x83f247 cloud.google.com/go/pubsub.(*messageIterator).sender+0x237 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:279
1 @ 0x40ab97 0x44259c 0x712482 0x45b831
# 0x44259b os/signal.signal_recv+0x9b c:/go/src/runtime/sigqueue.go:139
# 0x712481 os/signal.loop+0x21 c:/go/src/os/signal/signal_unix.go:23
1 @ 0x42db9b 0x428ed9 0x428586 0x4900ea 0x4901fd 0x4924f0 0x583a12 0x59ff1e 0x59e957 0x68415f 0x6a4b3c 0x682f8f 0x682c46 0x683c34 0x849a1e 0x45b831
# 0x428585 internal/poll.runtime_pollWait+0x65 c:/go/src/runtime/netpoll.go:173
# 0x4900e9 internal/poll.(*pollDesc).wait+0x99 c:/go/src/internal/poll/fd_poll_runtime.go:85
# 0x4901fc internal/poll.(*pollDesc).waitRead+0x3c c:/go/src/internal/poll/fd_poll_runtime.go:90
# 0x4924ef internal/poll.(*FD).Accept+0x19f c:/go/src/internal/poll/fd_unix.go:384
# 0x583a11 net.(*netFD).accept+0x41 c:/go/src/net/fd_unix.go:238
# 0x59ff1d net.(*TCPListener).accept+0x2d c:/go/src/net/tcpsock_posix.go:139
# 0x59e956 net.(*TCPListener).AcceptTCP+0x46 c:/go/src/net/tcpsock.go:247
# 0x68415e net/http.tcpKeepAliveListener.Accept+0x2e c:/go/src/net/http/server.go:3232
# 0x682f8e net/http.(*Server).Serve+0x22e c:/go/src/net/http/server.go:2826
# 0x682c45 net/http.(*Server).ListenAndServe+0xb5 c:/go/src/net/http/server.go:2764
# 0x683c33 net/http.ListenAndServe+0x73 c:/go/src/net/http/server.go:3004
# 0x849a1d main.main.func1+0x3d C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:39
1 @ 0x42db9b 0x42dc43 0x405a6e 0x40575b 0x805e5a 0x7e8b37 0x80149b 0x45b831
# 0x805e59 google.golang.org/api/internal.(*PoolResolver).Next+0x49 C:/Users/james/go/src/google.golang.org/api/internal/pool.go:54
# 0x7e8b36 google.golang.org/grpc.(*roundRobin).watchAddrUpdates+0x56 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer.go:145
# 0x80149a google.golang.org/grpc.(*roundRobin).Start.func1+0x2a C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer.go:220
1 @ 0x42db9b 0x42dc43 0x405a6e 0x40575b 0x8497da 0x42d7a7 0x45b831
# 0x8497d9 main.main+0x5c9 C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:124
# 0x42d7a6 runtime.main+0x206 c:/go/src/runtime/proc.go:201
1 @ 0x42db9b 0x42dc43 0x405a6e 0x40579b 0x7ebf6c 0x45b831
# 0x7ebf6b google.golang.org/grpc.(*balancerWrapper).lbWatcher+0xeb C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer_v1_wrapper.go:124
1 @ 0x42db9b 0x42dc43 0x43e55c 0x43e199 0x4724f4 0x83b221 0x844843 0x849fc7 0x45b831
# 0x43e198 sync.runtime_Semacquire+0x38 c:/go/src/runtime/sema.go:56
# 0x4724f3 sync.(*WaitGroup).Wait+0x63 c:/go/src/sync/waitgroup.go:130
# 0x83b220 golang.org/x/sync/errgroup.(*Group).Wait+0x30 C:/Users/james/go/src/golang.org/x/sync/errgroup/errgroup.go:41
# 0x844842 cloud.google.com/go/pubsub.(*Subscription).Receive+0x322 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:492
# 0x849fc6 main.main.func4+0xa6 C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:106
1 @ 0x42db9b 0x42dc43 0x43f59b 0x46f582 0x83c215 0x83bd8d 0x83c69a 0x45b831
# 0x43f59a sync.runtime_notifyListWait+0xea c:/go/src/runtime/sema.go:510
# 0x46f581 sync.(*Cond).Wait+0x91 c:/go/src/sync/cond.go:56
# 0x83c214 google.golang.org/api/support/bundler.(*Bundler).waitUntilAllHandled+0x74 C:/Users/james/go/src/google.golang.org/api/support/bundler/bundler.go:335
# 0x83bd8c google.golang.org/api/support/bundler.(*Bundler).Flush+0x8c C:/Users/james/go/src/google.golang.org/api/support/bundler/bundler.go:250
# 0x83c699 google.golang.org/api/support/bundler.(*Bundler).Flush-fm+0x29 C:/Users/james/go/src/google.golang.org/api/support/bundler/bundler.go:195
1 @ 0x42db9b 0x43d9ad 0x713fed 0x45b831
# 0x713fec github.com/levenlabs/go-llog.init.0.func1+0xfc C:/Users/james/Dropbox/go/src/github.com/levenlabs/go-llog/llog.go:242
1 @ 0x42db9b 0x43d9ad 0x742bcd 0x45b831
# 0x742bcc go.opencensus.io/stats/view.(*worker).start+0xdc C:/Users/james/go/src/go.opencensus.io/stats/view/worker.go:146
1 @ 0x42db9b 0x43d9ad 0x7eab9f 0x45b831
# 0x7eab9e google.golang.org/grpc.(*ccBalancerWrapper).watcher+0x10e C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer_conn_wrappers.go:122
1 @ 0x42db9b 0x43d9ad 0x7f739d 0x7f2748 0x7fe09e 0x7fd393 0x7ee78c 0x7ee543 0x8271d2 0x837ec4 0x8070a0 0x806e76 0x832391 0x846cb7 0x847fb3 0x83c524 0x45b831
# 0x7f739c google.golang.org/grpc.(*pickerWrapper).pick+0x56c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x7f2747 google.golang.org/grpc.(*ClientConn).getTransport+0x97 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/clientconn.go:721
# 0x7fe09d google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:309
# 0x7fd392 google.golang.org/grpc.newClientStream+0x712 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:269
# 0x7ee78b google.golang.org/grpc.invoke+0x9b C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:66
# 0x7ee542 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:37
# 0x8271d1 google.golang.org/genproto/googleapis/pubsub/v1.(*publisherClient).Publish+0xd1 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:2416
# 0x837ec3 cloud.google.com/go/pubsub/apiv1.(*PublisherClient).Publish.func1+0x83 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:196
# 0x80709f github.com/googleapis/gax-go.invoke+0x8f C:/Users/james/go/src/github.com/googleapis/gax-go/invoke.go:70
# 0x806e75 github.com/googleapis/gax-go.Invoke+0xf5 C:/Users/james/go/src/github.com/googleapis/gax-go/invoke.go:48
# 0x832390 cloud.google.com/go/pubsub/apiv1.(*PublisherClient).Publish+0x1d0 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:194
# 0x846cb6 cloud.google.com/go/pubsub.(*Topic).publishMessageBundle+0x396 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/topic.go:450
# 0x847fb2 cloud.google.com/go/pubsub.(*Topic).initBundler.func1+0x82 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/topic.go:422
# 0x83c523 google.golang.org/api/support/bundler.(*Bundler).startFlushLocked.func1+0xd3 C:/Users/james/go/src/google.golang.org/api/support/bundler/bundler.go:272
1 @ 0x42db9b 0x43d9ad 0x7f8ef2 0x45b831
# 0x7f8ef1 google.golang.org/grpc.(*ccResolverWrapper).watcher+0x141 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/resolver_conn_wrapper.go:111
1 @ 0x42db9b 0x43d9ad 0x849dae 0x45b831
# 0x849dad main.main.func3+0x12d C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:92
1 @ 0x6799e0 0x45b831
# 0x6799e0 net/http.(*connReader).backgroundRead+0x0 c:/go/src/net/http/server.go:675
1 @ 0x708148 0x707f50 0x7049b4 0x710df0 0x7116c3 0x67fed4 0x681b77 0x682b1b 0x67ef36 0x45b831
# 0x708147 runtime/pprof.writeRuntimeProfile+0x97 c:/go/src/runtime/pprof/pprof.go:707
# 0x707f4f runtime/pprof.writeGoroutine+0x9f c:/go/src/runtime/pprof/pprof.go:669
# 0x7049b3 runtime/pprof.(*Profile).WriteTo+0x3e3 c:/go/src/runtime/pprof/pprof.go:328
# 0x710def net/http/pprof.handler.ServeHTTP+0x20f c:/go/src/net/http/pprof/pprof.go:245
# 0x7116c2 net/http/pprof.Index+0x722 c:/go/src/net/http/pprof/pprof.go:268
# 0x67fed3 net/http.HandlerFunc.ServeHTTP+0x43 c:/go/src/net/http/server.go:1964
# 0x681b76 net/http.(*ServeMux).ServeHTTP+0x126 c:/go/src/net/http/server.go:2361
# 0x682b1a net/http.serverHandler.ServeHTTP+0xaa c:/go/src/net/http/server.go:2741
# 0x67ef35 net/http.(*conn).serve+0x645 c:/go/src/net/http/server.go:1847
@fastest963 Thank you for providing that repro. I've played with it today, and added instrumentation in pubsub to record:
With retries: Recv calls, Modack RPC calls, Publish RPC calls, StreamingPull RPC calls, Ack RPC calls
Without retries: Recv calls, Modack RPC calls, Publish RPC calls, StreamingPull RPC calls, Ack RPC calls
Num retries (former - latter): Recv calls, Modack RPC calls, Publish RPC calls, StreamingPull RPC calls, Ack RPC calls
Here are my results:
I've only run this for about 20m, but in that time I noticed very little difference between the before and the after. I have it set up to run for a few hours now to see if I notice a degradation over time.
As you've suggested, I think you're running into an issue that only occurs in a rate limiting situation. It's possible Pub/Sub sends a GOAWAY in a rate limiting situation and the grpc-go logic for handling GOAWAYs are funky in that commit. I'd love to narrow in on this a bit further, though. To check whether you're being rate limited, would you mind emailing your project ID, subscription ID, and topic ID to me at [email protected]? With that I can ask the Pub/Sub team to check out what's going on.
Meanwhile, I'm waiting to hear back from their team about what rate limiting looks like, and how I can simulate it.
If you have energy to try another thing, would you mind pulling down my copies of the instrumented client libraries and sending me the dump they produce against: 8997b5f, cfb9600 (before/after again)? It will give us information about whether the library is retrying RPCs more frequently in grpc-go=HEAD versus grpc-go=(older). The repos are:
$GOPATH/src/cloud.google.com/go=> https://github.com/jadekler/google-cloud-go.git on branchpubsub_fastest_instrumentation$GOPATH/src/github.com/googleapis/gax-go=> https://github.com/jadekler/gax-go.git on branchpubsub_fastest_instrumentation
When running with these branches, the Pub/Sub client will spit out 3 extra log lines a minute in the same manner as your repro above.
jadekler
on 17 Oct 2018
Sent over that info. I'll get another test started in the morning with those branches listed above and respond with the results. Thanks!
jameshartig
on 17 Oct 2018
Here's the log from grpc-go=8997b5f:
Oct 17 14:54:09 INFO startup-script: WITH RETRIES: countRecv 4384 countModack: 4758 countPublish: 4325 countStreamingPull: 40 countAck: 14291
Oct 17 14:54:09 INFO startup-script: WITHOUT RETRIES: countRecv 4384 countModack: 4758 countPublish: 4325 countStreamingPull: 40 countAck: 14291
Oct 17 14:54:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 14:54:09 INFO startup-script: ~ INFO -- count received last minute -- count="117452"
Oct 17 14:55:09 INFO startup-script: WITH RETRIES: countRecv 4579 countModack: 5028 countPublish: 4643 countStreamingPull: 0 countAck: 16631
Oct 17 14:55:09 INFO startup-script: WITHOUT RETRIES: countRecv 4579 countModack: 5028 countPublish: 4643 countStreamingPull: 0 countAck: 16631
Oct 17 14:55:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 14:55:09 INFO startup-script: ~ INFO -- count received last minute -- count="124833"
Oct 17 14:56:09 INFO startup-script: WITH RETRIES: countRecv 5337 countModack: 5856 countPublish: 5523 countStreamingPull: 0 countAck: 23130
Oct 17 14:56:09 INFO startup-script: WITHOUT RETRIES: countRecv 5337 countModack: 5856 countPublish: 5523 countStreamingPull: 0 countAck: 23130
Oct 17 14:56:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 14:56:09 INFO startup-script: ~ INFO -- count received last minute -- count="147869"
Oct 17 14:57:09 INFO startup-script: WITH RETRIES: countRecv 5412 countModack: 5864 countPublish: 5282 countStreamingPull: 0 countAck: 23275
Oct 17 14:57:09 INFO startup-script: WITHOUT RETRIES: countRecv 5412 countModack: 5864 countPublish: 5282 countStreamingPull: 0 countAck: 23275
Oct 17 14:57:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 14:57:09 INFO startup-script: ~ INFO -- count received last minute -- count="148361"
Oct 17 14:58:09 INFO startup-script: WITH RETRIES: countRecv 5343 countModack: 5821 countPublish: 5165 countStreamingPull: 0 countAck: 22914
Oct 17 14:58:09 INFO startup-script: WITHOUT RETRIES: countRecv 5343 countModack: 5821 countPublish: 5165 countStreamingPull: 0 countAck: 22914
Oct 17 14:58:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 14:58:09 INFO startup-script: ~ INFO -- count received last minute -- count="146204"
Oct 17 14:59:09 INFO startup-script: WITH RETRIES: countRecv 5262 countModack: 5729 countPublish: 5474 countStreamingPull: 0 countAck: 21955
Oct 17 14:59:09 INFO startup-script: WITHOUT RETRIES: countRecv 5262 countModack: 5729 countPublish: 5474 countStreamingPull: 0 countAck: 21955
Oct 17 14:59:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 14:59:09 INFO startup-script: ~ INFO -- count received last minute -- count="143815"
Oct 17 15:00:09 INFO startup-script: WITH RETRIES: countRecv 5285 countModack: 5731 countPublish: 5387 countStreamingPull: 0 countAck: 22072
Oct 17 15:00:09 INFO startup-script: WITHOUT RETRIES: countRecv 5285 countModack: 5731 countPublish: 5387 countStreamingPull: 0 countAck: 22072
Oct 17 15:00:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:00:09 INFO startup-script: ~ INFO -- count received last minute -- count="143614"
Oct 17 15:01:09 INFO startup-script: WITH RETRIES: countRecv 4756 countModack: 5194 countPublish: 4365 countStreamingPull: 0 countAck: 17972
Oct 17 15:01:09 INFO startup-script: WITHOUT RETRIES: countRecv 4756 countModack: 5194 countPublish: 4366 countStreamingPull: 0 countAck: 17972
Oct 17 15:01:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 1 countStreamingPull: 0 countAck: 0
Oct 17 15:01:09 INFO startup-script: ~ INFO -- count received last minute -- count="129838"
Oct 17 15:02:09 INFO startup-script: WITH RETRIES: countRecv 4465 countModack: 4909 countPublish: 4436 countStreamingPull: 0 countAck: 16164
Oct 17 15:02:09 INFO startup-script: WITHOUT RETRIES: countRecv 4465 countModack: 4909 countPublish: 4435 countStreamingPull: 0 countAck: 16164
Oct 17 15:02:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: -1 countStreamingPull: 0 countAck: 0
Oct 17 15:02:09 INFO startup-script: ~ INFO -- count received last minute -- count="121508"
Oct 17 15:03:09 INFO startup-script: WITH RETRIES: countRecv 4814 countModack: 5248 countPublish: 4896 countStreamingPull: 0 countAck: 18623
Oct 17 15:03:09 INFO startup-script: WITHOUT RETRIES: countRecv 4814 countModack: 5248 countPublish: 4896 countStreamingPull: 0 countAck: 18623
Oct 17 15:03:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:03:09 INFO startup-script: ~ INFO -- count received last minute -- count="131194"
Oct 17 15:04:09 INFO startup-script: WITH RETRIES: countRecv 4925 countModack: 5369 countPublish: 5272 countStreamingPull: 0 countAck: 18336
Oct 17 15:04:09 INFO startup-script: WITHOUT RETRIES: countRecv 4925 countModack: 5369 countPublish: 5272 countStreamingPull: 0 countAck: 18336
Oct 17 15:04:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:04:09 INFO startup-script: ~ INFO -- count received last minute -- count="134803"
Oct 17 15:05:09 INFO startup-script: WITH RETRIES: countRecv 5253 countModack: 5755 countPublish: 5458 countStreamingPull: 0 countAck: 22297
Oct 17 15:05:09 INFO startup-script: WITHOUT RETRIES: countRecv 5253 countModack: 5755 countPublish: 5458 countStreamingPull: 0 countAck: 22297
Oct 17 15:05:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:05:09 INFO startup-script: ~ INFO -- count received last minute -- count="145773"
Oct 17 15:06:09 INFO startup-script: WITH RETRIES: countRecv 5198 countModack: 5638 countPublish: 4807 countStreamingPull: 0 countAck: 21571
Oct 17 15:06:09 INFO startup-script: WITHOUT RETRIES: countRecv 5198 countModack: 5638 countPublish: 4807 countStreamingPull: 0 countAck: 21571
Oct 17 15:06:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:06:09 INFO startup-script: ~ INFO -- count received last minute -- count="142132"
Oct 17 15:07:09 INFO startup-script: WITH RETRIES: countRecv 4862 countModack: 5317 countPublish: 4781 countStreamingPull: 0 countAck: 18544
Oct 17 15:07:09 INFO startup-script: WITHOUT RETRIES: countRecv 4862 countModack: 5317 countPublish: 4781 countStreamingPull: 0 countAck: 18544
Oct 17 15:07:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:07:09 INFO startup-script: ~ INFO -- count received last minute -- count="132916"
Oct 17 15:08:09 INFO startup-script: WITH RETRIES: countRecv 5464 countModack: 5944 countPublish: 5502 countStreamingPull: 0 countAck: 23982
Oct 17 15:08:09 INFO startup-script: WITHOUT RETRIES: countRecv 5464 countModack: 5944 countPublish: 5502 countStreamingPull: 0 countAck: 23982
Oct 17 15:08:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:08:09 INFO startup-script: ~ INFO -- count received last minute -- count="150129"
Oct 17 15:09:09 INFO startup-script: WITH RETRIES: countRecv 4925 countModack: 5327 countPublish: 4570 countStreamingPull: 0 countAck: 19872
Oct 17 15:09:09 INFO startup-script: WITHOUT RETRIES: countRecv 4925 countModack: 5327 countPublish: 4570 countStreamingPull: 0 countAck: 19872
Oct 17 15:09:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:09:09 INFO startup-script: ~ INFO -- count received last minute -- count="134675"
Oct 17 15:10:09 INFO startup-script: WITH RETRIES: countRecv 4928 countModack: 5386 countPublish: 4778 countStreamingPull: 0 countAck: 19090
Oct 17 15:10:09 INFO startup-script: WITHOUT RETRIES: countRecv 4928 countModack: 5386 countPublish: 4778 countStreamingPull: 0 countAck: 19090
Oct 17 15:10:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:10:09 INFO startup-script: ~ INFO -- count received last minute -- count="134572"
Oct 17 15:11:09 INFO startup-script: WITH RETRIES: countRecv 4748 countModack: 5210 countPublish: 4449 countStreamingPull: 0 countAck: 18004
Oct 17 15:11:09 INFO startup-script: WITHOUT RETRIES: countRecv 4748 countModack: 5210 countPublish: 4449 countStreamingPull: 0 countAck: 18004
Oct 17 15:11:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:11:09 INFO startup-script: ~ INFO -- count received last minute -- count="129818"
Oct 17 15:12:09 INFO startup-script: WITH RETRIES: countRecv 5187 countModack: 5629 countPublish: 4676 countStreamingPull: 0 countAck: 21264
Oct 17 15:12:09 INFO startup-script: WITHOUT RETRIES: countRecv 5187 countModack: 5629 countPublish: 4676 countStreamingPull: 0 countAck: 21264
Oct 17 15:12:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:12:09 INFO startup-script: ~ INFO -- count received last minute -- count="141645"
Oct 17 15:13:09 INFO startup-script: WITH RETRIES: countRecv 5428 countModack: 5946 countPublish: 5506 countStreamingPull: 0 countAck: 23732
Oct 17 15:13:09 INFO startup-script: WITHOUT RETRIES: countRecv 5428 countModack: 5946 countPublish: 5506 countStreamingPull: 0 countAck: 23732
Oct 17 15:13:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:13:09 INFO startup-script: ~ INFO -- count received last minute -- count="149645"
Oct 17 15:14:09 INFO startup-script: WITH RETRIES: countRecv 5466 countModack: 5946 countPublish: 5120 countStreamingPull: 0 countAck: 23720
Oct 17 15:14:09 INFO startup-script: WITHOUT RETRIES: countRecv 5466 countModack: 5946 countPublish: 5120 countStreamingPull: 0 countAck: 23720
Oct 17 15:14:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:14:09 INFO startup-script: ~ INFO -- count received last minute -- count="149782"
Oct 17 15:15:09 INFO startup-script: WITH RETRIES: countRecv 5321 countModack: 5788 countPublish: 4973 countStreamingPull: 0 countAck: 22861
Oct 17 15:15:09 INFO startup-script: WITHOUT RETRIES: countRecv 5321 countModack: 5788 countPublish: 4973 countStreamingPull: 0 countAck: 22861
Oct 17 15:15:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:15:09 INFO startup-script: ~ INFO -- count received last minute -- count="146864"
Oct 17 15:16:09 INFO startup-script: WITH RETRIES: countRecv 5456 countModack: 5949 countPublish: 5418 countStreamingPull: 0 countAck: 23581
Oct 17 15:16:09 INFO startup-script: WITHOUT RETRIES: countRecv 5456 countModack: 5949 countPublish: 5418 countStreamingPull: 0 countAck: 23581
Oct 17 15:16:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:16:09 INFO startup-script: ~ INFO -- count received last minute -- count="149488"
Oct 17 15:17:09 INFO startup-script: WITH RETRIES: countRecv 5245 countModack: 5725 countPublish: 4903 countStreamingPull: 0 countAck: 22082
Oct 17 15:17:09 INFO startup-script: WITHOUT RETRIES: countRecv 5245 countModack: 5725 countPublish: 4903 countStreamingPull: 0 countAck: 22082
Oct 17 15:17:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:17:09 INFO startup-script: ~ INFO -- count received last minute -- count="144567"
Oct 17 15:18:09 INFO startup-script: WITH RETRIES: countRecv 5216 countModack: 5684 countPublish: 5100 countStreamingPull: 0 countAck: 21473
Oct 17 15:18:09 INFO startup-script: WITHOUT RETRIES: countRecv 5216 countModack: 5684 countPublish: 5100 countStreamingPull: 0 countAck: 21473
Oct 17 15:18:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:18:09 INFO startup-script: ~ INFO -- count received last minute -- count="142989"
Oct 17 15:19:09 INFO startup-script: WITH RETRIES: countRecv 4880 countModack: 5320 countPublish: 4696 countStreamingPull: 0 countAck: 20030
Oct 17 15:19:09 INFO startup-script: WITHOUT RETRIES: countRecv 4880 countModack: 5320 countPublish: 4696 countStreamingPull: 0 countAck: 20030
Oct 17 15:19:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:19:09 INFO startup-script: ~ INFO -- count received last minute -- count="135348"
Oct 17 15:20:09 INFO startup-script: WITH RETRIES: countRecv 5295 countModack: 5770 countPublish: 4806 countStreamingPull: 0 countAck: 22265
Oct 17 15:20:09 INFO startup-script: WITHOUT RETRIES: countRecv 5295 countModack: 5770 countPublish: 4807 countStreamingPull: 0 countAck: 22265
Oct 17 15:20:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 1 countStreamingPull: 0 countAck: 0
Oct 17 15:20:09 INFO startup-script: ~ INFO -- count received last minute -- count="145430"
Oct 17 15:21:09 INFO startup-script: WITH RETRIES: countRecv 4747 countModack: 5182 countPublish: 4514 countStreamingPull: 0 countAck: 18413
Oct 17 15:21:09 INFO startup-script: WITHOUT RETRIES: countRecv 4747 countModack: 5182 countPublish: 4513 countStreamingPull: 0 countAck: 18413
Oct 17 15:21:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: -1 countStreamingPull: 0 countAck: 0
Oct 17 15:21:09 INFO startup-script: ~ INFO -- count received last minute -- count="128555"
Oct 17 15:22:09 INFO startup-script: WITH RETRIES: countRecv 4672 countModack: 5123 countPublish: 4520 countStreamingPull: 0 countAck: 17445
Oct 17 15:22:09 INFO startup-script: WITHOUT RETRIES: countRecv 4672 countModack: 5123 countPublish: 4520 countStreamingPull: 0 countAck: 17445
Oct 17 15:22:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:22:09 INFO startup-script: ~ INFO -- count received last minute -- count="128535"
Oct 17 15:23:09 INFO startup-script: WITH RETRIES: countRecv 4977 countModack: 5464 countPublish: 4761 countStreamingPull: 0 countAck: 20449
Oct 17 15:23:09 INFO startup-script: WITHOUT RETRIES: countRecv 4977 countModack: 5464 countPublish: 4761 countStreamingPull: 0 countAck: 20449
Oct 17 15:23:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:23:09 INFO startup-script: ~ INFO -- count received last minute -- count="136915"
Oct 17 15:24:09 INFO startup-script: WITH RETRIES: countRecv 4965 countModack: 5441 countPublish: 5032 countStreamingPull: 12 countAck: 20262
Oct 17 15:24:09 INFO startup-script: WITHOUT RETRIES: countRecv 4965 countModack: 5441 countPublish: 5032 countStreamingPull: 12 countAck: 20262
Oct 17 15:24:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:24:09 INFO startup-script: ~ INFO -- count received last minute -- count="135871"
Oct 17 15:25:09 INFO startup-script: WITH RETRIES: countRecv 4850 countModack: 5256 countPublish: 4891 countStreamingPull: 27 countAck: 17036
Oct 17 15:25:09 INFO startup-script: WITHOUT RETRIES: countRecv 4850 countModack: 5256 countPublish: 4891 countStreamingPull: 27 countAck: 17036
Oct 17 15:25:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:25:09 INFO startup-script: ~ INFO -- count received last minute -- count="131520"
Oct 17 15:26:09 INFO startup-script: WITH RETRIES: countRecv 4906 countModack: 5365 countPublish: 4857 countStreamingPull: 1 countAck: 17014
Oct 17 15:26:09 INFO startup-script: WITHOUT RETRIES: countRecv 4906 countModack: 5365 countPublish: 4857 countStreamingPull: 1 countAck: 17014
Oct 17 15:26:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:26:09 INFO startup-script: ~ INFO -- count received last minute -- count="134585"
Oct 17 15:27:09 INFO startup-script: WITH RETRIES: countRecv 5079 countModack: 5529 countPublish: 4989 countStreamingPull: 0 countAck: 18270
Oct 17 15:27:09 INFO startup-script: WITHOUT RETRIES: countRecv 5079 countModack: 5529 countPublish: 4989 countStreamingPull: 0 countAck: 18270
Oct 17 15:27:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:27:09 INFO startup-script: ~ INFO -- count received last minute -- count="138514"
Oct 17 15:28:09 INFO startup-script: WITH RETRIES: countRecv 5222 countModack: 5649 countPublish: 4684 countStreamingPull: 0 countAck: 21104
Oct 17 15:28:09 INFO startup-script: WITHOUT RETRIES: countRecv 5222 countModack: 5649 countPublish: 4684 countStreamingPull: 0 countAck: 21104
Oct 17 15:28:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:28:09 INFO startup-script: ~ INFO -- count received last minute -- count="142951"
Oct 17 15:29:09 INFO startup-script: WITH RETRIES: countRecv 4999 countModack: 5478 countPublish: 5109 countStreamingPull: 0 countAck: 17603
Oct 17 15:29:09 INFO startup-script: WITHOUT RETRIES: countRecv 4999 countModack: 5478 countPublish: 5109 countStreamingPull: 0 countAck: 17603
Oct 17 15:29:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:29:09 INFO startup-script: ~ INFO -- count received last minute -- count="136820"
Oct 17 15:30:09 INFO startup-script: WITH RETRIES: countRecv 5029 countModack: 5492 countPublish: 4673 countStreamingPull: 0 countAck: 17560
Oct 17 15:30:09 INFO startup-script: WITHOUT RETRIES: countRecv 5029 countModack: 5492 countPublish: 4673 countStreamingPull: 0 countAck: 17560
Oct 17 15:30:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:30:09 INFO startup-script: ~ INFO -- count received last minute -- count="136939"
Oct 17 15:31:09 INFO startup-script: WITH RETRIES: countRecv 4906 countModack: 5375 countPublish: 4760 countStreamingPull: 0 countAck: 18121
Oct 17 15:31:09 INFO startup-script: WITHOUT RETRIES: countRecv 4906 countModack: 5375 countPublish: 4760 countStreamingPull: 0 countAck: 18121
Oct 17 15:31:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:31:09 INFO startup-script: ~ INFO -- count received last minute -- count="134901"
Oct 17 15:32:09 INFO startup-script: WITH RETRIES: countRecv 4342 countModack: 4737 countPublish: 3993 countStreamingPull: 0 countAck: 13874
Oct 17 15:32:09 INFO startup-script: WITHOUT RETRIES: countRecv 4342 countModack: 4737 countPublish: 3993 countStreamingPull: 0 countAck: 13874
Oct 17 15:32:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:32:09 INFO startup-script: ~ INFO -- count received last minute -- count="118337"
Oct 17 15:33:09 INFO startup-script: WITH RETRIES: countRecv 4954 countModack: 5424 countPublish: 4930 countStreamingPull: 0 countAck: 16736
Oct 17 15:33:09 INFO startup-script: WITHOUT RETRIES: countRecv 4954 countModack: 5424 countPublish: 4930 countStreamingPull: 0 countAck: 16736
Oct 17 15:33:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:33:09 INFO startup-script: ~ INFO -- count received last minute -- count="135992"
Oct 17 15:34:09 INFO startup-script: WITH RETRIES: countRecv 4356 countModack: 4774 countPublish: 4086 countStreamingPull: 0 countAck: 14668
Oct 17 15:34:09 INFO startup-script: WITHOUT RETRIES: countRecv 4356 countModack: 4774 countPublish: 4086 countStreamingPull: 0 countAck: 14668
Oct 17 15:34:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:34:09 INFO startup-script: ~ INFO -- count received last minute -- count="118950"
Oct 17 15:35:09 INFO startup-script: WITH RETRIES: countRecv 4736 countModack: 5152 countPublish: 4542 countStreamingPull: 0 countAck: 18097
Oct 17 15:35:09 INFO startup-script: WITHOUT RETRIES: countRecv 4736 countModack: 5152 countPublish: 4542 countStreamingPull: 0 countAck: 18097
Oct 17 15:35:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:35:09 INFO startup-script: ~ INFO -- count received last minute -- count="129673"
Oct 17 15:36:09 INFO startup-script: WITH RETRIES: countRecv 4875 countModack: 5352 countPublish: 4614 countStreamingPull: 0 countAck: 17195
Oct 17 15:36:09 INFO startup-script: WITHOUT RETRIES: countRecv 4875 countModack: 5352 countPublish: 4614 countStreamingPull: 0 countAck: 17195
Oct 17 15:36:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:36:09 INFO startup-script: ~ INFO -- count received last minute -- count="133381"
Oct 17 15:37:09 INFO startup-script: WITH RETRIES: countRecv 4838 countModack: 5317 countPublish: 4991 countStreamingPull: 0 countAck: 17534
Oct 17 15:37:09 INFO startup-script: WITHOUT RETRIES: countRecv 4838 countModack: 5317 countPublish: 4991 countStreamingPull: 0 countAck: 17534
Oct 17 15:37:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:37:09 INFO startup-script: ~ INFO -- count received last minute -- count="132894"
Oct 17 15:38:09 INFO startup-script: WITH RETRIES: countRecv 4697 countModack: 5094 countPublish: 4658 countStreamingPull: 0 countAck: 15555
Oct 17 15:38:09 INFO startup-script: WITHOUT RETRIES: countRecv 4697 countModack: 5094 countPublish: 4658 countStreamingPull: 0 countAck: 15555
Oct 17 15:38:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:38:09 INFO startup-script: ~ INFO -- count received last minute -- count="127657"
Oct 17 15:39:09 INFO startup-script: WITH RETRIES: countRecv 4162 countModack: 4601 countPublish: 3649 countStreamingPull: 0 countAck: 13823
Oct 17 15:39:09 INFO startup-script: WITHOUT RETRIES: countRecv 4162 countModack: 4601 countPublish: 3649 countStreamingPull: 0 countAck: 13823
Oct 17 15:39:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:39:09 INFO startup-script: ~ INFO -- count received last minute -- count="114221"
Oct 17 15:40:09 INFO startup-script: WITH RETRIES: countRecv 5444 countModack: 5943 countPublish: 5579 countStreamingPull: 0 countAck: 23891
Oct 17 15:40:09 INFO startup-script: WITHOUT RETRIES: countRecv 5444 countModack: 5943 countPublish: 5579 countStreamingPull: 0 countAck: 23891
Oct 17 15:40:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:40:09 INFO startup-script: ~ INFO -- count received last minute -- count="150186"
Oct 17 15:41:09 INFO startup-script: WITH RETRIES: countRecv 4877 countModack: 5267 countPublish: 4605 countStreamingPull: 0 countAck: 18709
Oct 17 15:41:09 INFO startup-script: WITHOUT RETRIES: countRecv 4877 countModack: 5267 countPublish: 4605 countStreamingPull: 0 countAck: 18709
Oct 17 15:41:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:41:09 INFO startup-script: ~ INFO -- count received last minute -- count="132422"
Oct 17 15:42:09 INFO startup-script: WITH RETRIES: countRecv 4629 countModack: 5060 countPublish: 4168 countStreamingPull: 0 countAck: 16112
Oct 17 15:42:09 INFO startup-script: WITHOUT RETRIES: countRecv 4629 countModack: 5060 countPublish: 4168 countStreamingPull: 0 countAck: 16112
Oct 17 15:42:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:42:09 INFO startup-script: ~ INFO -- count received last minute -- count="126781"
Oct 17 15:43:09 INFO startup-script: WITH RETRIES: countRecv 4771 countModack: 5229 countPublish: 4837 countStreamingPull: 0 countAck: 17109
Oct 17 15:43:09 INFO startup-script: WITHOUT RETRIES: countRecv 4771 countModack: 5229 countPublish: 4837 countStreamingPull: 0 countAck: 17109
Oct 17 15:43:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:43:09 INFO startup-script: ~ INFO -- count received last minute -- count="130960"
Oct 17 15:44:09 INFO startup-script: WITH RETRIES: countRecv 4756 countModack: 5204 countPublish: 4692 countStreamingPull: 0 countAck: 17170
Oct 17 15:44:09 INFO startup-script: WITHOUT RETRIES: countRecv 4756 countModack: 5204 countPublish: 4692 countStreamingPull: 0 countAck: 17170
Oct 17 15:44:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:44:09 INFO startup-script: ~ INFO -- count received last minute -- count="130765"
Oct 17 15:45:09 INFO startup-script: WITH RETRIES: countRecv 4341 countModack: 4721 countPublish: 4158 countStreamingPull: 0 countAck: 13203
Oct 17 15:45:09 INFO startup-script: WITHOUT RETRIES: countRecv 4341 countModack: 4721 countPublish: 4158 countStreamingPull: 0 countAck: 13203
Oct 17 15:45:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:45:09 INFO startup-script: ~ INFO -- count received last minute -- count="117770"
Oct 17 15:46:09 INFO startup-script: WITH RETRIES: countRecv 4684 countModack: 5157 countPublish: 4310 countStreamingPull: 0 countAck: 16221
Oct 17 15:46:09 INFO startup-script: WITHOUT RETRIES: countRecv 4684 countModack: 5157 countPublish: 4310 countStreamingPull: 0 countAck: 16221
Oct 17 15:46:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:46:09 INFO startup-script: ~ INFO -- count received last minute -- count="128024"
Oct 17 15:47:09 INFO startup-script: WITH RETRIES: countRecv 5131 countModack: 5548 countPublish: 4954 countStreamingPull: 0 countAck: 20397
Oct 17 15:47:09 INFO startup-script: WITHOUT RETRIES: countRecv 5131 countModack: 5548 countPublish: 4954 countStreamingPull: 0 countAck: 20397
Oct 17 15:47:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:47:09 INFO startup-script: ~ INFO -- count received last minute -- count="139731"
Oct 17 15:48:09 INFO startup-script: WITH RETRIES: countRecv 4931 countModack: 5437 countPublish: 4888 countStreamingPull: 0 countAck: 16907
Oct 17 15:48:09 INFO startup-script: WITHOUT RETRIES: countRecv 4931 countModack: 5437 countPublish: 4888 countStreamingPull: 0 countAck: 16907
Oct 17 15:48:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:48:09 INFO startup-script: ~ INFO -- count received last minute -- count="135370"
Oct 17 15:49:09 INFO startup-script: WITH RETRIES: countRecv 4607 countModack: 5008 countPublish: 4243 countStreamingPull: 0 countAck: 15113
Oct 17 15:49:09 INFO startup-script: WITHOUT RETRIES: countRecv 4607 countModack: 5008 countPublish: 4243 countStreamingPull: 0 countAck: 15113
Oct 17 15:49:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:49:09 INFO startup-script: ~ INFO -- count received last minute -- count="126019"
Oct 17 15:50:09 INFO startup-script: WITH RETRIES: countRecv 4693 countModack: 5134 countPublish: 4246 countStreamingPull: 0 countAck: 16110
Oct 17 15:50:09 INFO startup-script: WITHOUT RETRIES: countRecv 4693 countModack: 5134 countPublish: 4246 countStreamingPull: 0 countAck: 16110
Oct 17 15:50:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:50:09 INFO startup-script: ~ INFO -- count received last minute -- count="128291"
Oct 17 15:51:09 INFO startup-script: WITH RETRIES: countRecv 4757 countModack: 5185 countPublish: 4438 countStreamingPull: 0 countAck: 16554
Oct 17 15:51:09 INFO startup-script: WITHOUT RETRIES: countRecv 4757 countModack: 5185 countPublish: 4438 countStreamingPull: 0 countAck: 16554
Oct 17 15:51:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:51:09 INFO startup-script: ~ INFO -- count received last minute -- count="130124"
Oct 17 15:52:09 INFO startup-script: WITH RETRIES: countRecv 5172 countModack: 5600 countPublish: 4865 countStreamingPull: 0 countAck: 19636
Oct 17 15:52:09 INFO startup-script: WITHOUT RETRIES: countRecv 5172 countModack: 5600 countPublish: 4865 countStreamingPull: 0 countAck: 19636
Oct 17 15:52:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:52:09 INFO startup-script: ~ INFO -- count received last minute -- count="141131"
Oct 17 15:53:09 INFO startup-script: WITH RETRIES: countRecv 5283 countModack: 5763 countPublish: 5376 countStreamingPull: 0 countAck: 21138
Oct 17 15:53:09 INFO startup-script: WITHOUT RETRIES: countRecv 5283 countModack: 5763 countPublish: 5376 countStreamingPull: 0 countAck: 21138
Oct 17 15:53:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:53:09 INFO startup-script: ~ INFO -- count received last minute -- count="144966"
Oct 17 15:54:09 INFO startup-script: WITH RETRIES: countRecv 4787 countModack: 5220 countPublish: 4714 countStreamingPull: 1 countAck: 16616
Oct 17 15:54:09 INFO startup-script: WITHOUT RETRIES: countRecv 4787 countModack: 5220 countPublish: 4714 countStreamingPull: 1 countAck: 16616
Oct 17 15:54:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:54:09 INFO startup-script: ~ INFO -- count received last minute -- count="131482"
Oct 17 15:55:09 INFO startup-script: WITH RETRIES: countRecv 4992 countModack: 5451 countPublish: 4762 countStreamingPull: 25 countAck: 18208
Oct 17 15:55:09 INFO startup-script: WITHOUT RETRIES: countRecv 4992 countModack: 5451 countPublish: 4762 countStreamingPull: 25 countAck: 18208
Oct 17 15:55:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:55:09 INFO startup-script: ~ INFO -- count received last minute -- count="137256"
Oct 17 15:56:09 INFO startup-script: WITH RETRIES: countRecv 3426 countModack: 3658 countPublish: 1921 countStreamingPull: 11 countAck: 5827
Oct 17 15:56:09 INFO startup-script: WITHOUT RETRIES: countRecv 3426 countModack: 3658 countPublish: 1921 countStreamingPull: 11 countAck: 5827
Oct 17 15:56:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:56:09 INFO startup-script: ~ INFO -- count received last minute -- count="93878"
Oct 17 15:57:09 INFO startup-script: WITH RETRIES: countRecv 1126 countModack: 1089 countPublish: 2 countStreamingPull: 3 countAck: 0
Oct 17 15:57:09 INFO startup-script: WITHOUT RETRIES: countRecv 1126 countModack: 1089 countPublish: 2 countStreamingPull: 3 countAck: 0
Oct 17 15:57:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:57:09 INFO startup-script: ~ INFO -- count received last minute -- count="30803"
Oct 17 15:58:09 INFO startup-script: WITH RETRIES: countRecv 37 countModack: 35 countPublish: 1 countStreamingPull: 0 countAck: 0
Oct 17 15:58:09 INFO startup-script: WITHOUT RETRIES: countRecv 37 countModack: 35 countPublish: 1 countStreamingPull: 0 countAck: 0
Oct 17 15:58:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:58:09 INFO startup-script: ~ INFO -- count received last minute -- count="1036"
Oct 17 15:59:09 INFO startup-script: WITH RETRIES: countRecv 27 countModack: 37 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 15:59:09 INFO startup-script: WITHOUT RETRIES: countRecv 27 countModack: 37 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 15:59:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 15:59:09 INFO startup-script: ~ INFO -- count received last minute -- count="756"
Oct 17 16:00:09 INFO startup-script: WITH RETRIES: countRecv 33 countModack: 23 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 16:00:09 INFO startup-script: WITHOUT RETRIES: countRecv 33 countModack: 23 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 16:00:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:00:09 INFO startup-script: ~ INFO -- count received last minute -- count="914"
Oct 17 16:01:09 INFO startup-script: WITH RETRIES: countRecv 32 countModack: 32 countPublish: 1 countStreamingPull: 0 countAck: 0
Oct 17 16:01:09 INFO startup-script: WITHOUT RETRIES: countRecv 32 countModack: 32 countPublish: 1 countStreamingPull: 0 countAck: 0
Oct 17 16:01:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:01:09 INFO startup-script: ~ INFO -- count received last minute -- count="887"
Oct 17 16:02:09 INFO startup-script: WITH RETRIES: countRecv 35 countModack: 35 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 16:02:09 INFO startup-script: WITHOUT RETRIES: countRecv 35 countModack: 35 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 16:02:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:02:09 INFO startup-script: ~ INFO -- count received last minute -- count="954"
Oct 17 16:03:09 INFO startup-script: WITH RETRIES: countRecv 37 countModack: 37 countPublish: 1 countStreamingPull: 2 countAck: 0
Oct 17 16:03:09 INFO startup-script: WITHOUT RETRIES: countRecv 37 countModack: 37 countPublish: 1 countStreamingPull: 2 countAck: 0
Oct 17 16:03:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:03:09 INFO startup-script: ~ INFO -- count received last minute -- count="1023"
Oct 17 16:04:09 INFO startup-script: WITH RETRIES: countRecv 32 countModack: 32 countPublish: 1 countStreamingPull: 2 countAck: 0
Oct 17 16:04:09 INFO startup-script: WITHOUT RETRIES: countRecv 32 countModack: 32 countPublish: 1 countStreamingPull: 2 countAck: 0
Oct 17 16:04:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:04:09 INFO startup-script: ~ INFO -- count received last minute -- count="869"
Oct 17 16:05:09 INFO startup-script: WITH RETRIES: countRecv 38 countModack: 38 countPublish: 1 countStreamingPull: 2 countAck: 0
Oct 17 16:05:09 INFO startup-script: WITHOUT RETRIES: countRecv 38 countModack: 38 countPublish: 1 countStreamingPull: 2 countAck: 0
Oct 17 16:05:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:05:09 INFO startup-script: ~ INFO -- count received last minute -- count="1059"
Oct 17 16:06:09 INFO startup-script: WITH RETRIES: countRecv 34 countModack: 37 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 16:06:09 INFO startup-script: WITHOUT RETRIES: countRecv 34 countModack: 37 countPublish: 1 countStreamingPull: 1 countAck: 0
Oct 17 16:06:09 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:06:09 INFO startup-script: ~ INFO -- count received last minute -- count="914"
It dropped right at 3:58 PM UTC just around 60 minutes after the test started. It looks like countStreamingPull spiked (25 and then 11) right before it stopped receiving.
jameshartig
on 17 Oct 2018
I noticed with the last test above that publishes were also affected at the same time that receiving was affected.
Here's with grpc-go=0baa0671:
Oct 17 16:15:33 INFO startup-script: WITH RETRIES: countRecv 5372 countModack: 5812 countPublish: 6111 countStreamingPull: 40 countAck: 23468
Oct 17 16:15:33 INFO startup-script: WITHOUT RETRIES: countRecv 5372 countModack: 5812 countPublish: 6111 countStreamingPull: 40 countAck: 23468
Oct 17 16:15:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:15:33 INFO startup-script: ~ INFO -- count received last minute -- count="149205"
Oct 17 16:16:33 INFO startup-script: WITH RETRIES: countRecv 5488 countModack: 5968 countPublish: 5050 countStreamingPull: 0 countAck: 23998
Oct 17 16:16:33 INFO startup-script: WITHOUT RETRIES: countRecv 5488 countModack: 5968 countPublish: 5050 countStreamingPull: 0 countAck: 23998
Oct 17 16:16:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:16:33 INFO startup-script: ~ INFO -- count received last minute -- count="150088"
Oct 17 16:17:33 INFO startup-script: WITH RETRIES: countRecv 5418 countModack: 5898 countPublish: 6032 countStreamingPull: 0 countAck: 23992
Oct 17 16:17:33 INFO startup-script: WITHOUT RETRIES: countRecv 5418 countModack: 5898 countPublish: 6032 countStreamingPull: 0 countAck: 23992
Oct 17 16:17:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:17:33 INFO startup-script: ~ INFO -- count received last minute -- count="150139"
Oct 17 16:18:33 INFO startup-script: WITH RETRIES: countRecv 5438 countModack: 5918 countPublish: 5736 countStreamingPull: 0 countAck: 23992
Oct 17 16:18:33 INFO startup-script: WITHOUT RETRIES: countRecv 5438 countModack: 5918 countPublish: 5736 countStreamingPull: 0 countAck: 23992
Oct 17 16:18:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:18:33 INFO startup-script: ~ INFO -- count received last minute -- count="150132"
Oct 17 16:19:33 INFO startup-script: WITH RETRIES: countRecv 5435 countModack: 5915 countPublish: 5930 countStreamingPull: 0 countAck: 23995
Oct 17 16:19:33 INFO startup-script: WITHOUT RETRIES: countRecv 5435 countModack: 5915 countPublish: 5930 countStreamingPull: 0 countAck: 23995
Oct 17 16:19:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:19:33 INFO startup-script: ~ INFO -- count received last minute -- count="150099"
Oct 17 16:20:33 INFO startup-script: WITH RETRIES: countRecv 5445 countModack: 5924 countPublish: 5561 countStreamingPull: 0 countAck: 23990
Oct 17 16:20:33 INFO startup-script: WITHOUT RETRIES: countRecv 5445 countModack: 5925 countPublish: 5561 countStreamingPull: 0 countAck: 23990
Oct 17 16:20:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 1 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:20:33 INFO startup-script: ~ INFO -- count received last minute -- count="150219"
Oct 17 16:21:33 INFO startup-script: WITH RETRIES: countRecv 5448 countModack: 5929 countPublish: 5665 countStreamingPull: 0 countAck: 23991
Oct 17 16:21:33 INFO startup-script: WITHOUT RETRIES: countRecv 5448 countModack: 5928 countPublish: 5665 countStreamingPull: 0 countAck: 23991
Oct 17 16:21:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: -1 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:21:33 INFO startup-script: ~ INFO -- count received last minute -- count="150054"
Oct 17 16:22:33 INFO startup-script: WITH RETRIES: countRecv 5443 countModack: 5922 countPublish: 6437 countStreamingPull: 0 countAck: 23988
Oct 17 16:22:33 INFO startup-script: WITHOUT RETRIES: countRecv 5443 countModack: 5922 countPublish: 6437 countStreamingPull: 0 countAck: 23988
Oct 17 16:22:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:22:33 INFO startup-script: ~ INFO -- count received last minute -- count="150146"
Oct 17 16:23:33 INFO startup-script: WITH RETRIES: countRecv 5443 countModack: 5922 countPublish: 6235 countStreamingPull: 0 countAck: 23909
Oct 17 16:23:33 INFO startup-script: WITHOUT RETRIES: countRecv 5443 countModack: 5922 countPublish: 6235 countStreamingPull: 0 countAck: 23909
Oct 17 16:23:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:23:33 INFO startup-script: ~ INFO -- count received last minute -- count="150007"
Oct 17 16:24:33 INFO startup-script: WITH RETRIES: countRecv 5462 countModack: 5942 countPublish: 5586 countStreamingPull: 0 countAck: 23818
Oct 17 16:24:33 INFO startup-script: WITHOUT RETRIES: countRecv 5462 countModack: 5942 countPublish: 5586 countStreamingPull: 0 countAck: 23818
Oct 17 16:24:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:24:33 INFO startup-script: ~ INFO -- count received last minute -- count="150189"
Oct 17 16:25:33 INFO startup-script: WITH RETRIES: countRecv 5437 countModack: 5917 countPublish: 6427 countStreamingPull: 0 countAck: 23914
Oct 17 16:25:33 INFO startup-script: WITHOUT RETRIES: countRecv 5437 countModack: 5917 countPublish: 6427 countStreamingPull: 0 countAck: 23914
Oct 17 16:25:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:25:33 INFO startup-script: ~ INFO -- count received last minute -- count="150095"
Oct 17 16:26:33 INFO startup-script: WITH RETRIES: countRecv 5441 countModack: 5921 countPublish: 6294 countStreamingPull: 0 countAck: 23959
Oct 17 16:26:33 INFO startup-script: WITHOUT RETRIES: countRecv 5441 countModack: 5921 countPublish: 6294 countStreamingPull: 0 countAck: 23959
Oct 17 16:26:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:26:33 INFO startup-script: ~ INFO -- count received last minute -- count="150169"
Oct 17 16:27:33 INFO startup-script: WITH RETRIES: countRecv 5469 countModack: 5949 countPublish: 5585 countStreamingPull: 0 countAck: 23927
Oct 17 16:27:33 INFO startup-script: WITHOUT RETRIES: countRecv 5469 countModack: 5949 countPublish: 5585 countStreamingPull: 0 countAck: 23927
Oct 17 16:27:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:27:33 INFO startup-script: ~ INFO -- count received last minute -- count="150141"
Oct 17 16:28:33 INFO startup-script: WITH RETRIES: countRecv 5450 countModack: 5929 countPublish: 5811 countStreamingPull: 0 countAck: 23822
Oct 17 16:28:33 INFO startup-script: WITHOUT RETRIES: countRecv 5450 countModack: 5930 countPublish: 5811 countStreamingPull: 0 countAck: 23822
Oct 17 16:28:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 1 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:28:33 INFO startup-script: ~ INFO -- count received last minute -- count="150069"
Oct 17 16:29:33 INFO startup-script: WITH RETRIES: countRecv 5459 countModack: 5940 countPublish: 6273 countStreamingPull: 0 countAck: 23903
Oct 17 16:29:33 INFO startup-script: WITHOUT RETRIES: countRecv 5459 countModack: 5939 countPublish: 6273 countStreamingPull: 0 countAck: 23903
Oct 17 16:29:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: -1 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:29:33 INFO startup-script: ~ INFO -- count received last minute -- count="150181"
Oct 17 16:30:33 INFO startup-script: WITH RETRIES: countRecv 5428 countModack: 5908 countPublish: 5607 countStreamingPull: 0 countAck: 23869
Oct 17 16:30:33 INFO startup-script: WITHOUT RETRIES: countRecv 5428 countModack: 5908 countPublish: 5607 countStreamingPull: 0 countAck: 23869
Oct 17 16:30:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:30:33 INFO startup-script: ~ INFO -- count received last minute -- count="150036"
Oct 17 16:31:33 INFO startup-script: WITH RETRIES: countRecv 5468 countModack: 5948 countPublish: 5501 countStreamingPull: 0 countAck: 23748
Oct 17 16:31:33 INFO startup-script: WITHOUT RETRIES: countRecv 5468 countModack: 5948 countPublish: 5501 countStreamingPull: 0 countAck: 23748
Oct 17 16:31:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:31:33 INFO startup-script: ~ INFO -- count received last minute -- count="150092"
Oct 17 16:32:33 INFO startup-script: WITH RETRIES: countRecv 5449 countModack: 5929 countPublish: 5984 countStreamingPull: 0 countAck: 23941
Oct 17 16:32:33 INFO startup-script: WITHOUT RETRIES: countRecv 5449 countModack: 5929 countPublish: 5984 countStreamingPull: 0 countAck: 23941
Oct 17 16:32:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:32:33 INFO startup-script: ~ INFO -- count received last minute -- count="150137"
Oct 17 16:33:33 INFO startup-script: WITH RETRIES: countRecv 5410 countModack: 5884 countPublish: 4661 countStreamingPull: 0 countAck: 23435
Oct 17 16:33:33 INFO startup-script: WITHOUT RETRIES: countRecv 5410 countModack: 5884 countPublish: 4661 countStreamingPull: 0 countAck: 23435
Oct 17 16:33:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:33:33 INFO startup-script: ~ INFO -- count received last minute -- count="149088"
Oct 17 16:34:33 INFO startup-script: WITH RETRIES: countRecv 5473 countModack: 5946 countPublish: 6063 countStreamingPull: 0 countAck: 23842
Oct 17 16:34:33 INFO startup-script: WITHOUT RETRIES: countRecv 5473 countModack: 5946 countPublish: 6063 countStreamingPull: 0 countAck: 23842
Oct 17 16:34:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:34:33 INFO startup-script: ~ INFO -- count received last minute -- count="150155"
Oct 17 16:35:33 INFO startup-script: WITH RETRIES: countRecv 5371 countModack: 5858 countPublish: 5537 countStreamingPull: 0 countAck: 23592
Oct 17 16:35:33 INFO startup-script: WITHOUT RETRIES: countRecv 5371 countModack: 5858 countPublish: 5537 countStreamingPull: 0 countAck: 23592
Oct 17 16:35:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:35:33 INFO startup-script: ~ INFO -- count received last minute -- count="149392"
Oct 17 16:36:33 INFO startup-script: WITH RETRIES: countRecv 5472 countModack: 5952 countPublish: 4976 countStreamingPull: 0 countAck: 23991
Oct 17 16:36:33 INFO startup-script: WITHOUT RETRIES: countRecv 5472 countModack: 5952 countPublish: 4976 countStreamingPull: 0 countAck: 23991
Oct 17 16:36:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:36:33 INFO startup-script: ~ INFO -- count received last minute -- count="150079"
Oct 17 16:37:33 INFO startup-script: WITH RETRIES: countRecv 5488 countModack: 5966 countPublish: 5200 countStreamingPull: 0 countAck: 23926
Oct 17 16:37:33 INFO startup-script: WITHOUT RETRIES: countRecv 5488 countModack: 5966 countPublish: 5200 countStreamingPull: 0 countAck: 23926
Oct 17 16:37:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:37:33 INFO startup-script: ~ INFO -- count received last minute -- count="150055"
Oct 17 16:38:33 INFO startup-script: WITH RETRIES: countRecv 5433 countModack: 5915 countPublish: 4670 countStreamingPull: 0 countAck: 23917
Oct 17 16:38:33 INFO startup-script: WITHOUT RETRIES: countRecv 5433 countModack: 5915 countPublish: 4670 countStreamingPull: 0 countAck: 23917
Oct 17 16:38:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:38:33 INFO startup-script: ~ INFO -- count received last minute -- count="149964"
Oct 17 16:39:33 INFO startup-script: WITH RETRIES: countRecv 5432 countModack: 5912 countPublish: 4320 countStreamingPull: 0 countAck: 23978
Oct 17 16:39:33 INFO startup-script: WITHOUT RETRIES: countRecv 5432 countModack: 5912 countPublish: 4320 countStreamingPull: 0 countAck: 23978
Oct 17 16:39:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:39:33 INFO startup-script: ~ INFO -- count received last minute -- count="150164"
Oct 17 16:40:33 INFO startup-script: WITH RETRIES: countRecv 5429 countModack: 5909 countPublish: 4386 countStreamingPull: 0 countAck: 23979
Oct 17 16:40:33 INFO startup-script: WITHOUT RETRIES: countRecv 5429 countModack: 5909 countPublish: 4386 countStreamingPull: 0 countAck: 23979
Oct 17 16:40:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:40:33 INFO startup-script: ~ INFO -- count received last minute -- count="150252"
Oct 17 16:41:33 INFO startup-script: WITH RETRIES: countRecv 5460 countModack: 5940 countPublish: 4819 countStreamingPull: 0 countAck: 23896
Oct 17 16:41:33 INFO startup-script: WITHOUT RETRIES: countRecv 5460 countModack: 5940 countPublish: 4819 countStreamingPull: 0 countAck: 23896
Oct 17 16:41:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:41:33 INFO startup-script: ~ INFO -- count received last minute -- count="150180"
Oct 17 16:42:33 INFO startup-script: WITH RETRIES: countRecv 5449 countModack: 5929 countPublish: 4598 countStreamingPull: 0 countAck: 23962
Oct 17 16:42:33 INFO startup-script: WITHOUT RETRIES: countRecv 5449 countModack: 5929 countPublish: 4598 countStreamingPull: 0 countAck: 23962
Oct 17 16:42:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:42:33 INFO startup-script: ~ INFO -- count received last minute -- count="150059"
Oct 17 16:43:33 INFO startup-script: WITH RETRIES: countRecv 5431 countModack: 5910 countPublish: 5196 countStreamingPull: 0 countAck: 23992
Oct 17 16:43:33 INFO startup-script: WITHOUT RETRIES: countRecv 5431 countModack: 5910 countPublish: 5196 countStreamingPull: 0 countAck: 23992
Oct 17 16:43:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:43:33 INFO startup-script: ~ INFO -- count received last minute -- count="150175"
Oct 17 16:44:33 INFO startup-script: WITH RETRIES: countRecv 5327 countModack: 5776 countPublish: 4751 countStreamingPull: 0 countAck: 22782
Oct 17 16:44:33 INFO startup-script: WITHOUT RETRIES: countRecv 5327 countModack: 5776 countPublish: 4751 countStreamingPull: 0 countAck: 22782
Oct 17 16:44:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:44:33 INFO startup-script: ~ INFO -- count received last minute -- count="146566"
Oct 17 16:45:33 INFO startup-script: WITH RETRIES: countRecv 4811 countModack: 5299 countPublish: 4958 countStreamingPull: 0 countAck: 18754
Oct 17 16:45:33 INFO startup-script: WITHOUT RETRIES: countRecv 4811 countModack: 5299 countPublish: 4958 countStreamingPull: 0 countAck: 18754
Oct 17 16:45:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:45:33 INFO startup-script: ~ INFO -- count received last minute -- count="133237"
Oct 17 16:46:33 INFO startup-script: WITH RETRIES: countRecv 4964 countModack: 5397 countPublish: 4548 countStreamingPull: 0 countAck: 19734
Oct 17 16:46:33 INFO startup-script: WITHOUT RETRIES: countRecv 4964 countModack: 5397 countPublish: 4548 countStreamingPull: 0 countAck: 19734
Oct 17 16:46:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:46:33 INFO startup-script: ~ INFO -- count received last minute -- count="135181"
Oct 17 16:47:33 INFO startup-script: WITH RETRIES: countRecv 5352 countModack: 5831 countPublish: 5617 countStreamingPull: 0 countAck: 22928
Oct 17 16:47:33 INFO startup-script: WITHOUT RETRIES: countRecv 5352 countModack: 5831 countPublish: 5617 countStreamingPull: 0 countAck: 22928
Oct 17 16:47:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:47:33 INFO startup-script: ~ INFO -- count received last minute -- count="147798"
Oct 17 16:48:33 INFO startup-script: WITH RETRIES: countRecv 5463 countModack: 5943 countPublish: 5613 countStreamingPull: 0 countAck: 23991
Oct 17 16:48:33 INFO startup-script: WITHOUT RETRIES: countRecv 5463 countModack: 5943 countPublish: 5613 countStreamingPull: 0 countAck: 23991
Oct 17 16:48:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:48:33 INFO startup-script: ~ INFO -- count received last minute -- count="150151"
Oct 17 16:49:33 INFO startup-script: WITH RETRIES: countRecv 5421 countModack: 5901 countPublish: 5683 countStreamingPull: 1 countAck: 23980
Oct 17 16:49:33 INFO startup-script: WITHOUT RETRIES: countRecv 5421 countModack: 5901 countPublish: 5683 countStreamingPull: 1 countAck: 23980
Oct 17 16:49:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:49:33 INFO startup-script: ~ INFO -- count received last minute -- count="150183"
Oct 17 16:50:33 INFO startup-script: WITH RETRIES: countRecv 5433 countModack: 5906 countPublish: 5737 countStreamingPull: 39 countAck: 23789
Oct 17 16:50:33 INFO startup-script: WITHOUT RETRIES: countRecv 5433 countModack: 5906 countPublish: 5737 countStreamingPull: 39 countAck: 23789
Oct 17 16:50:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:50:33 INFO startup-script: ~ INFO -- count received last minute -- count="150099"
Oct 17 16:51:33 INFO startup-script: WITH RETRIES: countRecv 5441 countModack: 5921 countPublish: 5542 countStreamingPull: 0 countAck: 23997
Oct 17 16:51:33 INFO startup-script: WITHOUT RETRIES: countRecv 5441 countModack: 5921 countPublish: 5542 countStreamingPull: 0 countAck: 23997
Oct 17 16:51:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:51:33 INFO startup-script: ~ INFO -- count received last minute -- count="150132"
Oct 17 16:52:33 INFO startup-script: WITH RETRIES: countRecv 5446 countModack: 5925 countPublish: 6140 countStreamingPull: 0 countAck: 23995
Oct 17 16:52:33 INFO startup-script: WITHOUT RETRIES: countRecv 5446 countModack: 5925 countPublish: 6140 countStreamingPull: 0 countAck: 23995
Oct 17 16:52:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:52:33 INFO startup-script: ~ INFO -- count received last minute -- count="150189"
Oct 17 16:53:33 INFO startup-script: WITH RETRIES: countRecv 5425 countModack: 5906 countPublish: 5740 countStreamingPull: 0 countAck: 23989
Oct 17 16:53:33 INFO startup-script: WITHOUT RETRIES: countRecv 5425 countModack: 5906 countPublish: 5740 countStreamingPull: 0 countAck: 23989
Oct 17 16:53:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:53:33 INFO startup-script: ~ INFO -- count received last minute -- count="150246"
Oct 17 16:54:33 INFO startup-script: WITH RETRIES: countRecv 5450 countModack: 5930 countPublish: 5710 countStreamingPull: 0 countAck: 23996
Oct 17 16:54:33 INFO startup-script: WITHOUT RETRIES: countRecv 5450 countModack: 5930 countPublish: 5710 countStreamingPull: 0 countAck: 23996
Oct 17 16:54:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:54:33 INFO startup-script: ~ INFO -- count received last minute -- count="150099"
Oct 17 16:55:33 INFO startup-script: WITH RETRIES: countRecv 5424 countModack: 5904 countPublish: 5219 countStreamingPull: 0 countAck: 23992
Oct 17 16:55:33 INFO startup-script: WITHOUT RETRIES: countRecv 5424 countModack: 5904 countPublish: 5219 countStreamingPull: 0 countAck: 23992
Oct 17 16:55:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:55:33 INFO startup-script: ~ INFO -- count received last minute -- count="150188"
Oct 17 16:56:33 INFO startup-script: WITH RETRIES: countRecv 5434 countModack: 5914 countPublish: 5971 countStreamingPull: 0 countAck: 23969
Oct 17 16:56:33 INFO startup-script: WITHOUT RETRIES: countRecv 5434 countModack: 5914 countPublish: 5971 countStreamingPull: 0 countAck: 23969
Oct 17 16:56:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:56:33 INFO startup-script: ~ INFO -- count received last minute -- count="150098"
Oct 17 16:57:33 INFO startup-script: WITH RETRIES: countRecv 5427 countModack: 5907 countPublish: 6268 countStreamingPull: 0 countAck: 23990
Oct 17 16:57:33 INFO startup-script: WITHOUT RETRIES: countRecv 5427 countModack: 5907 countPublish: 6268 countStreamingPull: 0 countAck: 23990
Oct 17 16:57:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:57:33 INFO startup-script: ~ INFO -- count received last minute -- count="150157"
Oct 17 16:58:33 INFO startup-script: WITH RETRIES: countRecv 5420 countModack: 5900 countPublish: 5946 countStreamingPull: 0 countAck: 23993
Oct 17 16:58:33 INFO startup-script: WITHOUT RETRIES: countRecv 5420 countModack: 5900 countPublish: 5946 countStreamingPull: 0 countAck: 23993
Oct 17 16:58:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:58:33 INFO startup-script: ~ INFO -- count received last minute -- count="150022"
Oct 17 16:59:33 INFO startup-script: WITH RETRIES: countRecv 5456 countModack: 5936 countPublish: 5913 countStreamingPull: 0 countAck: 23993
Oct 17 16:59:33 INFO startup-script: WITHOUT RETRIES: countRecv 5456 countModack: 5936 countPublish: 5913 countStreamingPull: 0 countAck: 23993
Oct 17 16:59:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 16:59:33 INFO startup-script: ~ INFO -- count received last minute -- count="150137"
Oct 17 17:00:33 INFO startup-script: WITH RETRIES: countRecv 5434 countModack: 5914 countPublish: 5555 countStreamingPull: 0 countAck: 23994
Oct 17 17:00:33 INFO startup-script: WITHOUT RETRIES: countRecv 5434 countModack: 5914 countPublish: 5555 countStreamingPull: 0 countAck: 23994
Oct 17 17:00:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:00:33 INFO startup-script: ~ INFO -- count received last minute -- count="150069"
Oct 17 17:01:33 INFO startup-script: WITH RETRIES: countRecv 5422 countModack: 5902 countPublish: 5028 countStreamingPull: 0 countAck: 23989
Oct 17 17:01:33 INFO startup-script: WITHOUT RETRIES: countRecv 5422 countModack: 5902 countPublish: 5028 countStreamingPull: 0 countAck: 23989
Oct 17 17:01:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:01:33 INFO startup-script: ~ INFO -- count received last minute -- count="150045"
Oct 17 17:02:33 INFO startup-script: WITH RETRIES: countRecv 5429 countModack: 5909 countPublish: 3811 countStreamingPull: 0 countAck: 23995
Oct 17 17:02:33 INFO startup-script: WITHOUT RETRIES: countRecv 5429 countModack: 5909 countPublish: 3811 countStreamingPull: 0 countAck: 23995
Oct 17 17:02:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:02:33 INFO startup-script: ~ INFO -- count received last minute -- count="150090"
Oct 17 17:03:33 INFO startup-script: WITH RETRIES: countRecv 5479 countModack: 5959 countPublish: 4285 countStreamingPull: 0 countAck: 23995
Oct 17 17:03:33 INFO startup-script: WITHOUT RETRIES: countRecv 5479 countModack: 5959 countPublish: 4285 countStreamingPull: 0 countAck: 23995
Oct 17 17:03:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:03:33 INFO startup-script: ~ INFO -- count received last minute -- count="150110"
Oct 17 17:04:33 INFO startup-script: WITH RETRIES: countRecv 5325 countModack: 5745 countPublish: 3417 countStreamingPull: 0 countAck: 21806
Oct 17 17:04:33 INFO startup-script: WITHOUT RETRIES: countRecv 5325 countModack: 5745 countPublish: 3417 countStreamingPull: 0 countAck: 21806
Oct 17 17:04:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:04:33 INFO startup-script: ~ INFO -- count received last minute -- count="146458"
Oct 17 17:05:33 INFO startup-script: WITH RETRIES: countRecv 4406 countModack: 4838 countPublish: 4484 countStreamingPull: 0 countAck: 14469
Oct 17 17:05:33 INFO startup-script: WITHOUT RETRIES: countRecv 4406 countModack: 4838 countPublish: 4484 countStreamingPull: 0 countAck: 14469
Oct 17 17:05:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:05:33 INFO startup-script: ~ INFO -- count received last minute -- count="119222"
Oct 17 17:06:33 INFO startup-script: WITH RETRIES: countRecv 3973 countModack: 4433 countPublish: 3723 countStreamingPull: 0 countAck: 14083
Oct 17 17:06:33 INFO startup-script: WITHOUT RETRIES: countRecv 3973 countModack: 4433 countPublish: 3723 countStreamingPull: 0 countAck: 14083
Oct 17 17:06:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:06:33 INFO startup-script: ~ INFO -- count received last minute -- count="110122"
Oct 17 17:07:33 INFO startup-script: WITH RETRIES: countRecv 4605 countModack: 4997 countPublish: 4550 countStreamingPull: 0 countAck: 16225
Oct 17 17:07:33 INFO startup-script: WITHOUT RETRIES: countRecv 4605 countModack: 4997 countPublish: 4550 countStreamingPull: 0 countAck: 16225
Oct 17 17:07:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:07:33 INFO startup-script: ~ INFO -- count received last minute -- count="124709"
Oct 17 17:08:33 INFO startup-script: WITH RETRIES: countRecv 4608 countModack: 5024 countPublish: 4242 countStreamingPull: 0 countAck: 15885
Oct 17 17:08:33 INFO startup-script: WITHOUT RETRIES: countRecv 4608 countModack: 5024 countPublish: 4242 countStreamingPull: 0 countAck: 15885
Oct 17 17:08:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:08:33 INFO startup-script: ~ INFO -- count received last minute -- count="125016"
Oct 17 17:09:33 INFO startup-script: WITH RETRIES: countRecv 3961 countModack: 4370 countPublish: 3649 countStreamingPull: 0 countAck: 13109
Oct 17 17:09:33 INFO startup-script: WITHOUT RETRIES: countRecv 3961 countModack: 4370 countPublish: 3649 countStreamingPull: 0 countAck: 13109
Oct 17 17:09:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:09:33 INFO startup-script: ~ INFO -- count received last minute -- count="108695"
Oct 17 17:10:33 INFO startup-script: WITH RETRIES: countRecv 4381 countModack: 4804 countPublish: 4318 countStreamingPull: 0 countAck: 14508
Oct 17 17:10:33 INFO startup-script: WITHOUT RETRIES: countRecv 4381 countModack: 4804 countPublish: 4318 countStreamingPull: 0 countAck: 14508
Oct 17 17:10:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:10:33 INFO startup-script: ~ INFO -- count received last minute -- count="120135"
Oct 17 17:11:33 INFO startup-script: WITH RETRIES: countRecv 4425 countModack: 4822 countPublish: 4138 countStreamingPull: 0 countAck: 14668
Oct 17 17:11:33 INFO startup-script: WITHOUT RETRIES: countRecv 4425 countModack: 4822 countPublish: 4138 countStreamingPull: 0 countAck: 14668
Oct 17 17:11:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:11:33 INFO startup-script: ~ INFO -- count received last minute -- count="119916"
Oct 17 17:12:33 INFO startup-script: WITH RETRIES: countRecv 4110 countModack: 4517 countPublish: 4100 countStreamingPull: 0 countAck: 13175
Oct 17 17:12:33 INFO startup-script: WITHOUT RETRIES: countRecv 4110 countModack: 4517 countPublish: 4100 countStreamingPull: 0 countAck: 13175
Oct 17 17:12:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:12:33 INFO startup-script: ~ INFO -- count received last minute -- count="112724"
Oct 17 17:13:33 INFO startup-script: WITH RETRIES: countRecv 4241 countModack: 4642 countPublish: 4375 countStreamingPull: 0 countAck: 13554
Oct 17 17:13:33 INFO startup-script: WITHOUT RETRIES: countRecv 4241 countModack: 4642 countPublish: 4375 countStreamingPull: 0 countAck: 13554
Oct 17 17:13:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:13:33 INFO startup-script: ~ INFO -- count received last minute -- count="115113"
Oct 17 17:14:33 INFO startup-script: WITH RETRIES: countRecv 4674 countModack: 5112 countPublish: 4534 countStreamingPull: 0 countAck: 17042
Oct 17 17:14:33 INFO startup-script: WITHOUT RETRIES: countRecv 4674 countModack: 5112 countPublish: 4534 countStreamingPull: 0 countAck: 17042
Oct 17 17:14:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:14:33 INFO startup-script: ~ INFO -- count received last minute -- count="126950"
Oct 17 17:15:33 INFO startup-script: WITH RETRIES: countRecv 3955 countModack: 4286 countPublish: 4346 countStreamingPull: 0 countAck: 13181
Oct 17 17:15:33 INFO startup-script: WITHOUT RETRIES: countRecv 3955 countModack: 4286 countPublish: 4346 countStreamingPull: 0 countAck: 13181
Oct 17 17:15:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:15:33 INFO startup-script: ~ INFO -- count received last minute -- count="108249"
Oct 17 17:16:33 INFO startup-script: WITH RETRIES: countRecv 3096 countModack: 3445 countPublish: 3349 countStreamingPull: 0 countAck: 9192
Oct 17 17:16:33 INFO startup-script: WITHOUT RETRIES: countRecv 3096 countModack: 3445 countPublish: 3349 countStreamingPull: 0 countAck: 9192
Oct 17 17:16:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:16:33 INFO startup-script: ~ INFO -- count received last minute -- count="85736"
Oct 17 17:17:33 INFO startup-script: WITH RETRIES: countRecv 3387 countModack: 3726 countPublish: 3667 countStreamingPull: 0 countAck: 9977
Oct 17 17:17:33 INFO startup-script: WITHOUT RETRIES: countRecv 3387 countModack: 3726 countPublish: 3667 countStreamingPull: 0 countAck: 9977
Oct 17 17:17:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:17:33 INFO startup-script: ~ INFO -- count received last minute -- count="93244"
Oct 17 17:18:33 INFO startup-script: WITH RETRIES: countRecv 5150 countModack: 5654 countPublish: 4308 countStreamingPull: 0 countAck: 22646
Oct 17 17:18:33 INFO startup-script: WITHOUT RETRIES: countRecv 5150 countModack: 5654 countPublish: 4308 countStreamingPull: 0 countAck: 22646
Oct 17 17:18:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:18:33 INFO startup-script: ~ INFO -- count received last minute -- count="142947"
Oct 17 17:19:33 INFO startup-script: WITH RETRIES: countRecv 5480 countModack: 5960 countPublish: 4689 countStreamingPull: 0 countAck: 23991
Oct 17 17:19:33 INFO startup-script: WITHOUT RETRIES: countRecv 5480 countModack: 5960 countPublish: 4689 countStreamingPull: 0 countAck: 23991
Oct 17 17:19:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:19:33 INFO startup-script: ~ INFO -- count received last minute -- count="150152"
Oct 17 17:20:33 INFO startup-script: WITH RETRIES: countRecv 5159 countModack: 5616 countPublish: 4838 countStreamingPull: 0 countAck: 21102
Oct 17 17:20:33 INFO startup-script: WITHOUT RETRIES: countRecv 5159 countModack: 5616 countPublish: 4838 countStreamingPull: 0 countAck: 21102
Oct 17 17:20:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:20:33 INFO startup-script: ~ INFO -- count received last minute -- count="141128"
Oct 17 17:21:33 INFO startup-script: WITH RETRIES: countRecv 5164 countModack: 5659 countPublish: 5191 countStreamingPull: 0 countAck: 20952
Oct 17 17:21:33 INFO startup-script: WITHOUT RETRIES: countRecv 5164 countModack: 5659 countPublish: 5191 countStreamingPull: 0 countAck: 20952
Oct 17 17:21:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:21:33 INFO startup-script: ~ INFO -- count received last minute -- count="141722"
Oct 17 17:22:33 INFO startup-script: WITH RETRIES: countRecv 4864 countModack: 5328 countPublish: 4396 countStreamingPull: 0 countAck: 19811
Oct 17 17:22:33 INFO startup-script: WITHOUT RETRIES: countRecv 4864 countModack: 5328 countPublish: 4397 countStreamingPull: 0 countAck: 19811
Oct 17 17:22:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 1 countStreamingPull: 0 countAck: 0
Oct 17 17:22:33 INFO startup-script: ~ INFO -- count received last minute -- count="134035"
Oct 17 17:23:33 INFO startup-script: WITH RETRIES: countRecv 3906 countModack: 4235 countPublish: 3326 countStreamingPull: 0 countAck: 13601
Oct 17 17:23:33 INFO startup-script: WITHOUT RETRIES: countRecv 3906 countModack: 4235 countPublish: 3325 countStreamingPull: 0 countAck: 13601
Oct 17 17:23:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: -1 countStreamingPull: 0 countAck: 0
Oct 17 17:23:33 INFO startup-script: ~ INFO -- count received last minute -- count="106413"
Oct 17 17:24:33 INFO startup-script: WITH RETRIES: countRecv 4958 countModack: 5397 countPublish: 4557 countStreamingPull: 1 countAck: 19490
Oct 17 17:24:33 INFO startup-script: WITHOUT RETRIES: countRecv 4958 countModack: 5397 countPublish: 4557 countStreamingPull: 1 countAck: 19490
Oct 17 17:24:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:24:33 INFO startup-script: ~ INFO -- count received last minute -- count="135832"
Oct 17 17:25:33 INFO startup-script: WITH RETRIES: countRecv 4686 countModack: 5124 countPublish: 4678 countStreamingPull: 39 countAck: 16813
Oct 17 17:25:33 INFO startup-script: WITHOUT RETRIES: countRecv 4686 countModack: 5124 countPublish: 4678 countStreamingPull: 39 countAck: 16813
Oct 17 17:25:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:25:33 INFO startup-script: ~ INFO -- count received last minute -- count="127766"
Oct 17 17:26:33 INFO startup-script: WITH RETRIES: countRecv 5302 countModack: 5799 countPublish: 5461 countStreamingPull: 0 countAck: 22110
Oct 17 17:26:33 INFO startup-script: WITHOUT RETRIES: countRecv 5302 countModack: 5799 countPublish: 5461 countStreamingPull: 0 countAck: 22110
Oct 17 17:26:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:26:33 INFO startup-script: ~ INFO -- count received last minute -- count="145811"
Oct 17 17:27:33 INFO startup-script: WITH RETRIES: countRecv 5283 countModack: 5750 countPublish: 4784 countStreamingPull: 0 countAck: 21721
Oct 17 17:27:33 INFO startup-script: WITHOUT RETRIES: countRecv 5283 countModack: 5750 countPublish: 4784 countStreamingPull: 0 countAck: 21721
Oct 17 17:27:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:27:33 INFO startup-script: ~ INFO -- count received last minute -- count="143805"
Oct 17 17:28:33 INFO startup-script: WITH RETRIES: countRecv 4535 countModack: 4982 countPublish: 4246 countStreamingPull: 0 countAck: 17055
Oct 17 17:28:33 INFO startup-script: WITHOUT RETRIES: countRecv 4535 countModack: 4982 countPublish: 4246 countStreamingPull: 0 countAck: 17055
Oct 17 17:28:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:28:33 INFO startup-script: ~ INFO -- count received last minute -- count="123429"
Oct 17 17:29:33 INFO startup-script: WITH RETRIES: countRecv 4622 countModack: 4996 countPublish: 4906 countStreamingPull: 0 countAck: 16352
Oct 17 17:29:33 INFO startup-script: WITHOUT RETRIES: countRecv 4622 countModack: 4996 countPublish: 4906 countStreamingPull: 0 countAck: 16352
Oct 17 17:29:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:29:33 INFO startup-script: ~ INFO -- count received last minute -- count="126048"
Oct 17 17:30:33 INFO startup-script: WITH RETRIES: countRecv 4679 countModack: 5115 countPublish: 4587 countStreamingPull: 0 countAck: 16487
Oct 17 17:30:33 INFO startup-script: WITHOUT RETRIES: countRecv 4679 countModack: 5115 countPublish: 4587 countStreamingPull: 0 countAck: 16487
Oct 17 17:30:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:30:33 INFO startup-script: ~ INFO -- count received last minute -- count="126578"
Oct 17 17:31:33 INFO startup-script: WITH RETRIES: countRecv 5121 countModack: 5636 countPublish: 5256 countStreamingPull: 0 countAck: 20096
Oct 17 17:31:33 INFO startup-script: WITHOUT RETRIES: countRecv 5121 countModack: 5637 countPublish: 5256 countStreamingPull: 0 countAck: 20096
Oct 17 17:31:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 1 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:31:33 INFO startup-script: ~ INFO -- count received last minute -- count="141376"
Oct 17 17:32:33 INFO startup-script: WITH RETRIES: countRecv 4977 countModack: 5424 countPublish: 4943 countStreamingPull: 0 countAck: 20119
Oct 17 17:32:33 INFO startup-script: WITHOUT RETRIES: countRecv 4977 countModack: 5423 countPublish: 4943 countStreamingPull: 0 countAck: 20119
Oct 17 17:32:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: -1 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:32:33 INFO startup-script: ~ INFO -- count received last minute -- count="135900"
Oct 17 17:33:33 INFO startup-script: WITH RETRIES: countRecv 5130 countModack: 5585 countPublish: 5160 countStreamingPull: 0 countAck: 20736
Oct 17 17:33:33 INFO startup-script: WITHOUT RETRIES: countRecv 5130 countModack: 5585 countPublish: 5160 countStreamingPull: 0 countAck: 20736
Oct 17 17:33:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:33:33 INFO startup-script: ~ INFO -- count received last minute -- count="140311"
Oct 17 17:34:33 INFO startup-script: WITH RETRIES: countRecv 4993 countModack: 5444 countPublish: 4970 countStreamingPull: 0 countAck: 19227
Oct 17 17:34:33 INFO startup-script: WITHOUT RETRIES: countRecv 4993 countModack: 5444 countPublish: 4970 countStreamingPull: 0 countAck: 19227
Oct 17 17:34:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:34:33 INFO startup-script: ~ INFO -- count received last minute -- count="134427"
Oct 17 17:35:33 INFO startup-script: WITH RETRIES: countRecv 5076 countModack: 5519 countPublish: 5141 countStreamingPull: 0 countAck: 20050
Oct 17 17:35:33 INFO startup-script: WITHOUT RETRIES: countRecv 5076 countModack: 5519 countPublish: 5141 countStreamingPull: 0 countAck: 20050
Oct 17 17:35:33 INFO startup-script: NUM RETRIES: countRecv 0 countModack: 0 countPublish: 0 countStreamingPull: 0 countAck: 0
Oct 17 17:35:33 INFO startup-script: ~ INFO -- count received last minute -- count="138644"
I stopped it after 80 minutes because it wasn't showing any signs of slowing down.
jameshartig
on 17 Oct 2018
Thanks. This is valuable information. Here's a graph of those two for posterity:
(edit: the commit SHAs are off in this diagram, but the data is good)
The newer code seems less consistently smooth than the old, but that's a weak signal [1]. For next steps, here's what I'd like to suggest:
Long shot: we've recently made changes in google-api-go-client and grpc-go. Could you try with
google-api-go-client=HEAD,google-cloud-go=HEAD,grpc-go=HEADto see if any of those changes have made a difference? It's a shot in the dark, but worth looking at.I've created a branch of
grpc-gothat has much better logging available, which will help us figure this out in lieu of being able to reproduce the issue ourselves. This may be merged into master soon, but for now could you try:- Pulling
https://github.com/jadekler/grpc-go.gitat branchlog_connectivity_transitions. - Set
export GRPC_GO_LOG_VERBOSITY_LEVEL=99andexport GRPC_GO_LOG_SEVERITY_LEVEL=info - Gathering a dump of the logs around the time of the performance degradation to send to us
- Pulling
Could you take a look at Quotas page for Pub/Sub and describe if you're seeing any quota hits? I'm waiting on a TSE to do this for us, but you may be a bit quicker heh. The page should be found at APIs And Services > Dashboard > Cloud Pub/Sub API > Quotas.
Thanks for your continued help, we much appreciate it.
1: We have internal performance benchmarks that run continuously, and they show no change. This is likely just network jitter: note that the "old" line is smooth only 2/3 the time, and equally jagged the last third.
jadekler
on 19 Oct 2018
@jadekler The newer commit dropped at 3:58 PM UTC from over 100k a minute to less than 1,000 per minute and the topic was backing up. I think that's represented in your graph as it going to 0? It's definitely not much different until the point at which it seems to just completely fail and barely receive any messages. It also fails to publish messages as fast. You'll notice the countPublish count dropped as well. Sorry if I didn't make that clear.
To clarify, I'm not worried about the jitter and relatively similar performance in the beginning. Something happens with the new code after an hour and it just stops doing anything and that's the part I'm concerned about. You'll see in the graphs around the 60 minute mark and the red line is what the issue is.
I'll start a test with your logging branch and HEAD of everything else and I'll post the results.
Regarding the quotas, I don't see any that have been hit in the last 7 days. Are there any internal quotas that are not available for me to see?
jameshartig
on 19 Oct 2018
Yeah, the graphs that @jadekler posted show exactly the problem. The smoothness is a bit of a problem, but the sharp drop-off is the major issue.
dsymonds
on 19 Oct 2018
👍1
Right, yes, absolutely the drop is the problem. I neglected to mention that because there's not much to say about it that hasn't been said, but I should have, in hindsight. The jitter was new information, so I thought it would be good to briefly comment on; but, as mentioned, it's probably nothing.
I still have no idea what causes the drop-off, but loosely speaking I'm looking for:
- Ways that we might be being more chatty than before, causing an anti-DOS response from the GFE.
- Ways that we might be handling connections incorrectly. (the branch I asked you to try has instrumentation around that)
Regarding the quotas, I don't see any that have been hit in the last 7 days. Are there any internal quotas that are not available for me to see?
Not that I'm aware of, but I'm still waiting for a response from the Pub/Sub SREs.
jadekler
on 19 Oct 2018
Ah okay! Just wanted to make sure I wasn't being misunderstood!
Hopefully this helps:
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 parsed scheme: ""
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 scheme "" not registered, fallback to default scheme
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 ccResolverWrapper: sending new addresses to cc: [{pubsub.googleapis.com:443 0 <nil>}]
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 balancerWrapper: got update addr from Notify: [{pubsub.googleapis.com:443 0} {pubsub.googleapis.com:443 1} {pubsub.googleapis.com:443 2} {pubsub.googleapis.com:443 3}]
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: CONNECTING
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: CONNECTING
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: CONNECTING
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: CONNECTING
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: READY
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: READY
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: READY
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 1}]: server preface received
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 0}]: server preface received
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 2}]: server preface received
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: READY
Oct 18 23:31:40 INFO startup-script: INFO: 2018/10/18 23:31:40 [{pubsub.googleapis.com:443 0 3}]: server preface received
Oct 18 23:32:40 INFO startup-script: ~ INFO -- count received last minute -- count="138493"
Oct 18 23:33:40 INFO startup-script: ~ INFO -- count received last minute -- count="132874"
Oct 18 23:34:40 INFO startup-script: ~ INFO -- count received last minute -- count="145283"
Oct 18 23:35:40 INFO startup-script: ~ INFO -- count received last minute -- count="143396"
Oct 18 23:36:40 INFO startup-script: ~ INFO -- count received last minute -- count="150037"
Oct 18 23:37:40 INFO startup-script: ~ INFO -- count received last minute -- count="134866"
Oct 18 23:38:40 INFO startup-script: ~ INFO -- count received last minute -- count="150169"
Oct 18 23:39:40 INFO startup-script: ~ INFO -- count received last minute -- count="150096"
Oct 18 23:40:40 INFO startup-script: ~ INFO -- count received last minute -- count="150051"
Oct 18 23:41:40 INFO startup-script: ~ INFO -- count received last minute -- count="150095"
Oct 18 23:42:40 INFO startup-script: ~ INFO -- count received last minute -- count="150128"
Oct 18 23:43:40 INFO startup-script: ~ INFO -- count received last minute -- count="150205"
Oct 18 23:44:40 INFO startup-script: ~ INFO -- count received last minute -- count="150160"
Oct 18 23:45:40 INFO startup-script: ~ INFO -- count received last minute -- count="150114"
Oct 18 23:46:40 INFO startup-script: ~ INFO -- count received last minute -- count="150125"
Oct 18 23:47:40 INFO startup-script: ~ INFO -- count received last minute -- count="150090"
Oct 18 23:48:40 INFO startup-script: ~ INFO -- count received last minute -- count="150096"
Oct 18 23:49:40 INFO startup-script: ~ INFO -- count received last minute -- count="150124"
Oct 18 23:50:40 INFO startup-script: ~ INFO -- count received last minute -- count="150135"
Oct 18 23:51:40 INFO startup-script: ~ INFO -- count received last minute -- count="150160"
Oct 18 23:52:40 INFO startup-script: ~ INFO -- count received last minute -- count="150083"
Oct 18 23:53:40 INFO startup-script: ~ INFO -- count received last minute -- count="150078"
Oct 18 23:54:40 INFO startup-script: ~ INFO -- count received last minute -- count="150111"
Oct 18 23:55:40 INFO startup-script: ~ INFO -- count received last minute -- count="149939"
Oct 18 23:56:40 INFO startup-script: ~ INFO -- count received last minute -- count="150155"
Oct 18 23:57:40 INFO startup-script: ~ INFO -- count received last minute -- count="150200"
Oct 18 23:58:40 INFO startup-script: ~ INFO -- count received last minute -- count="150198"
Oct 18 23:59:40 INFO startup-script: ~ INFO -- count received last minute -- count="150133"
Oct 19 00:00:40 INFO startup-script: ~ INFO -- count received last minute -- count="150116"
Oct 19 00:01:40 INFO startup-script: ~ INFO -- count received last minute -- count="150146"
Oct 19 00:02:40 INFO startup-script: ~ INFO -- count received last minute -- count="150076"
Oct 19 00:03:40 INFO startup-script: ~ INFO -- count received last minute -- count="150153"
Oct 19 00:04:40 INFO startup-script: ~ INFO -- count received last minute -- count="150184"
Oct 19 00:05:40 INFO startup-script: ~ INFO -- count received last minute -- count="150144"
Oct 19 00:06:40 INFO startup-script: ~ INFO -- count received last minute -- count="150209"
Oct 19 00:07:40 INFO startup-script: ~ INFO -- count received last minute -- count="150141"
Oct 19 00:08:40 INFO startup-script: ~ INFO -- count received last minute -- count="150138"
Oct 19 00:09:40 INFO startup-script: ~ INFO -- count received last minute -- count="150183"
Oct 19 00:10:40 INFO startup-script: ~ INFO -- count received last minute -- count="150256"
Oct 19 00:11:40 INFO startup-script: ~ INFO -- count received last minute -- count="150087"
Oct 19 00:12:40 INFO startup-script: ~ INFO -- count received last minute -- count="150216"
Oct 19 00:13:40 INFO startup-script: ~ INFO -- count received last minute -- count="147759"
Oct 19 00:14:40 INFO startup-script: ~ INFO -- count received last minute -- count="145305"
Oct 19 00:15:40 INFO startup-script: ~ INFO -- count received last minute -- count="136578"
Oct 19 00:16:40 INFO startup-script: ~ INFO -- count received last minute -- count="144248"
Oct 19 00:17:40 INFO startup-script: ~ INFO -- count received last minute -- count="148786"
Oct 19 00:18:40 INFO startup-script: ~ INFO -- count received last minute -- count="150097"
Oct 19 00:19:40 INFO startup-script: ~ INFO -- count received last minute -- count="150113"
Oct 19 00:20:40 INFO startup-script: ~ INFO -- count received last minute -- count="150102"
Oct 19 00:21:40 INFO startup-script: ~ INFO -- count received last minute -- count="150095"
Oct 19 00:22:40 INFO startup-script: ~ INFO -- count received last minute -- count="150159"
Oct 19 00:23:40 INFO startup-script: ~ INFO -- count received last minute -- count="150015"
Oct 19 00:24:40 INFO startup-script: ~ INFO -- count received last minute -- count="150184"
Oct 19 00:25:40 INFO startup-script: ~ INFO -- count received last minute -- count="150178"
Oct 19 00:26:40 INFO startup-script: ~ INFO -- count received last minute -- count="150057"
Oct 19 00:27:40 INFO startup-script: ~ INFO -- count received last minute -- count="150150"
Oct 19 00:28:40 INFO startup-script: ~ INFO -- count received last minute -- count="150147"
Oct 19 00:29:40 INFO startup-script: ~ INFO -- count received last minute -- count="150140"
Oct 19 00:30:40 INFO startup-script: ~ INFO -- count received last minute -- count="150198"
Oct 19 00:31:36 INFO startup-script: INFO: 2018/10/19 00:31:36 [{pubsub.googleapis.com:443 0 2}]: onGoAway received
Oct 19 00:31:36 INFO startup-script: INFO: 2018/10/19 00:31:36 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 00:31:36 INFO startup-script: INFO: 2018/10/19 00:31:36 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: CONNECTING
Oct 19 00:31:36 INFO startup-script: INFO: 2018/10/19 00:31:36 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: READY
Oct 19 00:31:36 INFO startup-script: INFO: 2018/10/19 00:31:36 [{pubsub.googleapis.com:443 0 2}]: server preface received
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 0}]: onGoAway received
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: CONNECTING
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 1}]: onGoAway received
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: CONNECTING
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 3}]: onGoAway received
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: CONNECTING
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: READY
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 3}]: server preface received
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: READY
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 1}]: server preface received
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: READY
Oct 19 00:31:40 INFO startup-script: INFO: 2018/10/19 00:31:40 [{pubsub.googleapis.com:443 0 0}]: server preface received
Oct 19 00:31:40 INFO startup-script: ~ INFO -- count received last minute -- count="150145"
Oct 19 00:32:40 INFO startup-script: ~ INFO -- count received last minute -- count="150008"
Oct 19 00:33:40 INFO startup-script: ~ INFO -- count received last minute -- count="150192"
Oct 19 00:34:40 INFO startup-script: ~ INFO -- count received last minute -- count="150128"
Oct 19 00:35:40 INFO startup-script: ~ INFO -- count received last minute -- count="150143"
Oct 19 00:36:40 INFO startup-script: ~ INFO -- count received last minute -- count="150153"
Oct 19 00:37:40 INFO startup-script: ~ INFO -- count received last minute -- count="150161"
Oct 19 00:38:40 INFO startup-script: ~ INFO -- count received last minute -- count="150134"
Oct 19 00:39:40 INFO startup-script: ~ INFO -- count received last minute -- count="150092"
Oct 19 00:40:40 INFO startup-script: ~ INFO -- count received last minute -- count="150067"
Oct 19 00:41:40 INFO startup-script: ~ INFO -- count received last minute -- count="150057"
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 [{pubsub.googleapis.com:443 0 3}]: onClose received
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:29 INFO startup-script: INFO: 2018/10/19 00:42:29 blockingPicker: the picked transport is not ready, loop back to repick
...
Oct 19 00:42:40 INFO startup-script: ~ INFO -- count received last minute -- count="144448"
Oct 19 00:42:40 INFO startup-script: INFO: 2018/10/19 00:42:40 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:40 INFO startup-script: INFO: 2018/10/19 00:42:40 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:42:40 INFO startup-script: INFO: 2018/10/19 00:42:40 blockingPicker: the picked transport is not ready, loop back to repick
...
Oct 19 00:42:41 INFO startup-script: INFO: 2018/10/19 00:42:41 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
Oct 19 00:42:41 INFO startup-script: INFO: 2018/10/19 00:42:41 [{pubsub.googleapis.com:443 0 1}]: onClose received
Oct 19 00:42:41 INFO startup-script: INFO: 2018/10/19 00:42:41 blockingPicker: the picked transport is not ready, loop back to repick
...
Oct 19 00:43:29 INFO startup-script: ~ WARN -- error publishing -- err="context deadline exceeded"
Oct 19 00:43:29 INFO startup-script: ~ WARN -- error publishing -- err="context deadline exceeded"
Oct 19 00:43:29 INFO startup-script: ~ WARN -- error publishing -- err="context deadline exceeded"
...
Oct 19 00:43:29 INFO startup-script: INFO: 2018/10/19 00:43:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:29 INFO startup-script: INFO: 2018/10/19 00:43:29 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:29 INFO startup-script: INFO: 2018/10/19 00:43:29 blockingPicker: the picked transport is not ready, loop back to repick
...
Oct 19 00:43:40 INFO startup-script: ~ INFO -- count received last minute -- count="61037"
Oct 19 00:43:40 INFO startup-script: INFO: 2018/10/19 00:43:40 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:40 INFO startup-script: INFO: 2018/10/19 00:43:40 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:40 INFO startup-script: INFO: 2018/10/19 00:43:40 blockingPicker: the picked transport is not ready, loop back to repick
...
Oct 19 00:43:55 INFO startup-script: INFO: 2018/10/19 00:43:55 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
Oct 19 00:43:55 INFO startup-script: INFO: 2018/10/19 00:43:55 [{pubsub.googleapis.com:443 0 2}]: onClose received
...
Oct 19 00:43:55 INFO startup-script: INFO: 2018/10/19 00:43:55 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:55 INFO startup-script: INFO: 2018/10/19 00:43:55 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:55 INFO startup-script: INFO: 2018/10/19 00:43:55 blockingPicker: the picked transport is not ready, loop back to repick
...
Oct 19 00:43:58 INFO startup-script: INFO: 2018/10/19 00:43:58 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
Oct 19 00:43:58 INFO startup-script: INFO: 2018/10/19 00:43:58 [{pubsub.googleapis.com:443 0 0}]: onClose received
...
Oct 19 00:43:58 INFO startup-script: INFO: 2018/10/19 00:43:58 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:58 INFO startup-script: INFO: 2018/10/19 00:43:58 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 00:43:58 INFO startup-script: INFO: 2018/10/19 00:43:58 blockingPicker: the picked transport is not ready, loop back to repick
...
I deduplicated where the logs were the same log was on every line (denoted with ...) to not paste a massive dump into the comment but essentially that one blockingPicker error was happening tons of times a second. The full log is available: https://gobin.io/SClB
Update: Forgot to paste the logs from the beginning. Updated the snippet above with the logs from the start of the script.
jameshartig
on 19 Oct 2018
This is very, very useful. Thank you. We'll pore over this tomorrow. I presume these logs are around the time that you experienced the drop?
jadekler
on 19 Oct 2018
Yup! To make it easier, here are just the counts:
Oct 19 00:39:40 INFO startup-script: ~ INFO -- count received last minute -- count="150092"
Oct 19 00:40:40 INFO startup-script: ~ INFO -- count received last minute -- count="150067"
Oct 19 00:41:40 INFO startup-script: ~ INFO -- count received last minute -- count="150057"
Oct 19 00:42:40 INFO startup-script: ~ INFO -- count received last minute -- count="144448"
Oct 19 00:43:40 INFO startup-script: ~ INFO -- count received last minute -- count="61037"
Oct 19 00:44:40 INFO startup-script: ~ INFO -- count received last minute -- count="36671"
Oct 19 00:45:40 INFO startup-script: ~ INFO -- count received last minute -- count="20960"
Oct 19 00:46:40 INFO startup-script: ~ INFO -- count received last minute -- count="12574"
Oct 19 00:47:40 INFO startup-script: ~ INFO -- count received last minute -- count="8844"
Oct 19 00:48:40 INFO startup-script: ~ INFO -- count received last minute -- count="6255"
Oct 19 00:49:40 INFO startup-script: ~ INFO -- count received last minute -- count="3190"
Oct 19 00:50:40 INFO startup-script: ~ INFO -- count received last minute -- count="2002"
You can see the drop started around 12:42am UTC and the blockingPicker logs started around the same time.
Graph of successful Pull Ack requests (via stackdriver):
jameshartig
on 19 Oct 2018
Thank you very much. And just to check, could you post your commit SHA of google-api-go-client, google-cloud-go, and grpc-go?
jadekler
on 19 Oct 2018
Woops, forgot to post that earlier!
genproto=94acd270e44e65579b9ee3cdab25034d33fed608
google-api-go-client=1ee037c9707128cf915508b3051e3167243b7b7e
grpc-go=c96823908c3ec449e3094ac5d40974b19e1a946b
google-cloud-go=1d9633a229077f680bf8fe431a93d5f489835506
👍1
@fastest963 Those dumps were extremely enlightening. It appears as though onClose is either deadlocked [1] or it's being allowed to skip resetting the transport [2]. It gets logged without a corresponding transition to TRANSIENT_FAILURE, which is very smelly.
I've added some very verbose logging around all these flows: if you have any energy today or tomorrow, please give https://github.com/jadekler/grpc-go.git at commit 79c40c8630c95156b960ab741b25a44f71647b9f (latest commit on branch log_connectivity_transitions) a shot [3], and post dumps.
If you're not able to, no worries: we will continue to pore over that code and your recently-provided logs.
1: Your earlier goroutine dumps don't indicate it, so I suspect not.
2: Also not seeing how this could be possible.
3: You'll again need to set GRPC_GO_LOG_VERBOSITY_LEVEL=99 and GRPC_GO_LOG_SEVERITY_LEVEL=info.
jadekler
on 19 Oct 2018
Okay re-ran with the latest commit on your branch log_connectivity_transititions and didn't change the commits for any other packages.
Oct 19 14:05:03 INFO startup-script: ~ INFO -- count received last minute -- count="123581"
Oct 19 14:06:03 INFO startup-script: ~ INFO -- count received last minute -- count="126595"
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: onGoAway received
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: transient failure? true, true, false, false
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: entering transient failure
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: continuing the connect
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: CONNECTING
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: handle SubConn state change: READY
Oct 19 14:06:59 INFO startup-script: INFO: 2018/10/19 14:06:59 [{pubsub.googleapis.com:443 0 2}]: server preface received
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: onGoAway received
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: transient failure? true, true, false, false
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: entering transient failure
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: continuing the connect
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: CONNECTING
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: onGoAway received
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: transient failure? true, true, false, false
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: entering transient failure
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: continuing the connect
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: CONNECTING
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: handle SubConn state change: READY
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 3}]: server preface received
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: onGoAway received
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: transient failure? true, true, false, false
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: entering transient failure
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: TRANSIENT_FAILURE
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: continuing the connect
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: CONNECTING
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: handle SubConn state change: READY
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 0}]: server preface received
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: handle SubConn state change: READY
Oct 19 14:07:02 INFO startup-script: INFO: 2018/10/19 14:07:02 [{pubsub.googleapis.com:443 0 1}]: server preface received
Oct 19 14:07:03 INFO startup-script: ~ INFO -- count received last minute -- count="127483"
Oct 19 14:08:03 INFO startup-script: ~ INFO -- count received last minute -- count="120554"
Oct 19 14:09:03 INFO startup-script: ~ INFO -- count received last minute -- count="124916"
Oct 19 14:10:03 INFO startup-script: ~ INFO -- count received last minute -- count="114926"
Oct 19 14:11:03 INFO startup-script: ~ INFO -- count received last minute -- count="114391"
Oct 19 14:12:03 INFO startup-script: ~ INFO -- count received last minute -- count="101908"
Oct 19 14:13:03 INFO startup-script: ~ INFO -- count received last minute -- count="118148"
Oct 19 14:14:03 INFO startup-script: ~ INFO -- count received last minute -- count="124064"
Oct 19 14:15:03 INFO startup-script: ~ INFO -- count received last minute -- count="92735"
Oct 19 14:16:03 INFO startup-script: ~ INFO -- count received last minute -- count="89526"
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 [{pubsub.googleapis.com:443 0 2}]: onClose received
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 [{pubsub.googleapis.com:443 0 2}]: prefaceTimer.Stop()
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 [{pubsub.googleapis.com:443 0 2}]: select {}
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 [{pubsub.googleapis.com:443 0 2}]: allowed to reset! locking..
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 [{pubsub.googleapis.com:443 0 2}]: acquired lock
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 [{pubsub.googleapis.com:443 0 2}]: released lock
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:45 INFO startup-script: INFO: 2018/10/19 14:16:45 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
Oct 19 14:16:46 INFO startup-script: INFO: 2018/10/19 14:16:46 blockingPicker: the picked transport is not ready, loop back to repick
...
Full log is available here: https://gobin.io/eLqf
Also, goroutine dump:
goroutine profile: total 194
40 @ 0x42db9b 0x42dc43 0x405a6e 0x40575b 0x848798 0x45b831
# 0x848797 cloud.google.com/go/pubsub.(*Subscription).receive.func1+0x47 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:512
39 @ 0x42db9b 0x43d9ad 0x7f77ad 0x7f2748 0x7fe3be 0x7fd6b3 0x7ee78c 0x7ee543 0x828bf2 0x83a4d8 0x807682 0x807443 0x836a37 0x847b21 0x84078d 0x8404a8 0x83feac 0x45b831
# 0x7f77ac google.golang.org/grpc.(*pickerWrapper).pick+0x56c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x7f2747 google.golang.org/grpc.(*ClientConn).getTransport+0x97 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/clientconn.go:720
# 0x7fe3bd google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:309
# 0x7fd6b2 google.golang.org/grpc.newClientStream+0x712 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:269
# 0x7ee78b google.golang.org/grpc.invoke+0x9b C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:66
# 0x7ee542 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:37
# 0x828bf1 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).Acknowledge+0xd1 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3113
# 0x83a4d7 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).Acknowledge.func1+0x77 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:333
# 0x807681 github.com/googleapis/gax-go.invoke+0xa1 C:/Users/james/Dropbox/go/src/github.com/googleapis/gax-go/invoke.go:81
# 0x807442 github.com/googleapis/gax-go.Invoke+0x112 C:/Users/james/Dropbox/go/src/github.com/googleapis/gax-go/invoke.go:58
# 0x836a36 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).Acknowledge+0x1a6 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:331
# 0x847b20 cloud.google.com/go/pubsub.(*messageIterator).sendAck.func1+0x100 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:384
# 0x84078c cloud.google.com/go/pubsub.(*messageIterator).sendAckIDRPC+0x22c C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:448
# 0x8404a7 cloud.google.com/go/pubsub.(*messageIterator).sendAck+0x57 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:379
# 0x83feab cloud.google.com/go/pubsub.(*messageIterator).sender+0x3fb C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:336
27 @ 0x42db9b 0x43d9ad 0x7d31fe 0x7d2fca 0x7d3d55 0x4729a8 0x472b48 0x7d3c9f 0x7f9cd5 0x7fa94d 0x7faffb 0x8006c4 0x8032ad 0x7ff451 0x7ffe4d 0x828ff2 0x848431 0x841d0c 0x841fde 0x83fa33 0x83f783 0x845872 0x848727 0x83be47 0x45b831
# 0x7d31fd google.golang.org/grpc/internal/transport.(*recvBufferReader).read+0x1ad C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:142
# 0x7d2fc9 google.golang.org/grpc/internal/transport.(*recvBufferReader).Read+0x59 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:131
# 0x7d3d54 google.golang.org/grpc/internal/transport.(*transportReader).Read+0x54 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:401
# 0x4729a7 io.ReadAtLeast+0x87 c:/go/src/io/io.go:310
# 0x472b47 io.ReadFull+0x57 c:/go/src/io/io.go:329
# 0x7d3c9e google.golang.org/grpc/internal/transport.(*Stream).Read+0xbe C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/transport.go:385
# 0x7f9cd4 google.golang.org/grpc.(*parser).recvMsg+0x64 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/rpc_util.go:476
# 0x7fa94c google.golang.org/grpc.recvAndDecompress+0x4c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/rpc_util.go:602
# 0x7faffa google.golang.org/grpc.recv+0x9a C:/Users/james/Dropbox/go/src/google.golang.org/grpc/rpc_util.go:645
# 0x8006c3 google.golang.org/grpc.(*csAttempt).recvMsg+0xe3 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:762
# 0x8032ac google.golang.org/grpc.(*clientStream).RecvMsg.func1+0x3c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:648
# 0x7ff450 google.golang.org/grpc.(*clientStream).withRetry+0x280 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:530
# 0x7ffe4c google.golang.org/grpc.(*clientStream).RecvMsg+0x8c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:647
# 0x828ff1 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberStreamingPullClient).Recv+0x61 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3154
# 0x848430 cloud.google.com/go/pubsub.(*pullStream).Recv.func1+0x70 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:172
# 0x841d0b cloud.google.com/go/pubsub.(*pullStream).call+0xcb C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:132
# 0x841fdd cloud.google.com/go/pubsub.(*pullStream).Recv+0x6d C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:169
# 0x83fa32 cloud.google.com/go/pubsub.(*messageIterator).recvMessages+0x32 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:251
# 0x83f782 cloud.google.com/go/pubsub.(*messageIterator).receive+0x602 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:194
# 0x845871 cloud.google.com/go/pubsub.(*Subscription).receive+0x401 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:545
# 0x848726 cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x56 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:489
# 0x83be46 golang.org/x/sync/errgroup.(*Group).Go.func1+0x56 C:/Users/james/go/src/golang.org/x/sync/errgroup/errgroup.go:58
27 @ 0x42db9b 0x43d9ad 0x802da7 0x45b831
# 0x802da6 google.golang.org/grpc.newClientStream.func5+0xd6 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:287
20 @ 0x42db9b 0x43d9ad 0x847045 0x84a5f3 0x45b831
# 0x847044 cloud.google.com/go/pubsub.(*PublishResult).Get+0xe4 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/topic.go:380
# 0x84a5f2 main.main.func2+0x122 C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:72
13 @ 0x42db9b 0x43d9ad 0x7f77ad 0x7f2748 0x7fe3be 0x7fd6b3 0x7fcddf 0x828e48 0x83a66e 0x807682 0x807443 0x836fab 0x849123 0x8480f1 0x841b08 0x84190c 0x841ca8 0x841fde 0x83fa33 0x83f783 0x845872 0x848727 0x83be47 0x45b831
# 0x7f77ac google.golang.org/grpc.(*pickerWrapper).pick+0x56c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x7f2747 google.golang.org/grpc.(*ClientConn).getTransport+0x97 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/clientconn.go:720
# 0x7fe3bd google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:309
# 0x7fd6b2 google.golang.org/grpc.newClientStream+0x712 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:269
# 0x7fcdde google.golang.org/grpc.(*ClientConn).NewStream+0x17e C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:145
# 0x828e47 google.golang.org/genproto/googleapis/pubsub/v1.(*subscriberClient).StreamingPull+0xa7 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:3130
# 0x83a66d cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull.func1+0x7d C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:370
# 0x807681 github.com/googleapis/gax-go.invoke+0xa1 C:/Users/james/Dropbox/go/src/github.com/googleapis/gax-go/invoke.go:81
# 0x807442 github.com/googleapis/gax-go.Invoke+0x112 C:/Users/james/Dropbox/go/src/github.com/googleapis/gax-go/invoke.go:58
# 0x836faa cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull+0x1ca C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/subscriber_client.go:368
# 0x849122 cloud.google.com/go/pubsub/apiv1.(*SubscriberClient).StreamingPull-fm+0x62 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:77
# 0x8480f0 cloud.google.com/go/pubsub.newPullStream.func1+0x1f0 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:47
# 0x841b07 cloud.google.com/go/pubsub.(*pullStream).openWithRetry+0x77 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:108
# 0x84190b cloud.google.com/go/pubsub.(*pullStream).get+0xfb C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:100
# 0x841ca7 cloud.google.com/go/pubsub.(*pullStream).call+0x67 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:127
# 0x841fdd cloud.google.com/go/pubsub.(*pullStream).Recv+0x6d C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/pullstream.go:169
# 0x83fa32 cloud.google.com/go/pubsub.(*messageIterator).recvMessages+0x32 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:251
# 0x83f782 cloud.google.com/go/pubsub.(*messageIterator).receive+0x602 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:194
# 0x845871 cloud.google.com/go/pubsub.(*Subscription).receive+0x401 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:545
# 0x848726 cloud.google.com/go/pubsub.(*Subscription).Receive.func2+0x56 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:489
# 0x83be46 golang.org/x/sync/errgroup.(*Group).Go.func1+0x56 C:/Users/james/go/src/golang.org/x/sync/errgroup/errgroup.go:58
4 @ 0x42db9b 0x428ed9 0x428586 0x4900ea 0x4901fd 0x490f49 0x5830cf 0x596128 0x5e0e29 0x5e132d 0x5e48b1 0x54105f 0x4729a8 0x472b48 0x7b365b 0x7b3ec3 0x7ce176 0x45b831
# 0x428585 internal/poll.runtime_pollWait+0x65 c:/go/src/runtime/netpoll.go:173
# 0x4900e9 internal/poll.(*pollDesc).wait+0x99 c:/go/src/internal/poll/fd_poll_runtime.go:85
# 0x4901fc internal/poll.(*pollDesc).waitRead+0x3c c:/go/src/internal/poll/fd_poll_runtime.go:90
# 0x490f48 internal/poll.(*FD).Read+0x178 c:/go/src/internal/poll/fd_unix.go:169
# 0x5830ce net.(*netFD).Read+0x4e c:/go/src/net/fd_unix.go:202
# 0x596127 net.(*conn).Read+0x67 c:/go/src/net/net.go:177
# 0x5e0e28 crypto/tls.(*block).readFromUntil+0x88 c:/go/src/crypto/tls/conn.go:492
# 0x5e132c crypto/tls.(*Conn).readRecord+0xdc c:/go/src/crypto/tls/conn.go:593
# 0x5e48b0 crypto/tls.(*Conn).Read+0xf0 c:/go/src/crypto/tls/conn.go:1145
# 0x54105e bufio.(*Reader).Read+0x22e c:/go/src/bufio/bufio.go:216
# 0x4729a7 io.ReadAtLeast+0x87 c:/go/src/io/io.go:310
# 0x472b47 io.ReadFull+0x57 c:/go/src/io/io.go:329
# 0x7b365a golang.org/x/net/http2.readFrameHeader+0x7a C:/Users/james/go/src/golang.org/x/net/http2/frame.go:237
# 0x7b3ec2 golang.org/x/net/http2.(*Framer).ReadFrame+0xa2 C:/Users/james/go/src/golang.org/x/net/http2/frame.go:492
# 0x7ce175 google.golang.org/grpc/internal/transport.(*http2Client).reader+0x175 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/http2_client.go:1209
4 @ 0x42db9b 0x43d9ad 0x7c12d3 0x7c19ec 0x7d465b 0x45b831
# 0x7c12d2 google.golang.org/grpc/internal/transport.(*controlBuffer).get+0x102 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/controlbuf.go:317
# 0x7c19eb google.golang.org/grpc/internal/transport.(*loopyWriter).run+0x1ab C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/controlbuf.go:435
# 0x7d465a google.golang.org/grpc/internal/transport.newHTTP2Client.func3+0x7a C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/http2_client.go:319
4 @ 0x42db9b 0x43d9ad 0x7ce943 0x45b831
# 0x7ce942 google.golang.org/grpc/internal/transport.(*http2Client).keepalive+0x112 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/internal/transport/http2_client.go:1260
1 @ 0x40ab97 0x44259c 0x712482 0x45b831
# 0x44259b os/signal.signal_recv+0x9b c:/go/src/runtime/sigqueue.go:139
# 0x712481 os/signal.loop+0x21 c:/go/src/os/signal/signal_unix.go:23
1 @ 0x42db9b 0x428ed9 0x428586 0x4900ea 0x4901fd 0x4924f0 0x583a12 0x59ff1e 0x59e957 0x68415f 0x6a4b3c 0x682f8f 0x682c46 0x683c34 0x84a4be 0x45b831
# 0x428585 internal/poll.runtime_pollWait+0x65 c:/go/src/runtime/netpoll.go:173
# 0x4900e9 internal/poll.(*pollDesc).wait+0x99 c:/go/src/internal/poll/fd_poll_runtime.go:85
# 0x4901fc internal/poll.(*pollDesc).waitRead+0x3c c:/go/src/internal/poll/fd_poll_runtime.go:90
# 0x4924ef internal/poll.(*FD).Accept+0x19f c:/go/src/internal/poll/fd_unix.go:384
# 0x583a11 net.(*netFD).accept+0x41 c:/go/src/net/fd_unix.go:238
# 0x59ff1d net.(*TCPListener).accept+0x2d c:/go/src/net/tcpsock_posix.go:139
# 0x59e956 net.(*TCPListener).AcceptTCP+0x46 c:/go/src/net/tcpsock.go:247
# 0x68415e net/http.tcpKeepAliveListener.Accept+0x2e c:/go/src/net/http/server.go:3232
# 0x682f8e net/http.(*Server).Serve+0x22e c:/go/src/net/http/server.go:2826
# 0x682c45 net/http.(*Server).ListenAndServe+0xb5 c:/go/src/net/http/server.go:2764
# 0x683c33 net/http.ListenAndServe+0x73 c:/go/src/net/http/server.go:3004
# 0x84a4bd main.main.func1+0x3d C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:39
1 @ 0x42db9b 0x42dc43 0x405a6e 0x40575b 0x8063ca 0x7e8b37 0x8017bb 0x45b831
# 0x8063c9 google.golang.org/api/internal.(*PoolResolver).Next+0x49 C:/Users/james/Dropbox/go/src/google.golang.org/api/internal/pool.go:54
# 0x7e8b36 google.golang.org/grpc.(*roundRobin).watchAddrUpdates+0x56 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer.go:145
# 0x8017ba google.golang.org/grpc.(*roundRobin).Start.func1+0x2a C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer.go:220
1 @ 0x42db9b 0x42dc43 0x405a6e 0x40575b 0x84a27a 0x42d7a7 0x45b831
# 0x84a279 main.main+0x5c9 C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:124
# 0x42d7a6 runtime.main+0x206 c:/go/src/runtime/proc.go:201
1 @ 0x42db9b 0x42dc43 0x405a6e 0x40579b 0x7ebf6c 0x45b831
# 0x7ebf6b google.golang.org/grpc.(*balancerWrapper).lbWatcher+0xeb C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer_v1_wrapper.go:124
1 @ 0x42db9b 0x42dc43 0x43e55c 0x43e199 0x4724f4 0x83bcc1 0x8452e3 0x84aa67 0x45b831
# 0x43e198 sync.runtime_Semacquire+0x38 c:/go/src/runtime/sema.go:56
# 0x4724f3 sync.(*WaitGroup).Wait+0x63 c:/go/src/sync/waitgroup.go:130
# 0x83bcc0 golang.org/x/sync/errgroup.(*Group).Wait+0x30 C:/Users/james/go/src/golang.org/x/sync/errgroup/errgroup.go:41
# 0x8452e2 cloud.google.com/go/pubsub.(*Subscription).Receive+0x322 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/subscription.go:492
# 0x84aa66 main.main.func4+0xa6 C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:106
1 @ 0x42db9b 0x42dc43 0x43f59b 0x46f582 0x83ccb5 0x83c82d 0x83d13a 0x45b831
# 0x43f59a sync.runtime_notifyListWait+0xea c:/go/src/runtime/sema.go:510
# 0x46f581 sync.(*Cond).Wait+0x91 c:/go/src/sync/cond.go:56
# 0x83ccb4 google.golang.org/api/support/bundler.(*Bundler).waitUntilAllHandled+0x74 C:/Users/james/Dropbox/go/src/google.golang.org/api/support/bundler/bundler.go:335
# 0x83c82c google.golang.org/api/support/bundler.(*Bundler).Flush+0x8c C:/Users/james/Dropbox/go/src/google.golang.org/api/support/bundler/bundler.go:250
# 0x83d139 google.golang.org/api/support/bundler.(*Bundler).Flush-fm+0x29 C:/Users/james/Dropbox/go/src/google.golang.org/api/support/bundler/bundler.go:195
1 @ 0x42db9b 0x43d9ad 0x713fed 0x45b831
# 0x713fec github.com/levenlabs/go-llog.init.0.func1+0xfc C:/Users/james/Dropbox/go/src/github.com/levenlabs/go-llog/llog.go:242
1 @ 0x42db9b 0x43d9ad 0x742bcd 0x45b831
# 0x742bcc go.opencensus.io/stats/view.(*worker).start+0xdc C:/Users/james/go/src/go.opencensus.io/stats/view/worker.go:146
1 @ 0x42db9b 0x43d9ad 0x7eab9f 0x45b831
# 0x7eab9e google.golang.org/grpc.(*ccBalancerWrapper).watcher+0x10e C:/Users/james/Dropbox/go/src/google.golang.org/grpc/balancer_conn_wrappers.go:122
1 @ 0x42db9b 0x43d9ad 0x7f77ad 0x7f2748 0x7fe3be 0x7fd6b3 0x7ee78c 0x7ee543 0x827cf2 0x838964 0x807682 0x807443 0x832e31 0x847757 0x848a53 0x83cfc4 0x45b831
# 0x7f77ac google.golang.org/grpc.(*pickerWrapper).pick+0x56c C:/Users/james/Dropbox/go/src/google.golang.org/grpc/picker_wrapper.go:124
# 0x7f2747 google.golang.org/grpc.(*ClientConn).getTransport+0x97 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/clientconn.go:720
# 0x7fe3bd google.golang.org/grpc.(*clientStream).newAttemptLocked+0x13d C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:309
# 0x7fd6b2 google.golang.org/grpc.newClientStream+0x712 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/stream.go:269
# 0x7ee78b google.golang.org/grpc.invoke+0x9b C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:66
# 0x7ee542 google.golang.org/grpc.(*ClientConn).Invoke+0x1b2 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/call.go:37
# 0x827cf1 google.golang.org/genproto/googleapis/pubsub/v1.(*publisherClient).Publish+0xd1 C:/Users/james/Dropbox/go/src/google.golang.org/genproto/googleapis/pubsub/v1/pubsub.pb.go:2667
# 0x838963 cloud.google.com/go/pubsub/apiv1.(*PublisherClient).Publish.func1+0x83 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:195
# 0x807681 github.com/googleapis/gax-go.invoke+0xa1 C:/Users/james/Dropbox/go/src/github.com/googleapis/gax-go/invoke.go:81
# 0x807442 github.com/googleapis/gax-go.Invoke+0x112 C:/Users/james/Dropbox/go/src/github.com/googleapis/gax-go/invoke.go:58
# 0x832e30 cloud.google.com/go/pubsub/apiv1.(*PublisherClient).Publish+0x1d0 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/apiv1/publisher_client.go:193
# 0x847756 cloud.google.com/go/pubsub.(*Topic).publishMessageBundle+0x396 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/topic.go:450
# 0x848a52 cloud.google.com/go/pubsub.(*Topic).initBundler.func1+0x82 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/topic.go:422
# 0x83cfc3 google.golang.org/api/support/bundler.(*Bundler).startFlushLocked.func1+0xd3 C:/Users/james/Dropbox/go/src/google.golang.org/api/support/bundler/bundler.go:272
1 @ 0x42db9b 0x43d9ad 0x7f9212 0x45b831
# 0x7f9211 google.golang.org/grpc.(*ccResolverWrapper).watcher+0x141 C:/Users/james/Dropbox/go/src/google.golang.org/grpc/resolver_conn_wrapper.go:111
1 @ 0x42db9b 0x43d9ad 0x83fce8 0x45b831
# 0x83fce7 cloud.google.com/go/pubsub.(*messageIterator).sender+0x237 C:/Users/james/Dropbox/go/src/cloud.google.com/go/pubsub/iterator.go:279
1 @ 0x42db9b 0x43d9ad 0x84a84e 0x45b831
# 0x84a84d main.main.func3+0x12d C:/Users/james/Dropbox/go/src/gerrit.levenlabs.com/pubsub-test/main.go:92
1 @ 0x6799e0 0x45b831
# 0x6799e0 net/http.(*connReader).backgroundRead+0x0 c:/go/src/net/http/server.go:675
1 @ 0x708148 0x707f50 0x7049b4 0x710df0 0x7116c3 0x67fed4 0x681b77 0x682b1b 0x67ef36 0x45b831
# 0x708147 runtime/pprof.writeRuntimeProfile+0x97 c:/go/src/runtime/pprof/pprof.go:707
# 0x707f4f runtime/pprof.writeGoroutine+0x9f c:/go/src/runtime/pprof/pprof.go:669
# 0x7049b3 runtime/pprof.(*Profile).WriteTo+0x3e3 c:/go/src/runtime/pprof/pprof.go:328
# 0x710def net/http/pprof.handler.ServeHTTP+0x20f c:/go/src/net/http/pprof/pprof.go:245
# 0x7116c2 net/http/pprof.Index+0x722 c:/go/src/net/http/pprof/pprof.go:268
# 0x67fed3 net/http.HandlerFunc.ServeHTTP+0x43 c:/go/src/net/http/server.go:1964
# 0x681b76 net/http.(*ServeMux).ServeHTTP+0x126 c:/go/src/net/http/server.go:2361
# 0x682b1a net/http.serverHandler.ServeHTTP+0xaa c:/go/src/net/http/server.go:2741
# 0x67ef35 net/http.(*conn).serve+0x645 c:/go/src/net/http/server.go:1847
And here's the graph:
jameshartig
on 19 Oct 2018
Thanks, we've found the problem. Working on a fix now.
jadekler
on 19 Oct 2018
🎉2
Tracking fix in https://github.com/grpc/grpc-go/pull/2391.
jadekler
on 19 Oct 2018
I believe that as of grpc-go=ff2aa05958775030998dbe2f9bccbe2af324adf4 this is now fixed. Could you PTAL? If not, let me know, and we'll continue digging.
Also @fastest963, we plan on adding a special thanks for your help in the next grpc-go release as well as in the next google-cloud-go release. Furthermore, if you email me your address and shirt size, I think we may be able to send you a hoodie, too. We greatly appreciate all your help.
Keeping this issue open for now until someone can confirm that the problem is no longer present with ff2aa05958775030998dbe2f9bccbe2af324adf4.
jadekler
on 19 Oct 2018
Running a test with that commit now. Crossing my fingers!
Thanks for the swag and the thanks! I'll send you an email later with the my details.
jameshartig
on 20 Oct 2018
Ran the test for over 4 hours and there was no dropping off :thumbsup:
jameshartig
on 20 Oct 2018
🎉1
👍1
Great! Let us know how it's looking after the weekend 馃憤
jadekler
on 22 Oct 2018
The grpc-go fix is looking great! We deployed it across all of our servers and things have been stable all day so far. I think this is good to close.
jameshartig
on 22 Oct 2018
Fantastic news!
jadekler
on 22 Oct 2018
I can confirm that HEAD across the board has been looking good for me too.
dsymonds
on 23 Oct 2018
Woot, thanks for the confirmation @dsymonds.
jadekler
on 24 Oct 2018
Was this page helpful?
0 / 5 - 0 ratings
Related issues
philippgille
路
3Comments
lukaszraczylo
路
3Comments
imkira
路
4Comments
MoreThanCarbon
路
3Comments
rileykarson
路
4Comments
Most helpful comment
Ran the test for over 4 hours and there was no dropping off :thumbsup: