gRPC Unidirectional stream too chatty

Question

I enabled GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG in my python gRPC client. My server is written in Java. The client establishes a unidirectional stream connection with server and waits for the server to push messages onto it.

This is my keep-alive configuration for python client

GRPC_ENABLE_RETRIES = 1
GRPC_KEEPALIVE_TIME_MS = 60000
GRPC_KEEPALIVE_TIMEOUT_MS = 10000
GRPC_KEEPALIVE_PERMIT_WITHOUT_CALLS = True

When I start my client, I see a ton of logs being printed every millisecond

I1004 15:29:00.375854000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 375851000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.376925000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.376937000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 376934000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.378107000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.378120000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 378117000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.379159000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.379171000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 379169000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.380281000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.380291000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 380289000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.381440000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.381452000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 381450000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.382599000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.382610000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 382608000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.383749000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.383754000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 383753000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.384890000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.384895000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 384893000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.386029000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.386034000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 386033000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.387172000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.387177000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 387176000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.388315000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.388321000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 388320000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.389379000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.389406000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 389404000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.390550000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.390559000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 390557000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.391699000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.391704000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 391702000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.392849000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.392860000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 392858000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.393588000 123145472741376 timer_manager.cc:205]         wait ended: was_timed:1 kicked:0
I1004 15:29:00.393598000 123145472741376 timer_generic.cc:703]         TIMER CHECK BEGIN: now=3114 next=9223372036854775807 tls_min=2105 glob_min=3110
I1004 15:29:00.393602000 123145472741376 timer_generic.cc:601]           .. shard[0]->min_deadline = 3110
I1004 15:29:00.393605000 123145472741376 timer_generic.cc:516]           .. shard[0]: heap_empty=true
I1004 15:29:00.393607000 123145472741376 timer_generic.cc:487]           .. shard[0]->queue_deadline_cap --> 4114
I1004 15:29:00.393610000 123145472741376 timer_generic.cc:561]           .. shard[0] popped 0
I1004 15:29:00.393613000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[0]->min_deadline 3110 --> 4115, now=3114
I1004 15:29:00.393616000 123145472741376 timer_generic.cc:516]           .. shard[1]: heap_empty=true
I1004 15:29:00.393618000 123145472741376 timer_generic.cc:487]           .. shard[1]->queue_deadline_cap --> 4113
I1004 15:29:00.393620000 123145472741376 timer_generic.cc:561]           .. shard[1] popped 0
I1004 15:29:00.393623000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[1]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393625000 123145472741376 timer_generic.cc:516]           .. shard[2]: heap_empty=true
I1004 15:29:00.393627000 123145472741376 timer_generic.cc:487]           .. shard[2]->queue_deadline_cap --> 4114
I1004 15:29:00.393630000 123145472741376 timer_generic.cc:561]           .. shard[2] popped 0
I1004 15:29:00.393632000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[2]->min_deadline 3110 --> 4115, now=3114
I1004 15:29:00.393635000 123145472741376 timer_generic.cc:516]           .. shard[3]: heap_empty=true
I1004 15:29:00.393637000 123145472741376 timer_generic.cc:487]           .. shard[3]->queue_deadline_cap --> 4114
I1004 15:29:00.393639000 123145472741376 timer_generic.cc:561]           .. shard[3] popped 0
I1004 15:29:00.393642000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[3]->min_deadline 3110 --> 4115, now=3114
I1004 15:29:00.393644000 123145472741376 timer_generic.cc:516]           .. shard[4]: heap_empty=true
I1004 15:29:00.393646000 123145472741376 timer_generic.cc:487]           .. shard[4]->queue_deadline_cap --> 4113
I1004 15:29:00.393648000 123145472741376 timer_generic.cc:561]           .. shard[4] popped 0
I1004 15:29:00.393651000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[4]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393653000 123145472741376 timer_generic.cc:516]           .. shard[5]: heap_empty=true
I1004 15:29:00.393655000 123145472741376 timer_generic.cc:487]           .. shard[5]->queue_deadline_cap --> 4113
I1004 15:29:00.393662000 123145472741376 timer_generic.cc:561]           .. shard[5] popped 0
I1004 15:29:00.393665000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[5]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393667000 123145472741376 timer_generic.cc:516]           .. shard[6]: heap_empty=true
I1004 15:29:00.393670000 123145472741376 timer_generic.cc:487]           .. shard[6]->queue_deadline_cap --> 4113
I1004 15:29:00.393672000 123145472741376 timer_generic.cc:561]           .. shard[6] popped 0
I1004 15:29:00.393675000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[6]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393677000 123145472741376 timer_generic.cc:516]           .. shard[7]: heap_empty=true
I1004 15:29:00.393679000 123145472741376 timer_generic.cc:487]           .. shard[7]->queue_deadline_cap --> 4113
I1004 15:29:00.393681000 123145472741376 timer_generic.cc:561]           .. shard[7] popped 0
I1004 15:29:00.393684000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[7]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393686000 123145472741376 timer_generic.cc:516]           .. shard[8]: heap_empty=true
I1004 15:29:00.393688000 123145472741376 timer_generic.cc:487]           .. shard[8]->queue_deadline_cap --> 4113
I1004 15:29:00.393691000 123145472741376 timer_generic.cc:561]           .. shard[8] popped 0
I1004 15:29:00.393693000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[8]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393696000 123145472741376 timer_generic.cc:516]           .. shard[9]: heap_empty=true
I1004 15:29:00.393698000 123145472741376 timer_generic.cc:487]           .. shard[9]->queue_deadline_cap --> 4113
I1004 15:29:00.393700000 123145472741376 timer_generic.cc:561]           .. shard[9] popped 0
I1004 15:29:00.393703000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[9]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393705000 123145472741376 timer_generic.cc:516]           .. shard[10]: heap_empty=true
I1004 15:29:00.393707000 123145472741376 timer_generic.cc:487]           .. shard[10]->queue_deadline_cap --> 4113
I1004 15:29:00.393710000 123145472741376 timer_generic.cc:561]           .. shard[10] popped 0
I1004 15:29:00.393712000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[10]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393715000 123145472741376 timer_generic.cc:516]           .. shard[11]: heap_empty=true
I1004 15:29:00.393717000 123145472741376 timer_generic.cc:487]           .. shard[11]->queue_deadline_cap --> 4114
I1004 15:29:00.393719000 123145472741376 timer_generic.cc:561]           .. shard[11] popped 0
I1004 15:29:00.393722000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[11]->min_deadline 3110 --> 4115, now=3114
I1004 15:29:00.393724000 123145472741376 timer_generic.cc:516]           .. shard[12]: heap_empty=true
I1004 15:29:00.393727000 123145472741376 timer_generic.cc:487]           .. shard[12]->queue_deadline_cap --> 4113
I1004 15:29:00.393747000 123145472741376 timer_generic.cc:561]           .. shard[12] popped 0
I1004 15:29:00.393751000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[12]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393753000 123145472741376 timer_generic.cc:516]           .. shard[13]: heap_empty=true
I1004 15:29:00.393755000 123145472741376 timer_generic.cc:487]           .. shard[13]->queue_deadline_cap --> 4113
I1004 15:29:00.393757000 123145472741376 timer_generic.cc:561]           .. shard[13] popped 0
I1004 15:29:00.393760000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[13]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393762000 123145472741376 timer_generic.cc:516]           .. shard[14]: heap_empty=true
I1004 15:29:00.393764000 123145472741376 timer_generic.cc:487]           .. shard[14]->queue_deadline_cap --> 4113
I1004 15:29:00.393767000 123145472741376 timer_generic.cc:561]           .. shard[14] popped 0
I1004 15:29:00.393769000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[14]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393772000 123145472741376 timer_generic.cc:516]           .. shard[15]: heap_empty=true
I1004 15:29:00.393774000 123145472741376 timer_generic.cc:487]           .. shard[15]->queue_deadline_cap --> 4113
I1004 15:29:00.393776000 123145472741376 timer_generic.cc:561]           .. shard[15] popped 0
I1004 15:29:00.393778000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[15]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393781000 123145472741376 timer_generic.cc:516]           .. shard[16]: heap_empty=true
I1004 15:29:00.393783000 123145472741376 timer_generic.cc:487]           .. shard[16]->queue_deadline_cap --> 4113
I1004 15:29:00.393785000 123145472741376 timer_generic.cc:561]           .. shard[16] popped 0
I1004 15:29:00.393788000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[16]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393804000 123145472741376 timer_generic.cc:516]           .. shard[17]: heap_empty=true
I1004 15:29:00.393813000 123145472741376 timer_generic.cc:487]           .. shard[17]->queue_deadline_cap --> 4113
I1004 15:29:00.393816000 123145472741376 timer_generic.cc:561]           .. shard[17] popped 0
I1004 15:29:00.393820000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[17]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393823000 123145472741376 timer_generic.cc:516]           .. shard[18]: heap_empty=true
I1004 15:29:00.393825000 123145472741376 timer_generic.cc:487]           .. shard[18]->queue_deadline_cap --> 4113
I1004 15:29:00.393827000 123145472741376 timer_generic.cc:561]           .. shard[18] popped 0
I1004 15:29:00.393830000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[18]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393832000 123145472741376 timer_generic.cc:516]           .. shard[19]: heap_empty=true
I1004 15:29:00.393834000 123145472741376 timer_generic.cc:487]           .. shard[19]->queue_deadline_cap --> 4114
I1004 15:29:00.393836000 123145472741376 timer_generic.cc:561]           .. shard[19] popped 0
I1004 15:29:00.393839000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[19]->min_deadline 3110 --> 4115, now=3114
I1004 15:29:00.393841000 123145472741376 timer_generic.cc:516]           .. shard[20]: heap_empty=true
I1004 15:29:00.393844000 123145472741376 timer_generic.cc:487]           .. shard[20]->queue_deadline_cap --> 4113
I1004 15:29:00.393846000 123145472741376 timer_generic.cc:561]           .. shard[20] popped 0
I1004 15:29:00.393848000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[20]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393850000 123145472741376 timer_generic.cc:516]           .. shard[21]: heap_empty=true
I1004 15:29:00.393852000 123145472741376 timer_generic.cc:487]           .. shard[21]->queue_deadline_cap --> 4113
I1004 15:29:00.393855000 123145472741376 timer_generic.cc:561]           .. shard[21] popped 0
I1004 15:29:00.393857000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[21]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393859000 123145472741376 timer_generic.cc:516]           .. shard[22]: heap_empty=true
I1004 15:29:00.393861000 123145472741376 timer_generic.cc:487]           .. shard[22]->queue_deadline_cap --> 4113
I1004 15:29:00.393864000 123145472741376 timer_generic.cc:561]           .. shard[22] popped 0
I1004 15:29:00.393866000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[22]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393868000 123145472741376 timer_generic.cc:516]           .. shard[23]: heap_empty=true
I1004 15:29:00.393870000 123145472741376 timer_generic.cc:487]           .. shard[23]->queue_deadline_cap --> 4113
I1004 15:29:00.393872000 123145472741376 timer_generic.cc:561]           .. shard[23] popped 0
I1004 15:29:00.393875000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[23]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393877000 123145472741376 timer_generic.cc:516]           .. shard[24]: heap_empty=true
I1004 15:29:00.393879000 123145472741376 timer_generic.cc:487]           .. shard[24]->queue_deadline_cap --> 4113
I1004 15:29:00.393881000 123145472741376 timer_generic.cc:561]           .. shard[24] popped 0
I1004 15:29:00.393884000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[24]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393886000 123145472741376 timer_generic.cc:516]           .. shard[25]: heap_empty=true
I1004 15:29:00.393888000 123145472741376 timer_generic.cc:487]           .. shard[25]->queue_deadline_cap --> 4113
I1004 15:29:00.393890000 123145472741376 timer_generic.cc:561]           .. shard[25] popped 0
I1004 15:29:00.393893000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[25]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393895000 123145472741376 timer_generic.cc:516]           .. shard[26]: heap_empty=true
I1004 15:29:00.393897000 123145472741376 timer_generic.cc:487]           .. shard[26]->queue_deadline_cap --> 4113
I1004 15:29:00.393899000 123145472741376 timer_generic.cc:561]           .. shard[26] popped 0
I1004 15:29:00.393902000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[26]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393904000 123145472741376 timer_generic.cc:516]           .. shard[27]: heap_empty=true
I1004 15:29:00.393906000 123145472741376 timer_generic.cc:487]           .. shard[27]->queue_deadline_cap --> 4113
I1004 15:29:00.393908000 123145472741376 timer_generic.cc:561]           .. shard[27] popped 0
I1004 15:29:00.393910000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[27]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393913000 123145472741376 timer_generic.cc:516]           .. shard[28]: heap_empty=true
I1004 15:29:00.393915000 123145472741376 timer_generic.cc:487]           .. shard[28]->queue_deadline_cap --> 4113
I1004 15:29:00.393917000 123145472741376 timer_generic.cc:561]           .. shard[28] popped 0
I1004 15:29:00.393919000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[28]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393922000 123145472741376 timer_generic.cc:516]           .. shard[29]: heap_empty=true
I1004 15:29:00.393924000 123145472741376 timer_generic.cc:487]           .. shard[29]->queue_deadline_cap --> 4113
I1004 15:29:00.393926000 123145472741376 timer_generic.cc:561]           .. shard[29] popped 0
I1004 15:29:00.393928000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[29]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393930000 123145472741376 timer_generic.cc:516]           .. shard[30]: heap_empty=true
I1004 15:29:00.393933000 123145472741376 timer_generic.cc:487]           .. shard[30]->queue_deadline_cap --> 4113
I1004 15:29:00.393935000 123145472741376 timer_generic.cc:561]           .. shard[30] popped 0
I1004 15:29:00.393937000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[30]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393939000 123145472741376 timer_generic.cc:516]           .. shard[31]: heap_empty=true
I1004 15:29:00.393941000 123145472741376 timer_generic.cc:487]           .. shard[31]->queue_deadline_cap --> 4113
I1004 15:29:00.393943000 123145472741376 timer_generic.cc:561]           .. shard[31] popped 0
I1004 15:29:00.393946000 123145472741376 timer_generic.cc:620]           .. result --> 1, shard[31]->min_deadline 3110 --> 4114, now=3114
I1004 15:29:00.393948000 123145472741376 timer_generic.cc:728]         TIMER CHECK END: r=1; next=4114
I1004 15:29:00.393951000 123145472741376 timer_manager.cc:189]         sleep for a 1000 milliseconds
I1004 15:29:00.394037000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.394048000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 394046000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.395199000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.395210000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 395208000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.396239000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.396245000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 396243000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.397390000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.397401000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 397398000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.398582000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.398593000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 398591000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.399774000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.399785000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 399783000, clock_type: 1 }, reserved=0x0)
I1004 15:29:00.400935000 123145489530880 completion_queue.cc:1081]     RETURN_EVENT[0x7fa76fa44c20]: QUEUE_TIMEOUT
I1004 15:29:00.400946000 123145489530880 completion_queue.cc:976]      grpc_completion_queue_next(cq=0x7fa76fa44c20, deadline=gpr_timespec { tv_sec: 1664877540, tv_nsec: 400944000, clock_type: 1 }, reserved=0x0)

I have a few questions related to this

• Does these logs have anything to do with the stream connection? The keep-alive settings should trigger for every 1 minute. But the logs are printed every millisecond.
• Will this cause unnecessary CPU overhead ?
• Can this chattiness be controlled ?
• What do these logs signify in gRPC ?

Answer 1

You've turned up logging very high. GRPC_TRACE=all is intended for situations where you do not have direct access to a system demonstrating issues, so you need a data dump containing everything. In your case, since you have access to your own system, you should look for exactly the feature you want. In this case, you'll want to set GRPC_TRACE=http_keepalive. This option is included in all, but it's likely to be lost in the flood of everything else.

Does these logs have anything to do with the stream connection? The keep-alive settings should trigger for every 1 minute. But the logs are printed every millisecond.

No. Everything I see in this snippet is unrelated to keepalive.

Will this cause unnecessary CPU overhead ?

Absolutely. It will likely also fill up your logging filesystem if it's not actively rotated.

Can this chattiness be controlled ?

Yes. See the answer above.

What do these logs signify in gRPC ?

There are two types of logs in your snippet: timer logs and completion queue logs. A timer thread is created in every gRPC process. This enables other threads to schedule work to happen at some point in the future, i.e. RPC timeouts. You can see that thread waking up periodically in these logs.

The completion queue is the main data structure used for event communication between gRPC Core and languages wrapped around it, such as C++ and Python. Most time spent in a gRPC Python application is spent right here on this line. This will donate the thread to the gRPC Core layer to do I/O and other work for up to 200 milliseconds. Ideally, there would be no timeout here, but if we didn't call PyErr_CheckSignals periodically, then we would not be responsive to signals sent to the process. Each time grpc_completion_queue_next completes, you see an entry in the log above.