Comments (11)
leewyang
commented on May 24, 2024
Ideally, all nodes should have similar setups/paths for LIB_HDFS and LIB_JVM, otherwise, it can be difficult to target the right paths in a distributed cluster (e.g. imagine if libhdfs.so was in a different location on every node of a 50 node cluster). That said, are you able to run a simple spark job that reads/writes to HDFS, e.g. sc.parallelize(...).saveAsTextFile(...)?
from tensorflowonspark.
sat2000pts
commented on May 24, 2024
hey lee thank you very much for the reply.
Yes I was able to run it -> as example I run the spark pi and word count example (given here: https://spark.apache.org/examples.html) and it works as well.
I am not sure if this is correct way to do it but I installed hadoop.3.2.1.tar and extracted/copied it to each of the worker containers so I can set the LIB_HDFS=hadoop_3.2.1/lib/native and also set exported the CLASSPATH manually on the works and it still gets stuck at tf.io.gfile.makedirs
from tensorflowonspark.
leewyang
commented on May 24, 2024
For the word count example, are you able to see the output "counts" file on HDFS from every node in the cluster, e.g. hadoop fs -text counts?
If you have tensorflow installed locally on each node, you can remove TFoS from the picture to simplify debugging, and just run a python shell to test the TF->HDFS connectivity, e.g.:
# python
import tensorflow as tf
from getpass import getuser
# test simple list dir
tf.io.gfile.listdir("hdfs:///user/{}".format(getuser()))
# test write file
test_file = "hdfs:///user/{}/test.txt".format(getuser())
with tf.io.gfile.GFile(test_file, "w") as f:
f.write("hello, world")
from tensorflowonspark.
sat2000pts
commented on May 24, 2024
Hey lee,
Yes I can see the output "counts" file and I can also run the example that you posted on each of the works. I can confirm that for both it works and I see the directories listed and the file written into hadoop.
I had some missing environment variable which I added and now it doesn't get stuck at line 54 tf.io.gfile.makedirs(args.model_dir) but instead at:
with strategy.scope():
multi_worker_model = build_and_compile_cnn_model()
So I enabled the NCCL_DEBUG=INFO and many other:
SparkContext.setSystemProperty('spark.executorEnv.GRPC_TRACE', 'all')
SparkContext.setSystemProperty('spark.executorEnv.GRPC_GO_LOG_SEVERITY_LEVEL', 'info')
SparkContext.setSystemProperty('spark.executorEnv.GRPC_VERBOSITY', 'DEBUG')
SparkContext.setSystemProperty('spark.executorEnv.GRPC_GO_LOG_VERBOSITY_LEVEL', '2')
and this is what I see in the one of the workers logs when it reaches that line of code:
I0422 12:14:21.282076267 4196 init.cc:165] grpc_init(void)
I0422 12:14:21.282125153 4196 init.cc:165] grpc_init(void)
I0422 12:14:21.282132855 4196 channel_create.cc:96] grpc_insecure_channel_create(target=dns:///172.18.0.4:39485, args=0x7f42e907d0b0, reserved=(nil))
I0422 12:14:21.282149731 4196 init.cc:165] grpc_init(void)
I0422 12:14:21.282175355 4196 client_channel.cc:1427] chand=0x7f432849c848: creating client_channel for channel stack 0x7f432849c7d8
I0422 12:14:21.282186701 4196 timer_generic.cc:365] TIMER 0x7f432849cb00: SET 11659 now 6659 call 0x7f432849cb30[0x7f43d50e2980]
I0422 12:14:21.282191597 4196 timer_generic.cc:402] .. add to shard 2 with queue_deadline_cap=7010 => is_first_timer=false
I0422 12:14:21.282227701 4196 init.cc:165] grpc_init(void)
I0422 12:14:21.282239102 4196 init.cc:212] grpc_shutdown(void)
I0422 12:14:21.282243883 4196 init.cc:212] grpc_shutdown(void)
I0422 12:14:21.282306183 4196 grpc_context.cc:28] grpc_census_call_set_context(call=0x7f432849e2a0, census_context=(nil))
I0422 12:14:21.282321247 4196 call.cc:1967] grpc_call_start_batch(call=0x7f432849e2a0, ops=0x7f42e907ce60, nops=6, tag=0x7f432849f128, reserved=(nil))
I0422 12:14:21.282328262 4196 call.cc:1565] ops[0]: SEND_INITIAL_METADATA(nil)
I0422 12:14:21.282332769 4196 call.cc:1565] ops[1]: SEND_MESSAGE ptr=0x7f432849fac0
I0422 12:14:21.282336473 4196 call.cc:1565] ops[2]: SEND_CLOSE_FROM_CLIENT
I0422 12:14:21.282340549 4196 call.cc:1565] ops[3]: RECV_INITIAL_METADATA ptr=0x7f432849e148
I0422 12:14:21.282344458 4196 call.cc:1565] ops[4]: RECV_MESSAGE ptr=0x7f432849f1c0
I0422 12:14:21.282350186 4196 call.cc:1565] ops[5]: RECV_STATUS_ON_CLIENT metadata=0x7f432849e198 status=0x7f432849f1f8 details=0x7f432849f200
I0422 12:14:21.283417394 4196 call.cc:626] OP[client-channel:0x7f432849ec00]: SEND_INITIAL_METADATA{key=3a 70 61 74 68 ':path' value=2f 74 65 6e 73 6f 72 66 6c 6f 77 2e 57 6f 72 6b 65 72 53 65 72 76 69 63 65 2f 43 6f 6d 70 6c 65 74 65 47 72 6f 75 70 '/tensorflow.WorkerService/CompleteGroup'} SEND_MESSAGE:flags=0x00000000:len=54 SEND_TRAILING_METADATA{} RECV_INITIAL_METADATA RECV_MESSAGE RECV_TRAILING_METADATA
I0422 12:14:21.283430226 4196 client_channel.cc:2314] chand=0x7f432849c848 calld=0x7f432849ec20: adding pending batch at index 0
I0422 12:14:21.283435177 4196 client_channel.cc:2141] chand=0x7f432849c848 calld=0x7f432849ec20: grabbing data plane mutex to perform pick
I0422 12:14:21.283439921 4196 connectivity_state.cc:173] ConnectivityStateTracker client_channel[0x7f432849c900]: get current state: IDLE
I0422 12:14:21.283444348 4196 client_channel.cc:3764] chand=0x7f432849c848 calld=0x7f432849ec20: adding to queued picks list
I0422 12:14:21.283478746 4196 resolving_lb_policy.cc:196] resolving_lb=0x7f432849bcd0: starting name resolution
I0422 12:14:21.283487194 4196 client_channel.cc:1332] chand=0x7f432849c848: update: state=CONNECTING picker=0x7f432849bf10
I0422 12:14:21.283491962 4196 connectivity_state.cc:151] ConnectivityStateTracker client_channel[0x7f432849c900]: IDLE -> CONNECTING (helper)
I0422 12:14:21.283501511 4196 client_channel.cc:3912] chand=0x7f432849c848 calld=0x7f432849ec20: LB pick returned QUEUE (subchannel=(nil), error="No Error")
D0422 12:14:21.283508424 4196 dns_resolver.cc:261] Start resolving.
I0422 12:14:21.283514324 4196 executor.cc:306] EXECUTOR (resolver-executor) try to schedule 0x7f43284a0c10 (short) to thread 0
I0422 12:14:21.283523363 4196 client_channel.cc:1606] chand=0x7f432849c848: created resolving_lb_policy=0x7f432849bcd0
I0422 12:14:21.283536169 4070 executor.cc:245] EXECUTOR (resolver-executor) [0]: execute
I0422 12:14:21.283546537 4070 executor.cc:124] EXECUTOR (resolver-executor) run 0x7f43284a0c10
I0422 12:14:21.283560414 4070 resolving_lb_policy.cc:440] resolving_lb=0x7f432849bcd0: got resolver result
I0422 12:14:21.283566308 4070 client_channel.cc:3777] chand=0x7f432849c848 calld=0x7f432849ec20: applying service config to call
I0422 12:14:21.283572397 4070 resolving_lb_policy.cc:338] resolving_lb=0x7f432849bcd0: Creating new child policy pick_first
I0422 12:14:21.283589424 4070 pick_first.cc:146] Pick First 0x7f436c012d90 created.
I0422 12:14:21.283594343 4070 resolving_lb_policy.cc:392] resolving_lb=0x7f432849bcd0: created new LB policy "pick_first" (0x7f436c012d90)
I0422 12:14:21.283599222 4070 resolving_lb_policy.cc:355] resolving_lb=0x7f432849bcd0: Updating child policy 0x7f436c012d90
I0422 12:14:21.283611076 4070 pick_first.cc:265] Pick First 0x7f436c012d90 received update with 1 addresses
I0422 12:14:21.283618123 4070 subchannel_list.h:360] [pick_first 0x7f436c012d90] Creating subchannel list 0x7f436c013250 for 1 subchannels
I0422 12:14:21.283668944 4070 client_channel.cc:852] chand=0x7f432849c848: creating subchannel wrapper 0x7f436c013420 for subchannel 0x7f436c013f60
I0422 12:14:21.283678457 4070 subchannel_list.h:410] [pick_first 0x7f436c012d90] subchannel list 0x7f436c013250 index 0: Created subchannel 0x7f436c013420 for address uri ipv4:172.18.0.4:39485
I0422 12:14:21.283684572 4070 subchannel_list.h:307] [pick_first 0x7f436c012d90] subchannel list 0x7f436c013250 index 0 of 1 (subchannel 0x7f436c013420): starting watch (from IDLE)
I0422 12:14:21.283692090 4070 client_channel.cc:1016] chand=0x7f432849c848: connectivity change for subchannel wrapper 0x7f436c013420 subchannel 0x7f436c013f60 (connected_subchannel=(nil) state=CONNECTING); hopping into combiner
I0422 12:14:21.283812001 4070 tcp_client_posix.cc:326] CLIENT_CONNECT: ipv4:172.18.0.4:39485: asynchronously connecting fd 0x7f436c012c40
I0422 12:14:21.283818827 4070 timer_generic.cc:365] TIMER 0x7f436c014f30: SET 26661 now 6661 call 0x7f436c014f60[0x7f43d513ae40]
I0422 12:14:21.283826976 4070 timer_generic.cc:402] .. add to shard 1 with queue_deadline_cap=7010 => is_first_timer=false
I0422 12:14:21.283836051 4070 client_channel.cc:1063] chand=0x7f432849c848: processing connectivity change in combiner for subchannel wrapper 0x7f436c013420 subchannel 0x7f436c013f60 (connected_subchannel=(nil) state=CONNECTING): watcher=0x7f436c013b40
I0422 12:14:21.283841926 4070 subchannel_list.h:240] [pick_first 0x7f436c012d90] subchannel list 0x7f436c013250 index 0 of 1 (subchannel 0x7f436c013420): connectivity changed: state=CONNECTING, shutting_down=0, pending_watcher=0x7f436c013b40
I0422 12:14:21.283846672 4070 client_channel.cc:1332] chand=0x7f432849c848: update: state=CONNECTING picker=0x7f436c013610
I0422 12:14:21.283852385 4070 client_channel.cc:3912] chand=0x7f432849c848 calld=0x7f432849ec20: LB pick returned QUEUE (subchannel=(nil), error="No Error")
I0422 12:14:21.283858165 4070 executor.cc:224] EXECUTOR (resolver-executor) [0]: step (sub_depth=1)
I0422 12:14:21.633368410 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:21.633393868 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=7011 next=9223372036854775807 tls_min=6011 glob_min=7011
I0422 12:14:21.633400506 4071 timer_generic.cc:612] .. shard[7]->min_deadline = 7011
I0422 12:14:21.633404837 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:21.633408817 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 8011
I0422 12:14:21.633412546 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:21.633416685 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633420964 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:21.633424498 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 8011
I0422 12:14:21.633428001 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:21.633431690 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633437685 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:21.633441520 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 8011
I0422 12:14:21.633444710 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:21.633448618 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633452327 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:21.633455912 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 8011
I0422 12:14:21.633459243 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:21.633463008 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633466624 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:21.633470257 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 8011
I0422 12:14:21.633473462 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:21.633477332 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633481061 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:21.633484393 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 8011
I0422 12:14:21.633488073 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:21.633491809 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633495908 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:21.633499224 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 8011
I0422 12:14:21.633503054 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:21.633506502 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633510409 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:21.633513747 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 8011
I0422 12:14:21.633517347 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:21.633520937 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 7011 --> 8012, now=7011
I0422 12:14:21.633524936 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=8012
I0422 12:14:21.633528554 4071 timer_manager.cc:188] sleep for a 1001 milliseconds
2021-04-22 12:14:21,961 INFO (MainThread-4181) Connected to TFSparkNode.mgr on 172.18.0.8, executor=1, state='running'
2021-04-22 12:14:21,975 INFO (MainThread-4181) mgr.state='running'
2021-04-22 12:14:21,976 INFO (MainThread-4181) Feeding partition <itertools.chain object at 0x7f43ec840f90> into input queue <multiprocessing.queues.JoinableQueue object at 0x7f43f887d9d0>
I0422 12:14:22.634388778 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:22.634423050 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=8012 next=9223372036854775807 tls_min=7011 glob_min=8012
I0422 12:14:22.634433092 4071 timer_generic.cc:612] .. shard[0]->min_deadline = 8012
I0422 12:14:22.634442425 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:22.634449954 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 9012
I0422 12:14:22.634458804 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:22.634465244 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634476381 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:22.634482323 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 9012
I0422 12:14:22.634490115 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:22.634499054 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634507493 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:22.634516246 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 9012
I0422 12:14:22.634523783 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:22.634532684 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634540354 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:22.634548953 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 9012
I0422 12:14:22.634554082 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:22.634564414 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634571145 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:22.634578942 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 9012
I0422 12:14:22.634587364 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:22.634594693 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634603684 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:22.634608067 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 9012
I0422 12:14:22.634611196 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:22.634618995 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634623808 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:22.634626812 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 9012
I0422 12:14:22.634629819 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:22.634633294 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634636253 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:22.634639276 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 9012
I0422 12:14:22.634641957 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:22.634644880 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 8012 --> 9013, now=8012
I0422 12:14:22.634648131 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=9013
I0422 12:14:22.634651433 4071 timer_manager.cc:188] sleep for a 1001 milliseconds
I0422 12:14:23.635473192 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:23.635529952 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=9013 next=9223372036854775807 tls_min=8012 glob_min=9013
I0422 12:14:23.635542375 4071 timer_generic.cc:612] .. shard[7]->min_deadline = 9013
I0422 12:14:23.635547286 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:23.635551485 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 10012
I0422 12:14:23.635555452 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:23.635559452 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 9013 --> 10013, now=9013
I0422 12:14:23.635563869 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:23.635567176 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 10012
I0422 12:14:23.635570718 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:23.635574390 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 9013 --> 10013, now=9013
I0422 12:14:23.635579109 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:23.635582469 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 10012
I0422 12:14:23.635585846 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:23.635589480 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 9013 --> 10013, now=9013
I0422 12:14:23.635592948 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:23.635596366 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 10012
I0422 12:14:23.635599569 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:23.635603530 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 9013 --> 10013, now=9013
I0422 12:14:23.635607291 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:23.635610716 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 10012
I0422 12:14:23.635614077 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:23.635617564 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 9013 --> 10013, now=9013
I0422 12:14:23.635621074 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:23.635624526 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 10013
I0422 12:14:23.635629177 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:23.635632861 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 9013 --> 10014, now=9013
I0422 12:14:23.635636521 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:23.635639950 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 10013
I0422 12:14:23.635643914 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:23.635647708 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 9013 --> 10014, now=9013
I0422 12:14:23.635651313 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:23.635654861 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 10012
I0422 12:14:23.635658410 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:23.635662111 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 9013 --> 10013, now=9013
I0422 12:14:23.635667470 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=10013
I0422 12:14:23.635671005 4071 timer_manager.cc:188] sleep for a 1000 milliseconds
I0422 12:14:24.635401273 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:24.635432037 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=10013 next=9223372036854775807 tls_min=9013 glob_min=10013
I0422 12:14:24.635438847 4071 timer_generic.cc:612] .. shard[0]->min_deadline = 10013
I0422 12:14:24.635443272 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:24.635447689 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 11012
I0422 12:14:24.635451903 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:24.635456523 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 10013 --> 11013, now=10013
I0422 12:14:24.635461175 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:24.635465263 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 11012
I0422 12:14:24.635469245 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:24.635473474 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 10013 --> 11013, now=10013
I0422 12:14:24.635477524 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:24.635481408 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 11012
I0422 12:14:24.635485273 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:24.635489459 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 10013 --> 11013, now=10013
I0422 12:14:24.635493518 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:24.635497413 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 11012
I0422 12:14:24.635501260 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:24.635505490 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 10013 --> 11013, now=10013
I0422 12:14:24.635509503 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:24.635513444 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 11012
I0422 12:14:24.635517347 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:24.635521549 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 10013 --> 11013, now=10013
I0422 12:14:24.635525672 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:24.635529524 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 11012
I0422 12:14:24.635533423 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:24.635537618 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 10013 --> 11013, now=10013
I0422 12:14:24.635542800 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=10014
I0422 12:14:24.635546988 4071 timer_manager.cc:188] sleep for a 1 milliseconds
I0422 12:14:24.636447356 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:24.636468445 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=10014 next=9223372036854775807 tls_min=10013 glob_min=10014
I0422 12:14:24.636473421 4071 timer_generic.cc:612] .. shard[1]->min_deadline = 10014
I0422 12:14:24.636477703 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:24.636481829 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 11014
I0422 12:14:24.636486323 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:24.636490867 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 10014 --> 11015, now=10014
I0422 12:14:24.636495327 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:24.636499282 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 11014
I0422 12:14:24.636503453 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:24.636507685 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 10014 --> 11015, now=10014
I0422 12:14:24.636512312 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=11013
I0422 12:14:24.636516371 4071 timer_manager.cc:188] sleep for a 999 milliseconds
I0422 12:14:25.635440564 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:25.635482819 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=11013 next=9223372036854775807 tls_min=10014 glob_min=11013
I0422 12:14:25.635490559 4071 timer_generic.cc:612] .. shard[7]->min_deadline = 11013
I0422 12:14:25.635495492 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:25.635500445 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 12013
I0422 12:14:25.635504980 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:25.635510056 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 11013 --> 12014, now=11013
I0422 12:14:25.635516523 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:25.635520807 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 12013
I0422 12:14:25.635525245 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:25.635529555 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 11013 --> 12014, now=11013
I0422 12:14:25.635534218 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:25.635538070 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 12013
I0422 12:14:25.635542258 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:25.635546496 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 11013 --> 12014, now=11013
I0422 12:14:25.635550888 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:25.635554666 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 12013
I0422 12:14:25.635558869 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:25.635563047 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 11013 --> 12014, now=11013
I0422 12:14:25.635567591 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:25.635571529 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 12013
I0422 12:14:25.635575827 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:25.635580159 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 11013 --> 12014, now=11013
I0422 12:14:25.635584424 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:25.635588496 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 12013
I0422 12:14:25.635592646 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:25.635597378 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 11013 --> 12014, now=11013
I0422 12:14:25.635601826 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=11015
I0422 12:14:25.635606268 4071 timer_manager.cc:188] sleep for a 2 milliseconds
I0422 12:14:25.638711957 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:25.639336409 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=11017 next=9223372036854775807 tls_min=11013 glob_min=11015
I0422 12:14:25.639346303 4071 timer_generic.cc:612] .. shard[2]->min_deadline = 11015
I0422 12:14:25.639351436 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:25.639356253 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 12017
I0422 12:14:25.639360474 4071 timer_generic.cc:518] .. add timer with deadline 11659 to heap
I0422 12:14:25.639365264 4071 timer_generic.cc:545] .. check top timer deadline=11659 now=11017
I0422 12:14:25.639369879 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:25.639374305 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 11015 --> 11659, now=11017
I0422 12:14:25.639379319 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:25.639383298 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 12017
I0422 12:14:25.639387853 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:25.639392303 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 11015 --> 12018, now=11017
I0422 12:14:25.639397090 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=11659
I0422 12:14:25.639401745 4071 timer_manager.cc:188] sleep for a 642 milliseconds
I0422 12:14:26.281353629 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:26.281381188 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=11659 next=9223372036854775807 tls_min=11015 glob_min=11659
I0422 12:14:26.281387827 4071 timer_generic.cc:612] .. shard[2]->min_deadline = 11659
I0422 12:14:26.281392861 4071 timer_generic.cc:535] .. shard[2]: heap_empty=false
I0422 12:14:26.281397342 4071 timer_generic.cc:545] .. check top timer deadline=11659 now=11659
I0422 12:14:26.281402038 4071 timer_generic.cc:551] TIMER 0x7f432849cb00: FIRE 0ms late
I0422 12:14:26.281406686 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:26.281410948 4071 timer_generic.cc:575] .. shard[2] popped 1
I0422 12:14:26.281415873 4071 timer_generic.cc:630] .. result --> 2, shard[2]->min_deadline 11659 --> 12018, now=11659
I0422 12:14:26.281420916 4071 timer_generic.cc:740] TIMER CHECK END: r=2; next=12014
I0422 12:14:26.281425475 4071 timer_manager.cc:88] Spawn timer thread
I0422 12:14:26.281504162 4071 timer_manager.cc:132] flush exec_ctx
I0422 12:14:26.281516707 4071 timer_generic.cc:365] TIMER 0x7f432849cb00: SET 16659 now 11659 call 0x7f432849cb30[0x7f43d50e2980]
I0422 12:14:26.281521623 4071 timer_generic.cc:402] .. add to shard 2 with queue_deadline_cap=12017 => is_first_timer=false
I0422 12:14:26.281527433 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=11659 next=9223372036854775807 tls_min=11659 glob_min=12014
I0422 12:14:26.281532368 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=12014
I0422 12:14:26.281536488 4071 timer_manager.cc:188] sleep for a 355 milliseconds
I0422 12:14:26.284043548 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=11661 next=9223372036854775807 tls_min=0 glob_min=12014
I0422 12:14:26.284161643 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=12014
I0422 12:14:26.285137385 4215 timer_manager.cc:197] sleep until kicked
I0422 12:14:26.636388413 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:26.636419231 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=12014 next=9223372036854775807 tls_min=12014 glob_min=12014
I0422 12:14:26.636425559 4071 timer_generic.cc:612] .. shard[0]->min_deadline = 12014
I0422 12:14:26.636430409 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:26.636434707 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 13014
I0422 12:14:26.636439220 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:26.636443601 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 12014 --> 13015, now=12014
I0422 12:14:26.636448071 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:26.636452013 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 13014
I0422 12:14:26.636456072 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:26.636460540 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 12014 --> 13015, now=12014
I0422 12:14:26.636464824 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:26.636471453 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 13014
I0422 12:14:26.636478687 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:26.636483680 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 12014 --> 13015, now=12014
I0422 12:14:26.636488582 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:26.636492635 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 13014
I0422 12:14:26.636496595 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:26.636500807 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 12014 --> 13015, now=12014
I0422 12:14:26.636504849 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:26.636508652 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 13014
I0422 12:14:26.636512425 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:26.636516609 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 12014 --> 13015, now=12014
I0422 12:14:26.636520579 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:26.636524165 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 13014
I0422 12:14:26.636528015 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:26.636532200 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 12014 --> 13015, now=12014
I0422 12:14:26.636536933 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=12018
I0422 12:14:26.636540950 4071 timer_manager.cc:188] sleep for a 4 milliseconds
I0422 12:14:26.640353550 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:26.640378083 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=12018 next=9223372036854775807 tls_min=12014 glob_min=12018
I0422 12:14:26.640384528 4071 timer_generic.cc:612] .. shard[2]->min_deadline = 12018
I0422 12:14:26.640388949 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:26.640393401 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 13018
I0422 12:14:26.640398007 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:26.640402647 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 12018 --> 13019, now=12018
I0422 12:14:26.640407554 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:26.640411725 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 13018
I0422 12:14:26.640416098 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:26.640420524 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 12018 --> 13019, now=12018
I0422 12:14:26.640425445 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=13015
I0422 12:14:26.640430125 4071 timer_manager.cc:188] sleep for a 997 milliseconds
I0422 12:14:27.637402475 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:27.637442478 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=13015 next=9223372036854775807 tls_min=12018 glob_min=13015
I0422 12:14:27.637457448 4071 timer_generic.cc:612] .. shard[7]->min_deadline = 13015
I0422 12:14:27.637467519 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:27.637477767 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 14014
I0422 12:14:27.637484980 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:27.637494384 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 13015 --> 14015, now=13015
I0422 12:14:27.637505299 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:27.637514326 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 14014
I0422 12:14:27.637524369 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:27.637533062 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 13015 --> 14015, now=13015
I0422 12:14:27.637543730 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:27.637549629 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 14014
I0422 12:14:27.637561811 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:27.637569537 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 13015 --> 14015, now=13015
I0422 12:14:27.637578893 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:27.637588979 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 14014
I0422 12:14:27.637597587 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:27.637608130 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 13015 --> 14015, now=13015
I0422 12:14:27.637617018 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:27.637627084 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 14014
I0422 12:14:27.637633228 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:27.637645063 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 13015 --> 14015, now=13015
I0422 12:14:27.637653223 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:27.637662075 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 14014
I0422 12:14:27.637672110 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:27.637680931 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 13015 --> 14015, now=13015
I0422 12:14:27.637688289 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=13019
I0422 12:14:27.637692667 4071 timer_manager.cc:188] sleep for a 4 milliseconds
I0422 12:14:27.641403406 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:27.641436725 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=13019 next=9223372036854775807 tls_min=13015 glob_min=13019
I0422 12:14:27.641443690 4071 timer_generic.cc:612] .. shard[1]->min_deadline = 13019
I0422 12:14:27.641448362 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:27.641452620 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 14019
I0422 12:14:27.641460130 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:27.641467946 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 13019 --> 14020, now=13019
I0422 12:14:27.641476188 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:27.641486498 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 14019
I0422 12:14:27.641494626 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:27.641507506 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 13019 --> 14020, now=13019
I0422 12:14:27.641515583 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=14015
I0422 12:14:27.641527507 4071 timer_manager.cc:188] sleep for a 996 milliseconds
I0422 12:14:28.637408905 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:28.637463811 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=14015 next=9223372036854775807 tls_min=13019 glob_min=14015
I0422 12:14:28.637472197 4071 timer_generic.cc:612] .. shard[0]->min_deadline = 14015
I0422 12:14:28.637477905 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:28.637483375 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 15015
I0422 12:14:28.637488615 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:28.637493528 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 14015 --> 15016, now=14015
I0422 12:14:28.637501207 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:28.637505906 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 15015
I0422 12:14:28.637510165 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:28.637515007 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 14015 --> 15016, now=14015
I0422 12:14:28.637520095 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:28.637524663 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 15015
I0422 12:14:28.637528720 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:28.637533722 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 14015 --> 15016, now=14015
I0422 12:14:28.637538333 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:28.637542392 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 15015
I0422 12:14:28.637546669 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:28.637551135 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 14015 --> 15016, now=14015
I0422 12:14:28.637555624 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:28.637559510 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 15015
I0422 12:14:28.637564898 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:28.637569394 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 14015 --> 15016, now=14015
I0422 12:14:28.637574239 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:28.637578508 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 15015
I0422 12:14:28.637582838 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:28.637587195 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 14015 --> 15016, now=14015
I0422 12:14:28.637592215 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=14020
I0422 12:14:28.637597095 4071 timer_manager.cc:188] sleep for a 5 milliseconds
I0422 12:14:28.642390478 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:28.642415174 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=14020 next=9223372036854775807 tls_min=14015 glob_min=14020
I0422 12:14:28.642421546 4071 timer_generic.cc:612] .. shard[2]->min_deadline = 14020
I0422 12:14:28.642426352 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:28.642431283 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 15020
I0422 12:14:28.642435869 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:28.642440804 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 14020 --> 15021, now=14020
I0422 12:14:28.642445321 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:28.642449715 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 15020
I0422 12:14:28.642454059 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:28.642458904 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 14020 --> 15021, now=14020
I0422 12:14:28.642464056 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=15016
I0422 12:14:28.642468237 4071 timer_manager.cc:188] sleep for a 996 milliseconds
I0422 12:14:29.638412247 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:29.638456289 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=15016 next=9223372036854775807 tls_min=14020 glob_min=15016
I0422 12:14:29.638464041 4071 timer_generic.cc:612] .. shard[7]->min_deadline = 15016
I0422 12:14:29.638469312 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:29.638475333 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 16016
I0422 12:14:29.638479923 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:29.638485162 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 15016 --> 16017, now=15016
I0422 12:14:29.638491970 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:29.638496689 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 16016
I0422 12:14:29.638501186 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:29.638505523 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 15016 --> 16017, now=15016
I0422 12:14:29.638510227 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:29.638514632 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 16016
I0422 12:14:29.638519214 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:29.638523713 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 15016 --> 16017, now=15016
I0422 12:14:29.638528142 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:29.638532540 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 16016
I0422 12:14:29.638536329 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:29.638540586 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 15016 --> 16017, now=15016
I0422 12:14:29.638545126 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:29.638549911 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 16016
I0422 12:14:29.638553781 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:29.638558548 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 15016 --> 16017, now=15016
I0422 12:14:29.638562842 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:29.638567266 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 16016
I0422 12:14:29.638571225 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:29.638575783 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 15016 --> 16017, now=15016
I0422 12:14:29.638580437 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=15021
I0422 12:14:29.638584971 4071 timer_manager.cc:188] sleep for a 5 milliseconds
I0422 12:14:29.643398107 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:29.643422676 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=15021 next=9223372036854775807 tls_min=15016 glob_min=15021
I0422 12:14:29.643429694 4071 timer_generic.cc:612] .. shard[1]->min_deadline = 15021
I0422 12:14:29.643434140 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:29.643438815 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 16021
I0422 12:14:29.643443416 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:29.643448388 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 15021 --> 16022, now=15021
I0422 12:14:29.643453426 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:29.643457318 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 16021
I0422 12:14:29.643462018 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:29.643466273 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 15021 --> 16022, now=15021
I0422 12:14:29.643471300 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=16017
I0422 12:14:29.643475349 4071 timer_manager.cc:188] sleep for a 996 milliseconds
I0422 12:14:30.639376020 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:30.639406162 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=16017 next=9223372036854775807 tls_min=15021 glob_min=16017
I0422 12:14:30.639413236 4071 timer_generic.cc:612] .. shard[0]->min_deadline = 16017
I0422 12:14:30.639417956 4071 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:30.639422456 4071 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 17017
I0422 12:14:30.639426850 4071 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:30.639431606 4071 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 16017 --> 17018, now=16017
I0422 12:14:30.639436656 4071 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:30.639443834 4071 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 17017
I0422 12:14:30.639451043 4071 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:30.639455814 4071 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 16017 --> 17018, now=16017
I0422 12:14:30.639460208 4071 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:30.639464493 4071 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 17017
I0422 12:14:30.639468524 4071 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:30.639473230 4071 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 16017 --> 17018, now=16017
I0422 12:14:30.639477466 4071 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:30.639481731 4071 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 17017
I0422 12:14:30.639485605 4071 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:30.639490294 4071 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 16017 --> 17018, now=16017
I0422 12:14:30.639494575 4071 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:30.639498612 4071 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 17017
I0422 12:14:30.639502956 4071 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:30.639507045 4071 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 16017 --> 17018, now=16017
I0422 12:14:30.639511610 4071 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:30.639515679 4071 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 17017
I0422 12:14:30.639519918 4071 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:30.639524094 4071 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 16017 --> 17018, now=16017
I0422 12:14:30.639529141 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=16022
I0422 12:14:30.639533552 4071 timer_manager.cc:188] sleep for a 5 milliseconds
I0422 12:14:30.644344668 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:30.644368581 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=16022 next=9223372036854775807 tls_min=16017 glob_min=16022
I0422 12:14:30.644374423 4071 timer_generic.cc:612] .. shard[2]->min_deadline = 16022
I0422 12:14:30.644379047 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:30.644383368 4071 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 17022
I0422 12:14:30.644387444 4071 timer_generic.cc:518] .. add timer with deadline 16659 to heap
I0422 12:14:30.644391468 4071 timer_generic.cc:545] .. check top timer deadline=16659 now=16022
I0422 12:14:30.644395488 4071 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:30.644399822 4071 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 16022 --> 16659, now=16022
I0422 12:14:30.644404458 4071 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:30.644408269 4071 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 17022
I0422 12:14:30.644412176 4071 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:30.644416344 4071 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 16022 --> 17023, now=16022
I0422 12:14:30.644420992 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=16659
I0422 12:14:30.644425015 4071 timer_manager.cc:188] sleep for a 637 milliseconds
I0422 12:14:31.281346221 4071 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:31.281374371 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=16659 next=9223372036854775807 tls_min=16022 glob_min=16659
I0422 12:14:31.281380903 4071 timer_generic.cc:612] .. shard[2]->min_deadline = 16659
I0422 12:14:31.281385688 4071 timer_generic.cc:535] .. shard[2]: heap_empty=false
I0422 12:14:31.281390384 4071 timer_generic.cc:545] .. check top timer deadline=16659 now=16659
I0422 12:14:31.281394627 4071 timer_generic.cc:551] TIMER 0x7f432849cb00: FIRE 0ms late
I0422 12:14:31.281399442 4071 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:31.281403651 4071 timer_generic.cc:575] .. shard[2] popped 1
I0422 12:14:31.281408535 4071 timer_generic.cc:630] .. result --> 2, shard[2]->min_deadline 16659 --> 17023, now=16659
I0422 12:14:31.281413804 4071 timer_generic.cc:740] TIMER CHECK END: r=2; next=17018
I0422 12:14:31.281418147 4071 timer_manager.cc:124] kick untimed waiter
I0422 12:14:31.281428324 4071 timer_manager.cc:132] flush exec_ctx
I0422 12:14:31.281439405 4071 timer_generic.cc:365] TIMER 0x7f432849cb00: SET 21659 now 16659 call 0x7f432849cb30[0x7f43d50e2980]
I0422 12:14:31.281444858 4071 timer_generic.cc:402] .. add to shard 2 with queue_deadline_cap=17022 => is_first_timer=false
I0422 12:14:31.281439615 4215 timer_manager.cc:204] wait ended: was_timed:0 kicked:0
I0422 12:14:31.281475609 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=16659 next=9223372036854775807 tls_min=12014 glob_min=17018
I0422 12:14:31.281482921 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=17018
I0422 12:14:31.281487657 4215 timer_manager.cc:188] sleep for a 359 milliseconds
I0422 12:14:31.281502440 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=16659 next=9223372036854775807 tls_min=16659 glob_min=17018
I0422 12:14:31.281511856 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=17018
I0422 12:14:31.281516044 4071 timer_manager.cc:197] sleep until kicked
I0422 12:14:31.640359331 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:31.640387703 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=17018 next=9223372036854775807 tls_min=17018 glob_min=17018
I0422 12:14:31.640394864 4215 timer_generic.cc:612] .. shard[7]->min_deadline = 17018
I0422 12:14:31.640399487 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:31.640403857 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 18018
I0422 12:14:31.640408454 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:31.640413052 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 17018 --> 18019, now=17018
I0422 12:14:31.640417354 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:31.640421277 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 18018
I0422 12:14:31.640425217 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:31.640429518 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 17018 --> 18019, now=17018
I0422 12:14:31.640433620 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:31.640437495 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 18018
I0422 12:14:31.640441356 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:31.640445682 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 17018 --> 18019, now=17018
I0422 12:14:31.640449754 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:31.640453640 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 18018
I0422 12:14:31.640457554 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:31.640461791 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 17018 --> 18019, now=17018
I0422 12:14:31.640465817 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:31.640469674 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 18018
I0422 12:14:31.640473594 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:31.640477851 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 17018 --> 18019, now=17018
I0422 12:14:31.640481932 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:31.640485875 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 18018
I0422 12:14:31.640489878 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:31.640494239 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 17018 --> 18019, now=17018
I0422 12:14:31.640498768 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=17023
I0422 12:14:31.640502808 4215 timer_manager.cc:188] sleep for a 5 milliseconds
I0422 12:14:31.645349640 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:31.645376578 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=17023 next=9223372036854775807 tls_min=17018 glob_min=17023
I0422 12:14:31.645383035 4215 timer_generic.cc:612] .. shard[2]->min_deadline = 17023
I0422 12:14:31.645387326 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:31.645391678 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 18023
I0422 12:14:31.645396111 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:31.645400551 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 17023 --> 18024, now=17023
I0422 12:14:31.645405038 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:31.645409001 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 18023
I0422 12:14:31.645413027 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:31.645417257 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 17023 --> 18024, now=17023
I0422 12:14:31.645421766 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=18019
I0422 12:14:31.645425656 4215 timer_manager.cc:188] sleep for a 996 milliseconds
I0422 12:14:32.641350476 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:32.641380246 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=18019 next=9223372036854775807 tls_min=17023 glob_min=18019
I0422 12:14:32.641394333 4215 timer_generic.cc:612] .. shard[0]->min_deadline = 18019
I0422 12:14:32.641401773 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:32.641406610 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 19019
I0422 12:14:32.641411031 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:32.641416188 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 18019 --> 19020, now=18019
I0422 12:14:32.641421676 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:32.641425747 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 19019
I0422 12:14:32.641429923 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:32.641434532 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 18019 --> 19020, now=18019
I0422 12:14:32.641439405 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:32.641443556 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 19019
I0422 12:14:32.641448125 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:32.641452432 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 18019 --> 19020, now=18019
I0422 12:14:32.641457260 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:32.641461334 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 19019
I0422 12:14:32.641465761 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:32.641470064 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 18019 --> 19020, now=18019
I0422 12:14:32.641474633 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:32.641478688 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 19019
I0422 12:14:32.641483075 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:32.641487459 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 18019 --> 19020, now=18019
I0422 12:14:32.641492181 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:32.641496178 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 19019
I0422 12:14:32.641500590 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:32.641510198 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 18019 --> 19020, now=18019
I0422 12:14:32.641516647 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=18024
I0422 12:14:32.641521139 4215 timer_manager.cc:188] sleep for a 5 milliseconds
I0422 12:14:32.646410838 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:32.646436009 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=18024 next=9223372036854775807 tls_min=18019 glob_min=18024
I0422 12:14:32.646563830 4215 timer_generic.cc:612] .. shard[1]->min_deadline = 18024
I0422 12:14:32.646572402 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:32.646577210 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 19024
I0422 12:14:32.646581885 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:32.646586615 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 18024 --> 19025, now=18024
I0422 12:14:32.646591408 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:32.646595445 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 19024
I0422 12:14:32.646599559 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:32.646603671 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 18024 --> 19025, now=18024
I0422 12:14:32.646608498 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=19020
I0422 12:14:32.646617366 4215 timer_manager.cc:188] sleep for a 996 milliseconds
I0422 12:14:33.642387406 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:33.642414658 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=19020 next=9223372036854775807 tls_min=18024 glob_min=19020
I0422 12:14:33.642421253 4215 timer_generic.cc:612] .. shard[7]->min_deadline = 19020
I0422 12:14:33.642426266 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:33.642430453 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 20020
I0422 12:14:33.642434818 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:33.642439632 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 19020 --> 20021, now=19020
I0422 12:14:33.642444366 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:33.642448513 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 20020
I0422 12:14:33.642452246 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:33.642456585 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 19020 --> 20021, now=19020
I0422 12:14:33.642460634 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:33.642464796 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 20020
I0422 12:14:33.642468498 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:33.642472869 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 19020 --> 20021, now=19020
I0422 12:14:33.642476899 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:33.642480761 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 20020
I0422 12:14:33.642484691 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:33.642488854 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 19020 --> 20021, now=19020
I0422 12:14:33.642493185 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:33.642496864 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 20020
I0422 12:14:33.642500993 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:33.642505042 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 19020 --> 20021, now=19020
I0422 12:14:33.642509369 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:33.642513111 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 20020
I0422 12:14:33.642517202 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:33.642521258 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 19020 --> 20021, now=19020
I0422 12:14:33.642526035 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=19025
I0422 12:14:33.642529980 4215 timer_manager.cc:188] sleep for a 5 milliseconds
I0422 12:14:33.647342090 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:33.647356285 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=19025 next=9223372036854775807 tls_min=19020 glob_min=19025
I0422 12:14:33.647361543 4215 timer_generic.cc:612] .. shard[2]->min_deadline = 19025
I0422 12:14:33.647365637 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:33.647369714 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 20025
I0422 12:14:33.647374146 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:33.647378219 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 19025 --> 20026, now=19025
I0422 12:14:33.647382866 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:33.647386595 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 20025
I0422 12:14:33.647390859 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:33.647394907 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 19025 --> 20026, now=19025
I0422 12:14:33.647399503 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=20021
I0422 12:14:33.647403275 4215 timer_manager.cc:188] sleep for a 996 milliseconds
I0422 12:14:34.643350438 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:34.643377278 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=20021 next=9223372036854775807 tls_min=19025 glob_min=20021
I0422 12:14:34.643383898 4215 timer_generic.cc:612] .. shard[0]->min_deadline = 20021
I0422 12:14:34.643388463 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:34.643393107 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 21020
I0422 12:14:34.643397610 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:34.643402073 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 20021 --> 21021, now=20021
I0422 12:14:34.643407061 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:34.643411160 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 21020
I0422 12:14:34.643415208 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:34.643419701 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 20021 --> 21021, now=20021
I0422 12:14:34.643423707 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:34.643427836 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 21020
I0422 12:14:34.643431520 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:34.643436038 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 20021 --> 21021, now=20021
I0422 12:14:34.643440050 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:34.643444061 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 21020
I0422 12:14:34.643447833 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:34.643452209 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 20021 --> 21021, now=20021
I0422 12:14:34.643456145 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:34.643460271 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 21020
I0422 12:14:34.643463954 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:34.643468320 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 20021 --> 21021, now=20021
I0422 12:14:34.643472405 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:34.643476294 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 21020
I0422 12:14:34.643480275 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:34.643484469 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 20021 --> 21021, now=20021
I0422 12:14:34.643489208 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=20026
I0422 12:14:34.643493130 4215 timer_manager.cc:188] sleep for a 5 milliseconds
I0422 12:14:34.648347279 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:34.648362789 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=20026 next=9223372036854775807 tls_min=20021 glob_min=20026
I0422 12:14:34.648367864 4215 timer_generic.cc:612] .. shard[1]->min_deadline = 20026
I0422 12:14:34.648372203 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:34.648376157 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 21026
I0422 12:14:34.648380432 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:34.648384555 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 20026 --> 21027, now=20026
I0422 12:14:34.648389255 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:34.648393224 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 21026
I0422 12:14:34.648397353 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:34.648401831 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 20026 --> 21027, now=20026
I0422 12:14:34.648407477 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=21021
I0422 12:14:34.648411774 4215 timer_manager.cc:188] sleep for a 995 milliseconds
I0422 12:14:35.643348831 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:35.643375182 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=21021 next=9223372036854775807 tls_min=20026 glob_min=21021
I0422 12:14:35.643381716 4215 timer_generic.cc:612] .. shard[7]->min_deadline = 21021
I0422 12:14:35.643386302 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:35.643391136 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 22021
I0422 12:14:35.643395229 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:35.643400166 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 21021 --> 22022, now=21021
I0422 12:14:35.643404867 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:35.643409220 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 22021
I0422 12:14:35.643413081 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:35.643417701 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 21021 --> 22022, now=21021
I0422 12:14:35.643421975 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:35.643425957 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 22021
I0422 12:14:35.643430037 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:35.643434418 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 21021 --> 22022, now=21021
I0422 12:14:35.643438549 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:35.643442623 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 22021
I0422 12:14:35.643446636 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:35.643450956 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 21021 --> 22022, now=21021
I0422 12:14:35.643455393 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:35.643459219 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 22021
I0422 12:14:35.643463518 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:35.643467606 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 21021 --> 22022, now=21021
I0422 12:14:35.643472162 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:35.643475996 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 22021
I0422 12:14:35.643480286 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:35.643484432 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 21021 --> 22022, now=21021
I0422 12:14:35.643489382 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=21027
I0422 12:14:35.643493486 4215 timer_manager.cc:188] sleep for a 6 milliseconds
I0422 12:14:35.649347867 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:35.649366638 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=21027 next=9223372036854775807 tls_min=21021 glob_min=21027
I0422 12:14:35.649372277 4215 timer_generic.cc:612] .. shard[2]->min_deadline = 21027
I0422 12:14:35.649376354 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:35.649380791 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 22027
I0422 12:14:35.649384890 4215 timer_generic.cc:518] .. add timer with deadline 21659 to heap
I0422 12:14:35.649389474 4215 timer_generic.cc:545] .. check top timer deadline=21659 now=21027
I0422 12:14:35.649393510 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:35.649398259 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 21027 --> 21659, now=21027
I0422 12:14:35.649402831 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:35.649406964 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 22027
I0422 12:14:35.649411228 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:35.649415676 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 21027 --> 22028, now=21027
I0422 12:14:35.649420918 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=21659
I0422 12:14:35.649424955 4215 timer_manager.cc:188] sleep for a 632 milliseconds
I0422 12:14:36.281350272 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:36.281374965 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=21659 next=9223372036854775807 tls_min=21027 glob_min=21659
I0422 12:14:36.281381464 4215 timer_generic.cc:612] .. shard[2]->min_deadline = 21659
I0422 12:14:36.281386016 4215 timer_generic.cc:535] .. shard[2]: heap_empty=false
I0422 12:14:36.281390948 4215 timer_generic.cc:545] .. check top timer deadline=21659 now=21659
I0422 12:14:36.281395089 4215 timer_generic.cc:551] TIMER 0x7f432849cb00: FIRE 0ms late
I0422 12:14:36.281399550 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:36.281403651 4215 timer_generic.cc:575] .. shard[2] popped 1
I0422 12:14:36.281408660 4215 timer_generic.cc:630] .. result --> 2, shard[2]->min_deadline 21659 --> 22028, now=21659
I0422 12:14:36.281413950 4215 timer_generic.cc:740] TIMER CHECK END: r=2; next=22022
I0422 12:14:36.281417878 4215 timer_manager.cc:124] kick untimed waiter
I0422 12:14:36.281425478 4215 timer_manager.cc:132] flush exec_ctx
I0422 12:14:36.281435481 4215 timer_generic.cc:365] TIMER 0x7f432849cb00: SET 26659 now 21659 call 0x7f432849cb30[0x7f43d50e2980]
I0422 12:14:36.281440142 4215 timer_generic.cc:402] .. add to shard 2 with queue_deadline_cap=22027 => is_first_timer=false
I0422 12:14:36.281445766 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=21659 next=9223372036854775807 tls_min=21659 glob_min=22022
I0422 12:14:36.281450162 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=22022
I0422 12:14:36.281454286 4215 timer_manager.cc:188] sleep for a 363 milliseconds
I0422 12:14:36.281512624 4071 timer_manager.cc:204] wait ended: was_timed:0 kicked:0
I0422 12:14:36.281527961 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=21659 next=9223372036854775807 tls_min=17018 glob_min=22022
I0422 12:14:36.281533058 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=22022
I0422 12:14:36.281537149 4071 timer_manager.cc:197] sleep until kicked
I0422 12:14:36.650396669 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:36.650427318 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=22028 next=9223372036854775807 tls_min=22022 glob_min=22022
I0422 12:14:36.650434083 4215 timer_generic.cc:612] .. shard[0]->min_deadline = 22022
I0422 12:14:36.650438598 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:36.650443391 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 23027
I0422 12:14:36.650447776 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:36.650452583 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 22022 --> 23028, now=22028
I0422 12:14:36.650457690 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:36.650461772 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 23027
I0422 12:14:36.650466171 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:36.650470602 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 22022 --> 23028, now=22028
I0422 12:14:36.650475118 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:36.650479064 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 23027
I0422 12:14:36.650483299 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:36.650487518 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 22022 --> 23028, now=22028
I0422 12:14:36.650491971 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:36.650496071 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 23027
I0422 12:14:36.650500153 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:36.650504858 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 22022 --> 23028, now=22028
I0422 12:14:36.650508792 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:36.650513173 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 23027
I0422 12:14:36.650516964 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:36.650521591 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 22022 --> 23028, now=22028
I0422 12:14:36.650525626 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:36.650529834 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 23027
I0422 12:14:36.650533631 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:36.650538146 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 22022 --> 23028, now=22028
I0422 12:14:36.650542171 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:36.650546476 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 23028
I0422 12:14:36.650550626 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:36.650555185 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 22028 --> 23029, now=22028
I0422 12:14:36.650559508 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:36.650563540 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 23028
I0422 12:14:36.650567737 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:36.650572129 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 22028 --> 23029, now=22028
I0422 12:14:36.650577082 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=23028
I0422 12:14:36.650581152 4215 timer_manager.cc:188] sleep for a 1000 milliseconds
I0422 12:14:37.650386997 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:37.650414498 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=23028 next=9223372036854775807 tls_min=22022 glob_min=23028
I0422 12:14:37.650420738 4215 timer_generic.cc:612] .. shard[7]->min_deadline = 23028
I0422 12:14:37.650425334 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:37.650429954 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 24027
I0422 12:14:37.650434025 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:37.650438921 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 23028 --> 24028, now=23028
I0422 12:14:37.650443818 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:37.650447989 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 24027
I0422 12:14:37.650452039 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:37.650456531 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 23028 --> 24028, now=23028
I0422 12:14:37.650461297 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:37.650465186 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 24027
I0422 12:14:37.650469525 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:37.650473985 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 23028 --> 24028, now=23028
I0422 12:14:37.650478554 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:37.650482397 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 24027
I0422 12:14:37.650486744 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:37.650491037 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 23028 --> 24028, now=23028
I0422 12:14:37.650495573 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:37.650499646 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 24027
I0422 12:14:37.650503672 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:37.650508041 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 23028 --> 24028, now=23028
I0422 12:14:37.650512304 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:37.650516664 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 24027
I0422 12:14:37.650520579 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:37.650525204 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 23028 --> 24028, now=23028
I0422 12:14:37.650529765 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=23029
I0422 12:14:37.650534207 4215 timer_manager.cc:188] sleep for a 1 milliseconds
I0422 12:14:37.651346718 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:37.651360897 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=23029 next=9223372036854775807 tls_min=23028 glob_min=23029
I0422 12:14:37.651366384 4215 timer_generic.cc:612] .. shard[1]->min_deadline = 23029
I0422 12:14:37.651370384 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:37.651374817 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 24029
I0422 12:14:37.651379033 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:37.651383728 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 23029 --> 24030, now=23029
I0422 12:14:37.651388000 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:37.651392265 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 24029
I0422 12:14:37.651396378 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:37.651401058 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 23029 --> 24030, now=23029
I0422 12:14:37.651407150 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=24028
I0422 12:14:37.651411190 4215 timer_manager.cc:188] sleep for a 999 milliseconds
I0422 12:14:38.650387832 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:38.650414392 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=24028 next=9223372036854775807 tls_min=23029 glob_min=24028
I0422 12:14:38.650420906 4215 timer_generic.cc:612] .. shard[0]->min_deadline = 24028
I0422 12:14:38.650425754 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:38.650429905 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 25028
I0422 12:14:38.650434271 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:38.650438967 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 24028 --> 25029, now=24028
I0422 12:14:38.650443613 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:38.650447946 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 25028
I0422 12:14:38.650451700 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:38.650456264 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 24028 --> 25029, now=24028
I0422 12:14:38.650460242 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:38.650464332 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 25028
I0422 12:14:38.650468155 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:38.650472563 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 24028 --> 25029, now=24028
I0422 12:14:38.650476435 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:38.650480559 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 25028
I0422 12:14:38.650484509 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:38.650488722 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 24028 --> 25029, now=24028
I0422 12:14:38.650492789 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:38.650496643 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 25028
I0422 12:14:38.650500428 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:38.650504577 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 24028 --> 25029, now=24028
I0422 12:14:38.650508875 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:38.650512531 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 25028
I0422 12:14:38.650516711 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:38.650520760 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 24028 --> 25029, now=24028
I0422 12:14:38.650525447 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=24030
I0422 12:14:38.650529415 4215 timer_manager.cc:188] sleep for a 2 milliseconds
I0422 12:14:38.652342678 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:38.652357266 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=24030 next=9223372036854775807 tls_min=24028 glob_min=24030
I0422 12:14:38.652362631 4215 timer_generic.cc:612] .. shard[2]->min_deadline = 24030
I0422 12:14:38.652366933 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:38.652371410 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 25030
I0422 12:14:38.652375525 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:38.652380190 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 24030 --> 25031, now=24030
I0422 12:14:38.652384707 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:38.652389018 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 25030
I0422 12:14:38.652393128 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:38.652397717 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 24030 --> 25031, now=24030
I0422 12:14:38.652402460 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=25029
I0422 12:14:38.652406691 4215 timer_manager.cc:188] sleep for a 999 milliseconds
I0422 12:14:39.651351008 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:39.651379503 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=25029 next=9223372036854775807 tls_min=24030 glob_min=25029
I0422 12:14:39.651385966 4215 timer_generic.cc:612] .. shard[7]->min_deadline = 25029
I0422 12:14:39.651390871 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:39.651395528 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 26029
I0422 12:14:39.651399735 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:39.651405093 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 25029 --> 26030, now=25029
I0422 12:14:39.651410404 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:39.651414389 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 26029
I0422 12:14:39.651418739 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:39.651423240 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 25029 --> 26030, now=25029
I0422 12:14:39.651427885 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:39.651431860 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 26029
I0422 12:14:39.651436173 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:39.651440605 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 25029 --> 26030, now=25029
I0422 12:14:39.651445007 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:39.651449094 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 26029
I0422 12:14:39.651453132 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:39.651457775 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 25029 --> 26030, now=25029
I0422 12:14:39.651461959 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:39.651466258 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 26029
I0422 12:14:39.651470053 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:39.651474887 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 25029 --> 26030, now=25029
I0422 12:14:39.651479146 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:39.651483456 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 26029
I0422 12:14:39.651487372 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:39.651492078 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 25029 --> 26030, now=25029
I0422 12:14:39.651496898 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=25031
I0422 12:14:39.651501120 4215 timer_manager.cc:188] sleep for a 2 milliseconds
I0422 12:14:39.653344532 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:39.653358618 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=25031 next=9223372036854775807 tls_min=25029 glob_min=25031
I0422 12:14:39.653363852 4215 timer_generic.cc:612] .. shard[1]->min_deadline = 25031
I0422 12:14:39.653367884 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:39.653372243 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 26031
I0422 12:14:39.653376699 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:39.653381034 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 25031 --> 26032, now=25031
I0422 12:14:39.653385844 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:39.653389695 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 26031
I0422 12:14:39.653394212 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:39.653398394 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 25031 --> 26032, now=25031
I0422 12:14:39.653403167 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=26030
I0422 12:14:39.653407193 4215 timer_manager.cc:188] sleep for a 999 milliseconds
I0422 12:14:40.652360595 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:40.652395236 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=26030 next=9223372036854775807 tls_min=25031 glob_min=26030
I0422 12:14:40.652409242 4215 timer_generic.cc:612] .. shard[0]->min_deadline = 26030
I0422 12:14:40.652418668 4215 timer_generic.cc:535] .. shard[0]: heap_empty=true
I0422 12:14:40.652428858 4215 timer_generic.cc:510] .. shard[0]->queue_deadline_cap --> 27029
I0422 12:14:40.652435652 4215 timer_generic.cc:575] .. shard[0] popped 0
I0422 12:14:40.652448201 4215 timer_generic.cc:630] .. result --> 1, shard[0]->min_deadline 26030 --> 27030, now=26030
I0422 12:14:40.652458410 4215 timer_generic.cc:535] .. shard[3]: heap_empty=true
I0422 12:14:40.652468105 4215 timer_generic.cc:510] .. shard[3]->queue_deadline_cap --> 27029
I0422 12:14:40.652474596 4215 timer_generic.cc:575] .. shard[3] popped 0
I0422 12:14:40.652485966 4215 timer_generic.cc:630] .. result --> 1, shard[3]->min_deadline 26030 --> 27030, now=26030
I0422 12:14:40.652493572 4215 timer_generic.cc:535] .. shard[4]: heap_empty=true
I0422 12:14:40.652502037 4215 timer_generic.cc:510] .. shard[4]->queue_deadline_cap --> 27029
I0422 12:14:40.652511807 4215 timer_generic.cc:575] .. shard[4] popped 0
I0422 12:14:40.652520511 4215 timer_generic.cc:630] .. result --> 1, shard[4]->min_deadline 26030 --> 27030, now=26030
I0422 12:14:40.652530509 4215 timer_generic.cc:535] .. shard[5]: heap_empty=true
I0422 12:14:40.652538584 4215 timer_generic.cc:510] .. shard[5]->queue_deadline_cap --> 27029
I0422 12:14:40.652547936 4215 timer_generic.cc:575] .. shard[5] popped 0
I0422 12:14:40.652554419 4215 timer_generic.cc:630] .. result --> 1, shard[5]->min_deadline 26030 --> 27030, now=26030
I0422 12:14:40.652565632 4215 timer_generic.cc:535] .. shard[6]: heap_empty=true
I0422 12:14:40.652572947 4215 timer_generic.cc:510] .. shard[6]->queue_deadline_cap --> 27029
I0422 12:14:40.652581164 4215 timer_generic.cc:575] .. shard[6] popped 0
I0422 12:14:40.652591143 4215 timer_generic.cc:630] .. result --> 1, shard[6]->min_deadline 26030 --> 27030, now=26030
I0422 12:14:40.652600070 4215 timer_generic.cc:535] .. shard[7]: heap_empty=true
I0422 12:14:40.652609689 4215 timer_generic.cc:510] .. shard[7]->queue_deadline_cap --> 27029
I0422 12:14:40.652617629 4215 timer_generic.cc:575] .. shard[7] popped 0
I0422 12:14:40.652627334 4215 timer_generic.cc:630] .. result --> 1, shard[7]->min_deadline 26030 --> 27030, now=26030
I0422 12:14:40.652636774 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=26032
I0422 12:14:40.652646565 4215 timer_manager.cc:188] sleep for a 2 milliseconds
I0422 12:14:40.654385640 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:40.654409688 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=26032 next=9223372036854775807 tls_min=26030 glob_min=26032
I0422 12:14:40.654420032 4215 timer_generic.cc:612] .. shard[2]->min_deadline = 26032
I0422 12:14:40.654425857 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:40.654436930 4215 timer_generic.cc:510] .. shard[2]->queue_deadline_cap --> 27032
I0422 12:14:40.654444281 4215 timer_generic.cc:518] .. add timer with deadline 26659 to heap
I0422 12:14:40.654452789 4215 timer_generic.cc:545] .. check top timer deadline=26659 now=26032
I0422 12:14:40.654462184 4215 timer_generic.cc:575] .. shard[2] popped 0
I0422 12:14:40.654470390 4215 timer_generic.cc:630] .. result --> 1, shard[2]->min_deadline 26032 --> 26659, now=26032
I0422 12:14:40.654480468 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:40.654488688 4215 timer_generic.cc:510] .. shard[1]->queue_deadline_cap --> 27032
I0422 12:14:40.654498133 4215 timer_generic.cc:518] .. add timer with deadline 26661 to heap
I0422 12:14:40.654504766 4215 timer_generic.cc:545] .. check top timer deadline=26661 now=26032
I0422 12:14:40.654513384 4215 timer_generic.cc:575] .. shard[1] popped 0
I0422 12:14:40.654523160 4215 timer_generic.cc:630] .. result --> 1, shard[1]->min_deadline 26032 --> 26661, now=26032
I0422 12:14:40.654532538 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=26659
I0422 12:14:40.654542366 4215 timer_manager.cc:188] sleep for a 627 milliseconds
I0422 12:14:41.281352305 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:41.281378168 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=26659 next=9223372036854775807 tls_min=26032 glob_min=26659
I0422 12:14:41.281384137 4215 timer_generic.cc:612] .. shard[2]->min_deadline = 26659
I0422 12:14:41.281388783 4215 timer_generic.cc:535] .. shard[2]: heap_empty=false
I0422 12:14:41.281393032 4215 timer_generic.cc:545] .. check top timer deadline=26659 now=26659
I0422 12:14:41.281397178 4215 timer_generic.cc:551] TIMER 0x7f432849cb00: FIRE 0ms late
I0422 12:14:41.281401257 4215 timer_generic.cc:535] .. shard[2]: heap_empty=true
I0422 12:14:41.281405399 4215 timer_generic.cc:575] .. shard[2] popped 1
I0422 12:14:41.281409841 4215 timer_generic.cc:630] .. result --> 2, shard[2]->min_deadline 26659 --> 27033, now=26659
I0422 12:14:41.281416256 4215 timer_generic.cc:740] TIMER CHECK END: r=2; next=26661
I0422 12:14:41.281420265 4215 timer_manager.cc:124] kick untimed waiter
I0422 12:14:41.281428099 4215 timer_manager.cc:132] flush exec_ctx
I0422 12:14:41.281438023 4215 timer_generic.cc:365] TIMER 0x7f432849cb00: SET 31659 now 26659 call 0x7f432849cb30[0x7f43d50e2980]
I0422 12:14:41.281442603 4215 timer_generic.cc:402] .. add to shard 2 with queue_deadline_cap=27032 => is_first_timer=false
I0422 12:14:41.281447785 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=26659 next=9223372036854775807 tls_min=26659 glob_min=26661
I0422 12:14:41.281452010 4215 timer_generic.cc:740] TIMER CHECK END: r=1; next=26661
I0422 12:14:41.281455819 4215 timer_manager.cc:188] sleep for a 2 milliseconds
I0422 12:14:41.281510339 4071 timer_manager.cc:204] wait ended: was_timed:0 kicked:0
I0422 12:14:41.281525795 4071 timer_generic.cc:717] TIMER CHECK BEGIN: now=26659 next=9223372036854775807 tls_min=22022 glob_min=26661
I0422 12:14:41.281530536 4071 timer_generic.cc:740] TIMER CHECK END: r=1; next=26661
I0422 12:14:41.281534549 4071 timer_manager.cc:197] sleep until kicked
I0422 12:14:41.283342709 4215 timer_manager.cc:204] wait ended: was_timed:1 kicked:0
I0422 12:14:41.283356617 4215 timer_generic.cc:717] TIMER CHECK BEGIN: now=26661 next=9223372036854775807 tls_min=26661 glob_min=26661
I0422 12:14:41.283361359 4215 timer_generic.cc:612] .. shard[1]->min_deadline = 26661
I0422 12:14:41.283365309 4215 timer_generic.cc:535] .. shard[1]: heap_empty=false
I0422 12:14:41.283369212 4215 timer_generic.cc:545] .. check top timer deadline=26661 now=26661
I0422 12:14:41.283373011 4215 timer_generic.cc:551] TIMER 0x7f436c014f30: FIRE 0ms late
I0422 12:14:41.283376820 4215 timer_generic.cc:535] .. shard[1]: heap_empty=true
I0422 12:14:41.283380567 4215 timer_generic.cc:575] .. shard[1] popped 1
I0422 12:14:41.283384738 4215 timer_generic.cc:630] .. result --> 2, shard[1]->min_deadline 26661 --> 27033, now=26661
I0422 12:14:41.283389185 4215 timer_generic.cc:740] TIMER CHECK END: r=2; next=27030
I0422 12:14:41.283392817 4215 timer_manager.cc:124] kick untimed waiter
I0422 12:14:41.283399577 4215 timer_manager.cc:132] flush exec_ctx
I0422 12:14:41.283404174 4215 tcp_client_posix.cc:106] CLIENT_CONNECT: ipv4:172.18.0.4:39485: on_alarm: error="No Error"
I0422 12:14:41.283460312 4215 tcp_client_posix.cc:143] CLIENT_CONNECT: ipv4:172.18.0.4:39485: on_writable: error={"created":"@1619093681.283422772","description":"FD Shutdown","file":"external/com_github_grpc_grpc/src/core/lib/iomgr/lockfree_event.cc","file_line":195,"referenced_errors":[{"created":"@1619093681.283408697","description":"connect() timed out","file":"external/com_github_grpc_grpc/src/core/lib/iomgr/tcp_client_posix.cc","file_line":112}]}
I0422 12:14:41.283466122 4215 timer_generic.cc:468] TIMER 0x7f436c014f30: CANCEL pending=false
I0422 12:14:41.283506939 4215 subchannel.cc:1003] Connect failed: {"created":"@1619093681.283422772","description":"Failed to connect to remote host: FD Shutdown","file":"external/com_github_grpc_grpc/src/core/lib/iomgr/lockfree_event.cc","file_line":195,"os_error":"Timeout occurred","referenced_errors":[{"created":"@1619093681.283408697","description":"connect() timed out","file":"external/com_github_grpc_grpc/src/core/lib/iomgr/tcp_client_posix.cc","file_line":112}],"target_address":"ipv4:172.18.0.4:39485"}
I0422 12:14:41.283515875 4215 client_channel.cc:1016] chand=0x7f432849c848: connectivity change for subchannel wrapper 0x7f436c013420 subchannel 0x7f436c013f60 (connected_subchannel=(nil) state=TRANSIENT_FAILURE); hopping into combiner
I0422 12:14:41.283529330 4215 client_channel.cc:1063] chand=0x7f432849c848: processing connectivity change in combiner for subchannel wrapper 0x7f436c013420 subchannel 0x7f436c013f60 (connected_subchannel=(nil) state=TRANSIENT_FAILURE): watcher=0x7f436c013b40
I0422 12:14:41.283536508 4215 subchannel_list.h:240] [pick_first 0x7f436c012d90] subchannel list 0x7f436c013250 index 0 of 1 (subchannel 0x7f436c013420): connectivity changed: state=TRANSIENT_FAILURE, shutting_down=0, pending_watcher=0x7f436c013b40
I0422 12:14:41.283541726 4215 subchannel_list.h:327] [pick_first 0x7f436c012d90] subchannel list 0x7f436c013250 index 0 of 1 (subchannel 0x7f436c013420): canceling connectivity watch (connection attempt failed)
I0422 12:14:41.283548623 4215 resolving_lb_policy.cc:147] resolving_lb=0x7f432849bcd0: started name re-resolving
D0422 12:14:41.283553479 4215 dns_resolver.cc:239] In cooldown from last resolution (from 20000 ms ago). Will resolve again in 10000 ms
I0422 12:14:41.283558282 4215 timer_generic.cc:365] TIMER 0x7f43284a0048: SET 36661 now 26661 call 0x7f43284a0078[0x7f43d509df70]
I0422 12:14:41.283562418 4215 timer_generic.cc:402] .. add to shard 4 with queue_deadline_cap=27029 => is_first_timer=false
I0422 12:14:41.283567906 4215 client_channel.cc:1332] chand=0x7f432849c848: update: state=TRANSIENT_FAILURE picker=0x7f432449b4f0
I0422 12:14:41.283572716 4215 connectivity_state.cc:151] ConnectivityStateTracker client_channel[0x7f432849c900]: CONNECTING -> TRANSIENT_FAILURE (helper)
I0422 12:14:41.283589831 4215 client_channel.cc:3912] chand=0x7f432849c848 calld=0x7f432849ec20: LB pick returned FAILED (subchannel=(nil), error={"created":"@1619093681.283565985","description":"failed to connect to all addresses","file":"external/com_github_grpc_grpc/src/core/ext/filters/client_channel/lb_policy/pick_first/pick_first.cc","file_line":393,"grpc_status":14})
I0422 12:14:41.283596970 4215 subchannel_list.h:307] [pick_first 0x7f436c012d90] subchannel list 0x7f436c013250 index 0 of 1 (subchannel 0x7f436c013420): starting watch (from TRANSIENT_FAILURE)
I0422 12:14:41.283602882 4215 subchannel.cc:940] Subchannel 0x7f436c013f60: Retry immediately
I0422 12:14:41.283607650 4215 timer_generic.cc:365] TIMER 0x7f436c0140a8: SET 7661 now 26661 call 0x7f436c0140d8[0x7f43d5101070]
I0422 12:14:41.283611934 4215 subchannel.cc:967] Failed to connect to channel, retrying
I0422 12:14:41.283617473 4215 client_channel.cc:1016] chand=0x7f432849c848: connectivity change for subchannel wrapper 0x7f436c013420 subchannel 0x7f436c013f60 (connected_subchannel=(nil) state=CONNECTING); hopping into combiner
I0422 12:14:41.283725463 4215 tcp_client_posix.cc:326] CLIENT_CONNECT: ipv4:172.18.0.4:39485: asynchronously connecting fd 0x7f436c012c40
I0422 12:14:41.283731803 4215 timer_generic.cc:365] TIMER 0x7f432449cf40: SET 46661 now 26661 call 0x7f432449cf70[0x7f43d513ae40]
I0422 12:14:41.283736057 4215 timer_generic.cc:402] .. add to shard 4 with queue_deadline_cap=27029 => is_first_timer=false
I0422 12:14:41.283741564 4215 client_channel.cc:1063] chand=0x7f432849c848: processing connectivity change in combiner for subchannel wrapper 0x7f436c013420 subchannel 0x7f436c013f60 (connected_subchannel=(nil) state=CONNECTING): watcher=0x7f432449b270
I0422 12:14:41.283747032 4215 subchannel_list.h:240] [pick_first 0x7f436c012d90] subchannel list 0x7f436c013250 index 0 of 1 (subchannel 0x7f436c013420): connectivity changed: state=CONNECTING, shutting_down=0, pending_watcher=0x7f432449b270
On the second worker I see the same but before it logs a message from NCCL:
3f6133b3c614:3485:3651 [32616] NCCL INFO Bootstrap : Using [0]eth1:10.0.0.14<0> [1]eth2:172.18.0.4<0> [2]eth0:10.0.7.25<0>
3f6133b3c614:3485:3651 [32617] NCCL INFO NET/Plugin : No plugin found (libnccl-net.so), using internal implementation
3f6133b3c614:3485:3651 [32617] external/nccl_archive/src/misc/ibvwrap.cc:63 NCCL WARN Failed to open libibverbs.so[.1]
3f6133b3c614:3485:3651 [32616] NCCL INFO NET/Socket : Using [0]eth1:10.0.0.14<0> [1]eth2:172.18.0.4<0> [2]eth0:10.0.7.25<0>
3f6133b3c614:3485:3651 [268435456] NCCL INFO Using network Socket
I can see that the workers are trying to connect to each other but the logs shows that they fail to do so for some reason that I haven't figured out, maybe you have seen it before.
from tensorflowonspark.
leewyang
commented on May 24, 2024
No, haven't seen that before. Another thing to try is to just run the TF workers manually via python command line with the TF_CONFIG environment variable. This is basically what TFoS tries to automate, but in your case, removing TFoS should simplify your debugging.
from tensorflowonspark.
sat2000pts
commented on May 24, 2024
Hey lee,
I have tried something out: when I remove the master_node="chief" argument in TFCluster, it actually works. I see that the training is distributed, all workers log display the epochs and it completes. In HDFS checkpoints are written into mnist_model folder and the mnist_export is saved on the workers location (check). That's great and nice but I am wondering why is that the case when I remove master_node="chief".
Thought the issue was lack of worker maybe so I also tried it with 3 workers in the cluster and master_node="chief" not removed -> 1 chief, 2 workers and same result there as well, nothing is happening and its stuck causing it to throw timeout exception at some point (as mentioned in the posts above).
Therefore the current workaround I thought was to check each worker's task_index from ctx object. If ctx.task_index == 0 and ctx.job_name == "worker" then we write the mnist_export to HDFS else local -> according to tensorflow documentation the worker with task_index set to 0 is selected to be the chief. However, I am not sure if thats the way to go now.
from tensorflowonspark.
leewyang
commented on May 24, 2024
I would check your logs again. It's likely that each worker is just training independently, since removing master_node="chief" mostly impacts this code, which sets up the TF_CONFIG environment variable.
The behavior implies that either the nodes are unable to communicate with each other (when TF_CONFIG is set), or they're unable to read/share the model from HDFS (which is required for distributed training).
from tensorflowonspark.
sat2000pts
commented on May 24, 2024
Hey Lee thanks for the reply
I think you are right, I run the TF workers manually via python command line with the TF_CONFIG environment variable as you suggested on locally it worked and did the same thing on the spark workers container but I had instead of the container ip I had to specify the container name and publish the manually specified port -> it worked as well.
I am wondering now whether there is a way pass our own cluster specs so that TFOS at this part uses my specified ports and ip to build TF_CONFIG
from tensorflowonspark.
leewyang
commented on May 24, 2024
If you have manually specified ports for each container, you might be able to just set a TENSORFLOW_PORT environment variable for each container. Normally, in a Spark/YARN environment, TFoS will search for a free port on the executor. However for K8s/docker environments, you can also specify a static port instead by supplying this env var.
That said, if you also need to translate from IP to host, you may need to tweak this line. Note that we originally used hostname, but that caused issues in some setups if the DNS wasn't setup nicely, so we now just use IP addresses.
from tensorflowonspark.
sat2000pts
commented on May 24, 2024
Hey Lee,
Hope you doing well, I wanted thank you again for the help and the explanations, it is running smooth now .
For the people who had the same setup as me here is a short list:
- make sure the spark worker container's have the libhdfs.so and libjvm.so (should already exists)
- set the environment variables that are mentioned at Convert the MNIST zip files into HDFS files -> CLASSPATH especially
- for the tensorflow worker connections make sure TF_CONFIG uses the workers container names if you are using in the swarm but you have own load balancer then you can avoid setting TF_CONFIG by adding endpoint: dnsrr to your compose file
from tensorflowonspark.
leewyang
commented on May 24, 2024
Glad you got it working, and thanks for posting your setup instructions for others!
from tensorflowonspark.
Related Issues (20)
- Writing checkpoints to HDFS takes long HOT 2
- when using mnist_spark.py , serializer.dump_stream Timeout while feeding partition HOT 2
- pkg_resources.DistributionNotFound: The 'tensorflow' distribution was not found and is required by the application HOT 3
- MNIST example - Exception in TF background thread HOT 2
- the doubt about the data policy HOT 1
- Performance issues in the program HOT 2
- Performance issues in examples/mnist/estimator (by P3) HOT 3
- Retaining original columns after inference HOT 2
- tensorflow.python.framework.errors_impl.UnimplementedError: File system scheme 'cosn' not implemented HOT 2
- Model Saved with TF-2.5.0 HOT 3
- How to integrate a model into Spark cluster HOT 12
- Get stuck at "Added broadcast_0_piece0 in memory on" while runing Spark standalone cluster HOT 1
- ExitCode: 13 executing mnist_data_setup.py on a yarn cluster HOT 3
- can it run on tensorflow-cpu? HOT 1
- can it run use ParameterServerStrategy HOT 3
- do we support scala & java code write tensorflow model with tenorflow-core-api ? HOT 3
- Evalator hangs while training HOT 1
- yarn mode error HOT 1
- error while running mnist_tf_ds.py HOT 1
- I have been trying to use TensorFlowOnSpark in Azure Synapse Analytics and I would like to ask if you have any information about its compatibility in this environment
Recommend Projects
-
React
A declarative, efficient, and flexible JavaScript library for building user interfaces.
-
Vue.js
🖖 Vue.js is a progressive, incrementally-adoptable JavaScript framework for building UI on the web.
-
Typescript
TypeScript is a superset of JavaScript that compiles to clean JavaScript output.
-
TensorFlow
An Open Source Machine Learning Framework for Everyone
-
Django
The Web framework for perfectionists with deadlines.
-
Laravel
A PHP framework for web artisans
-
D3
Bring data to life with SVG, Canvas and HTML. 📊📈🎉
-
Recommend Topics
-
javascript
JavaScript (JS) is a lightweight interpreted programming language with first-class functions.
-
web
Some thing interesting about web. New door for the world.
-
server
A server is a program made to process requests and deliver data to clients.
-
Machine learning
Machine learning is a way of modeling and interpreting data that allows a piece of software to respond intelligently.
-
Visualization
Some thing interesting about visualization, use data art
-
Game
Some thing interesting about game, make everyone happy.
Recommend Org
-
Facebook
We are working to build community through open source technology. NB: members must have two-factor auth.
-
Microsoft
Open source projects and samples from Microsoft.
-
Google
Google ❤️ Open Source for everyone.
-
Alibaba
Alibaba Open Source for everyone
-
D3
Data-Driven Documents codes.
-
Tencent
China tencent open source team.
from tensorflowonspark.