Skip to content

cpp_protobuf_async_client_unary_1channel_64wide_128Breq_8MBresp_secure_low_thread_count failing consistently (on TSAN) #13178

@kpayson64

Description

@kpayson64
2017-10-27 18:15:47,801 I1027 18:13:42.458881161    4904 ev_epollsig_linux.cc:75]    epoll engine will be using signal: 40
D1027 18:13:42.459048049    4904 ev_posix.cc:135]            Using polling engine: epollsig
D1027 18:13:42.459924398    4904 dns_resolver.cc:306]        Using native dns resolver
D1027 18:13:42.476728917    4904 ev_posix.cc:135]            Using polling engine: epollsig
D1027 18:13:42.476848263    4904 dns_resolver.cc:306]        Using native dns resolver
I1027 18:13:42.516949711    4909 ev_epollsig_linux.cc:75]    epoll engine will be using signal: 40
D1027 18:13:42.517128829    4909 ev_posix.cc:135]            Using polling engine: epollsig
D1027 18:13:42.517222312    4909 dns_resolver.cc:306]        Using native dns resolver
I1027 18:13:42.518349364    4909 server_builder.cc:269]      Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 2, CQ timeout (msec): 10000
I1027 18:13:42.526790888    4914 ev_epollsig_linux.cc:75]    epoll engine will be using signal: 40
D1027 18:13:42.526950095    4914 ev_posix.cc:135]            Using polling engine: epollsig
D1027 18:13:42.527048716    4914 dns_resolver.cc:306]        Using native dns resolver
I1027 18:13:42.527900239    4914 server_builder.cc:269]      Synchronous server. Num CQs: 1, Min pollers: 1, Max Pollers: 2, CQ timeout (msec): 10000
RUNNING SCENARIO: cpp_protobuf_async_client_unary_1channel_64wide_128Breq_8MBresp_secure
I1027 18:13:42.543960882    4917 driver.cc:273]              Starting server on localhost:9543 (worker #0)
I1027 18:13:42.547842349    4917 ev_epollsig_linux.cc:75]    epoll engine will be using signal: 40
D1027 18:13:42.548316365    4917 ev_posix.cc:135]            Using polling engine: epollsig
D1027 18:13:42.548424249    4917 dns_resolver.cc:306]        Using native dns resolver
I1027 18:13:42.561185421    4925 qps_worker.cc:231]          RunServerBody: about to create server
I1027 18:13:42.571473724    4925 qps_worker.cc:69]           Starting server of type ASYNC_SERVER
I1027 18:13:42.576121976    4925 server_async.cc:94]         Sizing async server to 32 threads
I1027 18:14:07.837324342    4925 qps_worker.cc:239]          RunServerBody: server created
I1027 18:14:07.837800840    4925 qps_worker.cc:246]          RunServerBody: creation status reported
I1027 18:14:07.838381734    4917 driver.cc:329]              Starting client on localhost:25854 (worker #1)
D1027 18:14:07.839937325    4917 driver.cc:351]              Client 0 gets 1 channels
I1027 18:14:07.848938651    4928 qps_worker.cc:188]          RunClientBody: about to create client
I1027 18:14:07.858831155    4928 qps_worker.cc:50]           Starting client of type ASYNC_CLIENT UNARY 0
I1027 18:14:07.861585000    4928 client.h:427]               Connecting to localhost:1152
I1027 18:14:08.132607440    4928 qps_worker.cc:193]          RunClientBody: client created
I1027 18:14:08.133047638    4928 qps_worker.cc:198]          RunClientBody: creation status reported
I1027 18:14:08.133485063    4917 driver.cc:372]              Initiating
I1027 18:14:08.133886542    4928 qps_worker.cc:200]          RunClientBody: Message read
I1027 18:14:08.139762534    4928 qps_worker.cc:209]          RunClientBody: Mark response given
I1027 18:14:08.143236127    4917 driver.cc:393]              Warming up
I1027 18:14:08.143282859    4917 driver.cc:399]              Starting
I1027 18:14:08.143745349    4925 qps_worker.cc:248]          RunServerBody: Message read
I1027 18:14:08.143770172    4928 qps_worker.cc:200]          RunClientBody: Message read
I1027 18:14:08.148946705    4928 qps_worker.cc:209]          RunClientBody: Mark response given
I1027 18:14:08.150397200    4925 qps_worker.cc:257]          RunServerBody: Mark response given
I1027 18:14:08.156328952    4917 driver.cc:426]              Running
I1027 18:14:09.143493492    4917 driver.cc:440]              Finishing clients
I1027 18:14:09.144280150    4928 qps_worker.cc:200]          RunClientBody: Message read
I1027 18:14:09.149161372    4928 qps_worker.cc:209]          RunClientBody: Mark response given
I1027 18:14:09.149242851    4928 qps_worker.cc:212]          RunClientBody: Awaiting Threads Completion
I1027 18:14:09.152483490    4917 driver.cc:454]              Received final status from client 0
D1027 18:14:09.206467730   12083 writing.cc:142]             ipv6:[::1]:34016:0x7da40000f000 stream 1 stalled by transport [fc:pending=0:flowed=0:peer_initwin=4194304:t_win=0:s_win=0:s_delta=-4194304]
E1027 18:14:09.638315415   12082 call.cc:2034]               assertion failed: grpc_cq_begin_op(call->cq, notify_tag)
D1027 18:14:09.639733833   12045 writing.cc:142]             ipv6:[::1]:34016:0x7da40000f000 stream 1 stalled by stream [fc:pending=0:flowed=0:peer_initwin=4194304:t_win=4194304:s_win=0:s_delta=-4194304]
E1027 18:14:09.816502216    4917 driver.cc:473]              Client 0 had an error Stream removed
I1027 18:14:09.816924002    4917 driver.cc:486]              Finishing servers
I1027 18:14:09.817364543    4925 qps_worker.cc:248]          RunServerBody: Message read
I1027 18:14:09.821729519    4925 qps_worker.cc:257]          RunServerBody: Mark response given
I1027 18:14:09.821808964    4925 qps_worker.cc:260]          RunServerBody: Returning
I1027 18:14:09.825686611    4917 driver.cc:500]              Received final status from server 0
D1027 18:15:42.483047111   12091 server.cc:721]              Waiting for 0 channels and 1/1 listeners to be destroyed before shutting down server
I1027 18:15:46.856162292    4925 qps_worker.cc:127]          RunServer: Returning
I1027 18:15:46.876697109    4917 report.cc:82]               QPS: 0.0
D1027 18:15:46.878204786    4917 report.cc:106]              CLIENT[0].client_calls_created = 1
D1027 18:15:46.878222960    4917 report.cc:106]              CLIENT[0].server_calls_created = 1
D1027 18:15:46.878231582    4917 report.cc:106]              CLIENT[0].cqs_created = 12
D1027 18:15:46.878239277    4917 report.cc:106]              CLIENT[0].client_channels_created = 1
D1027 18:15:46.878246662    4917 report.cc:106]              CLIENT[0].client_subchannels_created = 2
D1027 18:15:46.878253932    4917 report.cc:106]              CLIENT[0].server_channels_created = 1
D1027 18:15:46.878261069    4917 report.cc:106]              CLIENT[0].syscall_poll = 23
D1027 18:15:46.878268003    4917 report.cc:106]              CLIENT[0].syscall_wait = 0
D1027 18:15:46.878274753    4917 report.cc:106]              CLIENT[0].pollset_kick = 16
D1027 18:15:46.878281712    4917 report.cc:106]              CLIENT[0].pollset_kicked_without_poller = 0
D1027 18:15:46.878288865    4917 report.cc:106]              CLIENT[0].pollset_kicked_again = 0
D1027 18:15:46.878295762    4917 report.cc:106]              CLIENT[0].pollset_kick_wakeup_fd = 0
D1027 18:15:46.878302572    4917 report.cc:106]              CLIENT[0].pollset_kick_wakeup_cv = 0
D1027 18:15:46.878309385    4917 report.cc:106]              CLIENT[0].pollset_kick_own_thread = 0
D1027 18:15:46.878316180    4917 report.cc:106]              CLIENT[0].histogram_slow_lookups = 2
D1027 18:15:46.878323053    4917 report.cc:106]              CLIENT[0].syscall_write = 10
D1027 18:15:46.878329906    4917 report.cc:106]              CLIENT[0].syscall_read = 190
D1027 18:15:46.878336652    4917 report.cc:106]              CLIENT[0].tcp_backup_pollers_created = 0
D1027 18:15:46.878343418    4917 report.cc:106]              CLIENT[0].tcp_backup_poller_polls = 0
D1027 18:15:46.878350159    4917 report.cc:106]              CLIENT[0].http2_op_batches = 12
D1027 18:15:46.878359595    4917 report.cc:106]              CLIENT[0].http2_op_cancel = 1
D1027 18:15:46.878366771    4917 report.cc:106]              CLIENT[0].http2_op_send_initial_metadata = 2
D1027 18:15:46.878373706    4917 report.cc:106]              CLIENT[0].http2_op_send_message = 4
D1027 18:15:46.878380619    4917 report.cc:106]              CLIENT[0].http2_op_send_trailing_metadata = 1
D1027 18:15:46.878387585    4917 report.cc:106]              CLIENT[0].http2_op_recv_initial_metadata = 2
D1027 18:15:46.878394397    4917 report.cc:106]              CLIENT[0].http2_op_recv_message = 5
D1027 18:15:46.878401318    4917 report.cc:106]              CLIENT[0].http2_op_recv_trailing_metadata = 2
D1027 18:15:46.878431546    4917 report.cc:106]              CLIENT[0].http2_settings_writes = 2
D1027 18:15:46.878438338    4917 report.cc:106]              CLIENT[0].http2_pings_sent = 4
D1027 18:15:46.878444670    4917 report.cc:106]              CLIENT[0].http2_writes_begun = 8
D1027 18:15:46.878450856    4917 report.cc:106]              CLIENT[0].http2_writes_offloaded = 0
D1027 18:15:46.878457052    4917 report.cc:106]              CLIENT[0].http2_writes_continued = 0
D1027 18:15:46.878463248    4917 report.cc:106]              CLIENT[0].http2_partial_writes = 0
D1027 18:15:46.878471702    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_initial_write = 0
D1027 18:15:46.878478472    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_start_new_stream = 1
D1027 18:15:46.878497831    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_send_message = 2
D1027 18:15:46.878504729    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_send_initial_metadata = 1
D1027 18:15:46.878511692    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_send_trailing_metadata = 0
D1027 18:15:46.878518229    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_retry_send_ping = 0
D1027 18:15:46.878524763    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_continue_pings = 0
D1027 18:15:46.878531239    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_goaway_sent = 0
D1027 18:15:46.878537819    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_rst_stream = 0
D1027 18:15:46.878544220    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_close_from_api = 0
D1027 18:15:46.878550797    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_stream_flow_control = 1
D1027 18:15:46.878557297    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_transport_flow_control = 2
D1027 18:15:46.878563598    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_send_settings = 0
D1027 18:15:46.878569958    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_bdp_estimator_ping = 0
D1027 18:15:46.878576548    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_flow_control_unstalled_by_setting = 0
D1027 18:15:46.878583266    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_flow_control_unstalled_by_update = 0
D1027 18:15:46.878589657    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_application_ping = 0
D1027 18:15:46.878595997    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_keepalive_ping = 0
D1027 18:15:46.878602357    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_transport_flow_control_unstalled = 0
D1027 18:15:46.878608783    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_ping_response = 2
D1027 18:15:46.878615178    4917 report.cc:106]              CLIENT[0].http2_initiate_write_due_to_force_rst_stream = 0
D1027 18:15:46.878621563    4917 report.cc:106]              CLIENT[0].http2_spurious_writes_begun = 0
D1027 18:15:46.878627992    4917 report.cc:106]              CLIENT[0].hpack_recv_indexed = 0
D1027 18:15:46.878634422    4917 report.cc:106]              CLIENT[0].hpack_recv_lithdr_incidx = 0
D1027 18:15:46.878640913    4917 report.cc:106]              CLIENT[0].hpack_recv_lithdr_incidx_v = 13
D1027 18:15:46.878647255    4917 report.cc:106]              CLIENT[0].hpack_recv_lithdr_notidx = 0
D1027 18:15:46.878653532    4917 report.cc:106]              CLIENT[0].hpack_recv_lithdr_notidx_v = 0
D1027 18:15:46.878659899    4917 report.cc:106]              CLIENT[0].hpack_recv_lithdr_nvridx = 0
D1027 18:15:46.878666177    4917 report.cc:106]              CLIENT[0].hpack_recv_lithdr_nvridx_v = 0
D1027 18:15:46.878672533    4917 report.cc:106]              CLIENT[0].hpack_recv_uncompressed = 26
D1027 18:15:46.878678778    4917 report.cc:106]              CLIENT[0].hpack_recv_huffman = 0
D1027 18:15:46.878688803    4917 report.cc:106]              CLIENT[0].hpack_recv_binary = 0
D1027 18:15:46.878695473    4917 report.cc:106]              CLIENT[0].hpack_recv_binary_base64 = 0
D1027 18:15:46.878701857    4917 report.cc:106]              CLIENT[0].hpack_send_indexed = 0
D1027 18:15:46.878708148    4917 report.cc:106]              CLIENT[0].hpack_send_lithdr_incidx = 0
D1027 18:15:46.878721017    4917 report.cc:106]              CLIENT[0].hpack_send_lithdr_incidx_v = 13
D1027 18:15:46.878728499    4917 report.cc:106]              CLIENT[0].hpack_send_lithdr_notidx = 0
D1027 18:15:46.878735028    4917 report.cc:106]              CLIENT[0].hpack_send_lithdr_notidx_v = 0
D1027 18:15:46.878741291    4917 report.cc:106]              CLIENT[0].hpack_send_lithdr_nvridx = 0
D1027 18:15:46.878747575    4917 report.cc:106]              CLIENT[0].hpack_send_lithdr_nvridx_v = 0
D1027 18:15:46.878753971    4917 report.cc:106]              CLIENT[0].hpack_send_uncompressed = 26
D1027 18:15:46.878760172    4917 report.cc:106]              CLIENT[0].hpack_send_huffman = 0
D1027 18:15:46.878766369    4917 report.cc:106]              CLIENT[0].hpack_send_binary = 0
D1027 18:15:46.878772609    4917 report.cc:106]              CLIENT[0].hpack_send_binary_base64 = 0
D1027 18:15:46.878778869    4917 report.cc:106]              CLIENT[0].combiner_locks_initiated = 51
D1027 18:15:46.878785348    4917 report.cc:106]              CLIENT[0].combiner_locks_scheduled_items = 254
D1027 18:15:46.878792122    4917 report.cc:106]              CLIENT[0].combiner_locks_scheduled_final_items = 15
D1027 18:15:46.878798629    4917 report.cc:106]              CLIENT[0].combiner_locks_offloaded = 0
D1027 18:15:46.878805097    4917 report.cc:106]              CLIENT[0].call_combiner_locks_initiated = 26
D1027 18:15:46.878811643    4917 report.cc:106]              CLIENT[0].call_combiner_locks_scheduled_items = 30
D1027 18:15:46.878818083    4917 report.cc:106]              CLIENT[0].call_combiner_set_notify_on_cancel = 0
D1027 18:15:46.878824517    4917 report.cc:106]              CLIENT[0].call_combiner_cancelled = 1
D1027 18:15:46.878831049    4917 report.cc:106]              CLIENT[0].executor_scheduled_short_items = 2
D1027 18:15:46.878837495    4917 report.cc:106]              CLIENT[0].executor_scheduled_long_items = 0
D1027 18:15:46.878843762    4917 report.cc:106]              CLIENT[0].executor_scheduled_to_self = 0
D1027 18:15:46.878850438    4917 report.cc:106]              CLIENT[0].executor_wakeup_initiated = 2
D1027 18:15:46.878856858    4917 report.cc:106]              CLIENT[0].executor_queue_drained = 2
D1027 18:15:46.878863162    4917 report.cc:106]              CLIENT[0].executor_push_retries = 0
D1027 18:15:46.878869509    4917 report.cc:106]              CLIENT[0].server_requested_calls = 6
D1027 18:15:46.878875938    4917 report.cc:106]              CLIENT[0].server_slowpath_requests_queued = 0
D1027 18:15:46.878882389    4917 report.cc:106]              CLIENT[0].cq_ev_queue_trylock_failures = 0
D1027 18:15:46.878888866    4917 report.cc:106]              CLIENT[0].cq_ev_queue_trylock_successes = 34
D1027 18:15:46.878925418    4917 report.cc:106]              CLIENT[0].cq_ev_queue_transient_pop_failures = 0
D1027 18:15:46.878951628    4917 report.cc:110]              CLIENT[0].call_initial_size = 3620.5/6560.0/6645.6 (50/95/99%-ile)
D1027 18:15:46.878973003    4917 report.cc:110]              CLIENT[0].poll_events_returned = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.878993783    4917 report.cc:110]              CLIENT[0].tcp_write_size = 143.7/16049.5/16790.7 (50/95/99%-ile)
D1027 18:15:46.879012149    4917 report.cc:110]              CLIENT[0].tcp_write_iov_size = 2.5/21.0/21.8 (50/95/99%-ile)
D1027 18:15:46.879026339    4917 report.cc:110]              CLIENT[0].tcp_read_size = 9173.1/10265.1/10362.2 (50/95/99%-ile)
D1027 18:15:46.879037978    4917 report.cc:110]              CLIENT[0].tcp_read_offer = 9373.7/15215.6/16623.9 (50/95/99%-ile)
D1027 18:15:46.879053451    4917 report.cc:110]              CLIENT[0].tcp_read_offer_iov_size = 1.6/2.5/2.9 (50/95/99%-ile)
D1027 18:15:46.879065383    4917 report.cc:110]              CLIENT[0].http2_send_message_size = 6695.5/16605.4/16901.9 (50/95/99%-ile)
D1027 18:15:46.879074772    4917 report.cc:110]              CLIENT[0].http2_send_initial_metadata_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.879084122    4917 report.cc:110]              CLIENT[0].http2_send_message_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.879093531    4917 report.cc:110]              CLIENT[0].http2_send_trailing_metadata_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.879102731    4917 report.cc:110]              CLIENT[0].http2_send_flowctl_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.879111266    4917 report.cc:110]              CLIENT[0].server_cqs_checked = 0.5/0.9/1.0 (50/95/99%-ile)
D1027 18:15:46.880561284    4917 report.cc:106]              SERVER[0].client_calls_created = 0
D1027 18:15:46.880579638    4917 report.cc:106]              SERVER[0].server_calls_created = 2
D1027 18:15:46.880587619    4917 report.cc:106]              SERVER[0].cqs_created = 39
D1027 18:15:46.880594592    4917 report.cc:106]              SERVER[0].client_channels_created = 0
D1027 18:15:46.880601442    4917 report.cc:106]              SERVER[0].client_subchannels_created = 0
D1027 18:15:46.880608177    4917 report.cc:106]              SERVER[0].server_channels_created = 2
D1027 18:15:46.880614778    4917 report.cc:106]              SERVER[0].syscall_poll = 56
D1027 18:15:46.880621221    4917 report.cc:106]              SERVER[0].syscall_wait = 0
D1027 18:15:46.880627534    4917 report.cc:106]              SERVER[0].pollset_kick = 12
D1027 18:15:46.880634118    4917 report.cc:106]              SERVER[0].pollset_kicked_without_poller = 0
D1027 18:15:46.880640598    4917 report.cc:106]              SERVER[0].pollset_kicked_again = 0
D1027 18:15:46.880647034    4917 report.cc:106]              SERVER[0].pollset_kick_wakeup_fd = 0
D1027 18:15:46.880653567    4917 report.cc:106]              SERVER[0].pollset_kick_wakeup_cv = 0
D1027 18:15:46.880660094    4917 report.cc:106]              SERVER[0].pollset_kick_own_thread = 0
D1027 18:15:46.880666496    4917 report.cc:106]              SERVER[0].histogram_slow_lookups = 11
D1027 18:15:46.880673105    4917 report.cc:106]              SERVER[0].syscall_write = 18
D1027 18:15:46.880679544    4917 report.cc:106]              SERVER[0].syscall_read = 27
D1027 18:15:46.880685897    4917 report.cc:106]              SERVER[0].tcp_backup_pollers_created = 1
D1027 18:15:46.880692351    4917 report.cc:106]              SERVER[0].tcp_backup_poller_polls = 2
D1027 18:15:46.880698718    4917 report.cc:106]              SERVER[0].http2_op_batches = 12
D1027 18:15:46.880705196    4917 report.cc:106]              SERVER[0].http2_op_cancel = 1
D1027 18:15:46.880711791    4917 report.cc:106]              SERVER[0].http2_op_send_initial_metadata = 2
D1027 18:15:46.880726557    4917 report.cc:106]              SERVER[0].http2_op_send_message = 3
D1027 18:15:46.880733526    4917 report.cc:106]              SERVER[0].http2_op_send_trailing_metadata = 1
D1027 18:15:46.880740129    4917 report.cc:106]              SERVER[0].http2_op_recv_initial_metadata = 2
D1027 18:15:46.880746650    4917 report.cc:106]              SERVER[0].http2_op_recv_message = 4
D1027 18:15:46.880753156    4917 report.cc:106]              SERVER[0].http2_op_recv_trailing_metadata = 2
D1027 18:15:46.880759603    4917 report.cc:106]              SERVER[0].http2_settings_writes = 2
D1027 18:15:46.880766204    4917 report.cc:106]              SERVER[0].http2_pings_sent = 5
D1027 18:15:46.880772683    4917 report.cc:106]              SERVER[0].http2_writes_begun = 11
D1027 18:15:46.880779066    4917 report.cc:106]              SERVER[0].http2_writes_offloaded = 1
D1027 18:15:46.880785611    4917 report.cc:106]              SERVER[0].http2_writes_continued = 0
D1027 18:15:46.880792035    4917 report.cc:106]              SERVER[0].http2_partial_writes = 1
D1027 18:15:46.880804424    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_initial_write = 0
D1027 18:15:46.880811596    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_start_new_stream = 0
D1027 18:15:46.880818398    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_send_message = 1
D1027 18:15:46.880825030    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_send_initial_metadata = 2
D1027 18:15:46.880831918    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_send_trailing_metadata = 0
D1027 18:15:46.880838600    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_retry_send_ping = 0
D1027 18:15:46.880845115    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_continue_pings = 0
D1027 18:15:46.880851747    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_goaway_sent = 0
D1027 18:15:46.880861433    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_rst_stream = 0
D1027 18:15:46.880873177    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_close_from_api = 0
D1027 18:15:46.880885118    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_stream_flow_control = 0
D1027 18:15:46.880892838    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_transport_flow_control = 2
D1027 18:15:46.880899306    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_send_settings = 0
D1027 18:15:46.880907131    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_bdp_estimator_ping = 0
D1027 18:15:46.880919221    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_flow_control_unstalled_by_setting = 0
D1027 18:15:46.880930157    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_flow_control_unstalled_by_update = 0
D1027 18:15:46.880940227    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_application_ping = 0
D1027 18:15:46.880951070    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_keepalive_ping = 0
D1027 18:15:46.880961713    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_transport_flow_control_unstalled = 1
D1027 18:15:46.880968461    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_ping_response = 4
D1027 18:15:46.880974910    4917 report.cc:106]              SERVER[0].http2_initiate_write_due_to_force_rst_stream = 0
D1027 18:15:46.880981469    4917 report.cc:106]              SERVER[0].http2_spurious_writes_begun = 1
D1027 18:15:46.880987971    4917 report.cc:106]              SERVER[0].hpack_recv_indexed = 0
D1027 18:15:46.880994503    4917 report.cc:106]              SERVER[0].hpack_recv_lithdr_incidx = 0
D1027 18:15:46.881001113    4917 report.cc:106]              SERVER[0].hpack_recv_lithdr_incidx_v = 18
D1027 18:15:46.881007495    4917 report.cc:106]              SERVER[0].hpack_recv_lithdr_notidx = 0
D1027 18:15:46.881013916    4917 report.cc:106]              SERVER[0].hpack_recv_lithdr_notidx_v = 0
D1027 18:15:46.881020281    4917 report.cc:106]              SERVER[0].hpack_recv_lithdr_nvridx = 0
D1027 18:15:46.881026711    4917 report.cc:106]              SERVER[0].hpack_recv_lithdr_nvridx_v = 0
D1027 18:15:46.881033077    4917 report.cc:106]              SERVER[0].hpack_recv_uncompressed = 36
D1027 18:15:46.881039400    4917 report.cc:106]              SERVER[0].hpack_recv_huffman = 0
D1027 18:15:46.881045897    4917 report.cc:106]              SERVER[0].hpack_recv_binary = 0
D1027 18:15:46.881052421    4917 report.cc:106]              SERVER[0].hpack_recv_binary_base64 = 0
D1027 18:15:46.881058811    4917 report.cc:106]              SERVER[0].hpack_send_indexed = 0
D1027 18:15:46.881065177    4917 report.cc:106]              SERVER[0].hpack_send_lithdr_incidx = 0
D1027 18:15:46.881071586    4917 report.cc:106]              SERVER[0].hpack_send_lithdr_incidx_v = 8
D1027 18:15:46.881077923    4917 report.cc:106]              SERVER[0].hpack_send_lithdr_notidx = 0
D1027 18:15:46.881088623    4917 report.cc:106]              SERVER[0].hpack_send_lithdr_notidx_v = 0
D1027 18:15:46.881095250    4917 report.cc:106]              SERVER[0].hpack_send_lithdr_nvridx = 0
D1027 18:15:46.881101617    4917 report.cc:106]              SERVER[0].hpack_send_lithdr_nvridx_v = 0
D1027 18:15:46.881108018    4917 report.cc:106]              SERVER[0].hpack_send_uncompressed = 16
D1027 18:15:46.881114343    4917 report.cc:106]              SERVER[0].hpack_send_huffman = 0
D1027 18:15:46.881120526    4917 report.cc:106]              SERVER[0].hpack_send_binary = 0
D1027 18:15:46.881126810    4917 report.cc:106]              SERVER[0].hpack_send_binary_base64 = 0
D1027 18:15:46.881133257    4917 report.cc:106]              SERVER[0].combiner_locks_initiated = 50
D1027 18:15:46.881139870    4917 report.cc:106]              SERVER[0].combiner_locks_scheduled_items = 86
D1027 18:15:46.881146681    4917 report.cc:106]              SERVER[0].combiner_locks_scheduled_final_items = 21
D1027 18:15:46.881153189    4917 report.cc:106]              SERVER[0].combiner_locks_offloaded = 0
D1027 18:15:46.881159704    4917 report.cc:106]              SERVER[0].call_combiner_locks_initiated = 23
D1027 18:15:46.881166250    4917 report.cc:106]              SERVER[0].call_combiner_locks_scheduled_items = 29
D1027 18:15:46.881172831    4917 report.cc:106]              SERVER[0].call_combiner_set_notify_on_cancel = 1
D1027 18:15:46.881179387    4917 report.cc:106]              SERVER[0].call_combiner_cancelled = 1
D1027 18:15:46.881185997    4917 report.cc:106]              SERVER[0].executor_scheduled_short_items = 4
D1027 18:15:46.881192509    4917 report.cc:106]              SERVER[0].executor_scheduled_long_items = 2
D1027 18:15:46.881198967    4917 report.cc:106]              SERVER[0].executor_scheduled_to_self = 3
D1027 18:15:46.881205233    4917 report.cc:106]              SERVER[0].executor_wakeup_initiated = 6
D1027 18:15:46.881211590    4917 report.cc:106]              SERVER[0].executor_queue_drained = 6
D1027 18:15:46.881218071    4917 report.cc:106]              SERVER[0].executor_push_retries = 1
D1027 18:15:46.881224560    4917 report.cc:106]              SERVER[0].server_requested_calls = 640039
D1027 18:15:46.881230937    4917 report.cc:106]              SERVER[0].server_slowpath_requests_queued = 0
D1027 18:15:46.881237446    4917 report.cc:106]              SERVER[0].cq_ev_queue_trylock_failures = 0
D1027 18:15:46.881243877    4917 report.cc:106]              SERVER[0].cq_ev_queue_trylock_successes = 55
D1027 18:15:46.881250353    4917 report.cc:106]              SERVER[0].cq_ev_queue_transient_pop_failures = 0
D1027 18:15:46.881263826    4917 report.cc:110]              SERVER[0].call_initial_size = 6132.0/7813.6/7915.5 (50/95/99%-ile)
D1027 18:15:46.881275580    4917 report.cc:110]              SERVER[0].poll_events_returned = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.881287963    4917 report.cc:110]              SERVER[0].tcp_write_size = 205.0/3934886.8/4704565.4 (50/95/99%-ile)
D1027 18:15:46.881299307    4917 report.cc:110]              SERVER[0].tcp_write_iov_size = 2.5/489.8/517.2 (50/95/99%-ile)
D1027 18:15:46.881309936    4917 report.cc:110]              SERVER[0].tcp_read_size = 65.0/495.7/528.7 (50/95/99%-ile)
D1027 18:15:46.881321469    4917 report.cc:110]              SERVER[0].tcp_read_offer = 14891.4/16767.5/16934.3 (50/95/99%-ile)
D1027 18:15:46.881331713    4917 report.cc:110]              SERVER[0].tcp_read_offer_iov_size = 2.4/2.9/3.0 (50/95/99%-ile)
D1027 18:15:46.881361143    4917 report.cc:110]              SERVER[0].http2_send_message_size = 11821.5/9916186.8/10184741.3 (50/95/99%-ile)
D1027 18:15:46.881385847    4917 report.cc:110]              SERVER[0].http2_send_initial_metadata_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.881394667    4917 report.cc:110]              SERVER[0].http2_send_message_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.881403287    4917 report.cc:110]              SERVER[0].http2_send_trailing_metadata_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.881415384    4917 report.cc:110]              SERVER[0].http2_send_flowctl_per_write = 0.0/0.0/0.0 (50/95/99%-ile)
D1027 18:15:46.881423471    4917 report.cc:110]              SERVER[0].server_cqs_checked = 0.5/0.9/1.0 (50/95/99%-ile)
I1027 18:15:46.881435899    4917 report.cc:119]              QPS: 0.0 (0.0/server core)
I1027 18:15:46.881447590    4917 report.cc:124]              Latencies (50/90/95/99/99.9%-ile): 0.0/0.0/0.0/0.0/0.0 us
I1027 18:15:46.881457587    4917 report.cc:134]              Server system time: 3.11%
I1027 18:15:46.881469029    4917 report.cc:136]              Server user time:   43.73%
I1027 18:15:46.881481874    4917 report.cc:138]              Client system time: 0.00%
I1027 18:15:46.881492264    4917 report.cc:140]              Client user time:   24.38%
I1027 18:15:46.881501776    4917 report.cc:145]              Server CPU usage: 14.61%
I1027 18:15:46.881518858    4917 report.cc:150]              Client Polls per Request: -nan
I1027 18:15:46.881530736    4917 report.cc:152]              Server Polls per Request: inf
I1027 18:15:46.881552737    4917 report.cc:157]              Server Queries/CPU-sec: 0.00
I1027 18:15:46.881559977    4917 report.cc:159]              Client Queries/CPU-sec: 0.00
I1027 18:15:46.885313080    4904 json_run_localhost.cc:67]   driver: subprocess exited with status 1
D1027 18:15:47.558942434    4909 ev_posix.cc:135]            Using polling engine: epollsig
D1027 18:15:47.559042252    4909 dns_resolver.cc:306]        Using native dns resolver
I1027 18:15:47.680932580    4904 json_run_localhost.cc:70]   worker: subprocess terminated with signal 6
E1027 18:15:47.680976480    4904 json_run_localhost.cc:129]  assertion failed: driver_join_status == 0

2017-10-27 18:15:47,801 FAILED: json_run_localhost:cpp_protobuf_async_client_unary_1channel_64wide_128Breq_8MBresp_secure_low_thread_count GRPC_POLL_STRATEGY=epollsig [ret=-6, pid=4904, time=125.4sec]

https://sponge.corp.google.com/target?id=75a30064-0059-492e-a28f-c1d509694abc&target=grpc/ubuntu/pull_request/grpc_cpp_tsan&searchFor=&show=ALL&sortBy=STATUS

I suspect #13084 might be at fault.

Metadata

Metadata

Assignees

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions