{"action":"created","issue":{"url":"https://api.github.com/repos/yahoo/TensorFlowOnSpark/issues/244","repository_url":"https://api.github.com/repos/yahoo/TensorFlowOnSpark","labels_url":"https://api.github.com/repos/yahoo/TensorFlowOnSpark/issues/244/labels{/name}","comments_url":"https://api.github.com/repos/yahoo/TensorFlowOnSpark/issues/244/comments","events_url":"https://api.github.com/repos/yahoo/TensorFlowOnSpark/issues/244/events","html_url":"https://github.com/yahoo/TensorFlowOnSpark/issues/244","id":304505531,"number":244,"title":"CreateSession still waiting for response from worker: /job:worker/replica:0/task:0","user":{"login":"koushikv","id":9465961,"avatar_url":"https://avatars0.githubusercontent.com/u/9465961?v=4","gravatar_id":"","url":"https://api.github.com/users/koushikv","html_url":"https://github.com/koushikv","followers_url":"https://api.github.com/users/koushikv/followers","following_url":"https://api.github.com/users/koushikv/following{/other_user}","gists_url":"https://api.github.com/users/koushikv/gists{/gist_id}","starred_url":"https://api.github.com/users/koushikv/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/koushikv/subscriptions","organizations_url":"https://api.github.com/users/koushikv/orgs","repos_url":"https://api.github.com/users/koushikv/repos","events_url":"https://api.github.com/users/koushikv/events{/privacy}","received_events_url":"https://api.github.com/users/koushikv/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":0,"created_at":"2018-03-12T19:17:28Z","updated_at":"2018-03-13T00:09:08Z","closed_at":null,"author_association":"NONE","body":"We are trying run mnist_spark.py using  Spark on yarn cluster on CDH 5.11.0 cluster. The cluster has 4 machines and each machine has 2 GPUs.\r\nBelow are the cluster details\r\nVersion information:\r\n```\r\n pip list | grep tensor\r\ntensorflow-gpu (1.5.0)\r\ntensorflow-tensorboard (1.5.1)\r\ntensorflowonspark (1.2.0)\r\n\r\npython --version\r\nPython 2.7.10 :: Continuum Analytics, Inc.\r\n```\r\nJob ran successfully when i specified number of executors as 2 but when i increase the number of executors to any value greater than 2 it is going to a hang state.\r\n\r\nBelow is the shell script that am triggering:\r\n```\r\nset -x\r\nexport PYTHON_ROOT=/apps/anaconda/2.3\r\nexport MASTER=yarn\r\nexport HADOOP_HDFS_HOME=/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib/hadoop-hdfs\r\nexport TFoS_HOME=/data1/tensorflow-software/TensorFlowOnSpark\r\nexport hdfs_path=hdfs://<Hostname>:8020/user/vap_admin_fid/tensorflow\r\nexport LIB_HDFS=/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib64\r\nexport LIB_JVM=/usr/java/jdk1.8.0_60/jre/lib/amd64/server\r\nexport LIB_CUDA=/usr/local/cuda-9.0/lib64\r\nexport PYSPARK_PYTHON=/apps/anaconda/2.3/bin/python\r\n\r\nspark-submit \\\r\n--master ${MASTER} \\\r\n--deploy-mode client \\\r\n--executor-memory 4G \\\r\n--executor-cores 1 \\\r\n--driver-memory 2G \\\r\n--num-executors 4 \\\r\n--py-files ${TFoS_HOME}/examples/mnist/spark/mnist_dist.py \\\r\n--conf spark.dynamicAllocation.enabled=false \\\r\n--conf spark.yarn.maxAppAttempts=1 \\\r\n--conf spark.yarn.executor.memoryOverhead=16 \\\r\n--conf spark.executorEnv.LD_LIBRARY_PATH=\"${LIB_CUDA}:${LIB_JVM}:${LIB_HDFS}\" \\\r\n--conf spark.executorEnv.HADOOP_HDFS_HOME=$HADOOP_HDFS_HOME \\\r\n${TFoS_HOME}/examples/mnist/spark/mnist_spark.py \\\r\n--steps 10 \\\r\n--images ${hdfs_path}/images \\\r\n--labels ${hdfs_path}/labels \\\r\n--format csv \\\r\n--mode train \\\r\n--model ${hdfs_path}/mnist_model \\\r\n--cluster_size 4\r\n\r\n```\r\nDriver Log:\r\n```\r\n+ export PYTHON_ROOT=/apps/anaconda/2.3\r\n+ PYTHON_ROOT=/apps/anaconda/2.3\r\n+ export MASTER=yarn\r\n+ MASTER=yarn\r\n+ export HADOOP_HDFS_HOME=/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib/hadoop-hdfs\r\n+ HADOOP_HDFS_HOME=/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib/hadoop-hdfs\r\n+ export TFoS_HOME=/data1/tensorflow-software/TensorFlowOnSpark\r\n+ TFoS_HOME=/data1/tensorflow-software/TensorFlowOnSpark\r\n+ export hdfs_path=hdfs://node194215:8020/user/vap_admin_fid/tensorflow\r\n+ hdfs_path=hdfs://node194215:8020/user/vap_admin_fid/tensorflow\r\n+ export LIB_HDFS=/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib64\r\n+ LIB_HDFS=/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib64\r\n+ export LIB_JVM=/usr/java/jdk1.8.0_60/jre/lib/amd64/server\r\n+ LIB_JVM=/usr/java/jdk1.8.0_60/jre/lib/amd64/server\r\n+ export LIB_CUDA=/usr/local/cuda-9.0/lib64\r\n+ LIB_CUDA=/usr/local/cuda-9.0/lib64\r\n+ export PYSPARK_PYTHON=/apps/anaconda/2.3/bin/python\r\n+ PYSPARK_PYTHON=/apps/anaconda/2.3/bin/python\r\n+ spark-submit --master yarn --deploy-mode client --executor-memory 4G --executor-cores 1 --driver-memory 2G --num-executors 4 --py-files /data1/tensorflow-software/TensorFlowOnSpark/examples/mnist/spark/mnist_dist.py --conf spark.dynamicAllocation.enabled=false --conf spark.yarn.maxAppAttempts=1 --conf spark.yarn.executor.memoryOverhead=16 --conf spark.executorEnv.LD_LIBRARY_PATH=/usr/local/cuda-9.0/lib64/:/usr/java/jdk1.8.0_60/jre/lib/amd64/server/:/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib64/ --conf spark.executorEnv.HADOOP_HDFS_HOME=/opt/cloudera/parcels/CDH-5.11.1-1.cdh5.11.1.p0.4/lib/hadoop-hdfs --archives hdfs://node194215:8020/user/vap_admin_fid/tensorflow/Python.zip#Python /data1/tensorflow-software/TensorFlowOnSpark/examples/mnist/spark/mnist_spark.py --steps 10 --images hdfs://node194215:8020/user/vap_admin_fid/tensorflow/images --labels hdfs://node194215:8020/user/vap_admin_fid/tensorflow/labels --format csv --mode train --model hdfs://node194215:8020/user/vap_admin_fid/tensorflow/mnist_model\r\n18/03/12 13:18:13 INFO spark.SparkContext: Running Spark version 1.6.0\r\n18/03/12 13:18:13 INFO spark.SecurityManager: Changing view acls to: root\r\n18/03/12 13:18:13 INFO spark.SecurityManager: Changing modify acls to: root\r\n18/03/12 13:18:13 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(root); users with modify permissions: Set(root)\r\n18/03/12 13:18:13 INFO util.Utils: Successfully started service 'sparkDriver' on port 37199.\r\n18/03/12 13:18:14 INFO slf4j.Slf4jLogger: Slf4jLogger started\r\n18/03/12 13:18:14 INFO Remoting: Starting remoting\r\n18/03/12 13:18:14 INFO Remoting: Remoting started; listening on addresses :[akka.tcp://sparkDriverActorSystem@10.100.194.217:46236]\r\n18/03/12 13:18:14 INFO Remoting: Remoting now listens on addresses: [akka.tcp://sparkDriverActorSystem@10.100.194.217:46236]\r\n18/03/12 13:18:14 INFO util.Utils: Successfully started service 'sparkDriverActorSystem' on port 46236.\r\n18/03/12 13:18:14 INFO spark.SparkEnv: Registering MapOutputTracker\r\n18/03/12 13:18:14 INFO spark.SparkEnv: Registering BlockManagerMaster\r\n18/03/12 13:18:14 INFO storage.DiskBlockManager: Created local directory at /tmp/blockmgr-0483b8d5-3a34-442d-92dc-2a2ace61b808\r\n18/03/12 13:18:14 INFO storage.MemoryStore: MemoryStore started with capacity 1060.0 MB\r\n18/03/12 13:18:14 INFO spark.SparkEnv: Registering OutputCommitCoordinator\r\n18/03/12 13:18:14 INFO util.Utils: Successfully started service 'SparkUI' on port 4040.\r\n18/03/12 13:18:14 INFO ui.SparkUI: Started SparkUI at http://10.100.194.217:4040\r\n18/03/12 13:18:14 INFO client.RMProxy: Connecting to ResourceManager at node194090/10.100.194.90:8032\r\n18/03/12 13:18:14 INFO yarn.Client: Requesting a new application from cluster with 4 NodeManagers\r\n18/03/12 13:18:14 INFO yarn.Client: Verifying our application has not requested more than the maximum memory capability of the cluster (495192 MB per container)\r\n18/03/12 13:18:14 INFO yarn.Client: Will allocate AM container, with 896 MB memory including 384 MB overhead\r\n18/03/12 13:18:14 INFO yarn.Client: Setting up container launch context for our AM\r\n18/03/12 13:18:14 INFO yarn.Client: Setting up the launch environment for our AM container\r\n18/03/12 13:18:14 INFO yarn.Client: Preparing resources for our AM container\r\n18/03/12 13:18:15 INFO yarn.Client: Source and destination file systems are the same. Not copying hdfs://node194215:8020/user/vap_admin_fid/tensorflow/Python.zip#Python\r\n18/03/12 13:18:15 INFO yarn.Client: Uploading resource file:/data1/tensorflow-software/TensorFlowOnSpark/examples/mnist/spark/mnist_dist.py -> hdfs://node194215:8020/user/root/.sparkStaging/application_1520874763502_0012/mnist_dist.py\r\n18/03/12 13:18:15 INFO yarn.Client: Uploading resource file:/tmp/spark-b42c9811-b323-407a-bbc9-4d3996647850/__spark_conf__6309647882202470623.zip -> hdfs://node194215:8020/user/root/.sparkStaging/application_1520874763502_0012/__spark_conf__6309647882202470623.zip\r\n18/03/12 13:18:15 INFO spark.SecurityManager: Changing view acls to: root\r\n18/03/12 13:18:15 INFO spark.SecurityManager: Changing modify acls to: root\r\n18/03/12 13:18:15 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(root); users with modify permissions: Set(root)\r\n18/03/12 13:18:15 INFO yarn.Client: Submitting application 12 to ResourceManager\r\n18/03/12 13:18:16 INFO impl.YarnClientImpl: Submitted application application_1520874763502_0012\r\n18/03/12 13:18:17 INFO yarn.Client: Application report for application_1520874763502_0012 (state: ACCEPTED)\r\n18/03/12 13:18:17 INFO yarn.Client:\r\n         client token: N/A\r\n         diagnostics: N/A\r\n         ApplicationMaster host: N/A\r\n         ApplicationMaster RPC port: -1\r\n         queue: root.users.root\r\n         start time: 1520878684671\r\n         final status: UNDEFINED\r\n         tracking URL: http://node194090:8088/proxy/application_1520874763502_0012/\r\n         user: root\r\n18/03/12 13:18:18 INFO yarn.Client: Application report for application_1520874763502_0012 (state: ACCEPTED)\r\n18/03/12 13:18:18 INFO cluster.YarnSchedulerBackend$YarnSchedulerEndpoint: ApplicationMaster registered as NettyRpcEndpointRef(null)\r\n18/03/12 13:18:18 INFO cluster.YarnClientSchedulerBackend: Add WebUI Filter. org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter, Map(PROXY_HOSTS -> node194090, PROXY_URI_BASES -> http://node194090:8088/proxy/application_1520874763502_0012), /proxy/application_1520874763502_0012\r\n18/03/12 13:18:18 INFO ui.JettyUtils: Adding filter: org.apache.hadoop.yarn.server.webproxy.amfilter.AmIpFilter\r\n18/03/12 13:18:19 INFO yarn.Client: Application report for application_1520874763502_0012 (state: ACCEPTED)\r\n18/03/12 13:18:20 INFO yarn.Client: Application report for application_1520874763502_0012 (state: RUNNING)\r\n18/03/12 13:18:20 INFO yarn.Client:\r\n         client token: N/A\r\n         diagnostics: N/A\r\n         ApplicationMaster host: 10.100.194.215\r\n         ApplicationMaster RPC port: 0\r\n         queue: root.users.root\r\n         start time: 1520878684671\r\n         final status: UNDEFINED\r\n         tracking URL: http://node194090:8088/proxy/application_1520874763502_0012/\r\n         user: root\r\n18/03/12 13:18:20 INFO cluster.YarnClientSchedulerBackend: Application application_1520874763502_0012 has started running.\r\n18/03/12 13:18:20 INFO util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 39801.\r\n18/03/12 13:18:20 INFO netty.NettyBlockTransferService: Server created on 39801\r\n18/03/12 13:18:20 INFO storage.BlockManager: external shuffle service port = 7337\r\n18/03/12 13:18:20 INFO storage.BlockManagerMaster: Trying to register BlockManager\r\n18/03/12 13:18:20 INFO storage.BlockManagerMasterEndpoint: Registering block manager 10.100.194.217:39801 with 1060.0 MB RAM, BlockManagerId(driver, 10.100.194.217, 39801)\r\n18/03/12 13:18:20 INFO storage.BlockManagerMaster: Registered BlockManager\r\n18/03/12 13:18:20 INFO scheduler.EventLoggingListener: Logging events to hdfs://node194215:8020/user/spark/applicationHistory/application_1520874763502_0012\r\n18/03/12 13:18:20 INFO spark.SparkContext: Registered listener com.cloudera.spark.lineage.ClouderaNavigatorListener\r\n18/03/12 13:18:22 INFO cluster.YarnClientSchedulerBackend: Registered executor NettyRpcEndpointRef(null) (node194215:40102) with ID 1\r\n18/03/12 13:18:22 INFO storage.BlockManagerMasterEndpoint: Registering block manager node194215:39167 with 2.1 GB RAM, BlockManagerId(1, node194215, 39167)\r\n18/03/12 13:18:22 INFO cluster.YarnClientSchedulerBackend: Registered executor NettyRpcEndpointRef(null) (node194090:49448) with ID 2\r\n18/03/12 13:18:22 INFO cluster.YarnClientSchedulerBackend: Registered executor NettyRpcEndpointRef(null) (node194090:49446) with ID 3\r\n18/03/12 13:18:22 INFO storage.BlockManagerMasterEndpoint: Registering block manager node194090:43201 with 2.1 GB RAM, BlockManagerId(2, node194090, 43201)\r\n18/03/12 13:18:22 INFO storage.BlockManagerMasterEndpoint: Registering block manager node194090:34955 with 2.1 GB RAM, BlockManagerId(3, node194090, 34955)\r\n18/03/12 13:18:22 INFO cluster.YarnClientSchedulerBackend: Registered executor NettyRpcEndpointRef(null) (node194217:48856) with ID 4\r\n18/03/12 13:18:22 INFO storage.BlockManagerMasterEndpoint: Registering block manager node194217:36373 with 2.1 GB RAM, BlockManagerId(4, node194217, 36373)\r\n18/03/12 13:18:22 INFO cluster.YarnClientSchedulerBackend: SchedulerBackend is ready for scheduling beginning after reached minRegisteredResourcesRatio: 0.8\r\nargs: Namespace(batch_size=100, cluster_size=4, epochs=1, format='csv', images='hdfs://node194215:8020/user/vap_admin_fid/tensorflow/images', labels='hdfs://node194215:8020/user/vap_admin_fid/tensorflow/labels', mode='train', model='hdfs://node194215:8020/user/vap_admin_fid/tensorflow/mnist_model', output='predictions', rdma=False, readers=1, steps=10, tensorboard=False)\r\n2018-03-12T13:18:22.911420 ===== Start\r\n18/03/12 13:18:23 INFO storage.MemoryStore: Block broadcast_0 stored as values in memory (estimated size 290.6 KB, free 1059.7 MB)\r\n18/03/12 13:18:23 INFO storage.MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 25.4 KB, free 1059.7 MB)\r\n18/03/12 13:18:23 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in memory on 10.100.194.217:39801 (size: 25.4 KB, free: 1060.0 MB)\r\n18/03/12 13:18:23 INFO spark.SparkContext: Created broadcast 0 from textFile at NativeMethodAccessorImpl.java:-2\r\n18/03/12 13:18:23 INFO storage.MemoryStore: Block broadcast_1 stored as values in memory (estimated size 290.7 KB, free 1059.4 MB)\r\n18/03/12 13:18:23 INFO storage.MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 25.4 KB, free 1059.4 MB)\r\n18/03/12 13:18:23 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in memory on 10.100.194.217:39801 (size: 25.4 KB, free: 1060.0 MB)\r\n18/03/12 13:18:23 INFO spark.SparkContext: Created broadcast 1 from textFile at NativeMethodAccessorImpl.java:-2\r\nzipping images and labels\r\n18/03/12 13:18:23 INFO mapred.FileInputFormat: Total input paths to process : 10\r\n18/03/12 13:18:23 INFO mapred.FileInputFormat: Total input paths to process : 10\r\n2018-03-12 13:18:23,484 INFO (MainThread-76707) Reserving TFSparkNodes\r\n2018-03-12 13:18:23,484 INFO (MainThread-76707) worker node range [1, 2, 3], ps node range [0]\r\n2018-03-12 13:18:23,486 INFO (MainThread-76707) listening for reservations at ('10.100.194.217', 42756)\r\n2018-03-12 13:18:23,486 INFO (MainThread-76707) Starting TensorFlow on executors\r\n2018-03-12 13:18:23,492 INFO (MainThread-76707) Waiting for TFSparkNodes to start\r\n2018-03-12 13:18:23,493 INFO (MainThread-76707) waiting for 4 reservations\r\n18/03/12 13:18:23 INFO spark.SparkContext: Starting job: foreachPartition at /apps/anaconda/2.3/lib/python2.7/site-packages/tensorflowonspark/TFCluster.py:271\r\n18/03/12 13:18:23 INFO scheduler.DAGScheduler: Got job 0 (foreachPartition at /apps/anaconda/2.3/lib/python2.7/site-packages/tensorflowonspark/TFCluster.py:271) with 4 output partitions\r\n18/03/12 13:18:23 INFO scheduler.DAGScheduler: Final stage: ResultStage 0 (foreachPartition at /apps/anaconda/2.3/lib/python2.7/site-packages/tensorflowonspark/TFCluster.py:271)\r\n18/03/12 13:18:23 INFO scheduler.DAGScheduler: Parents of final stage: List()\r\n18/03/12 13:18:23 INFO scheduler.DAGScheduler: Missing parents: List()\r\n18/03/12 13:18:23 INFO scheduler.DAGScheduler: Submitting ResultStage 0 (PythonRDD[8] at foreachPartition at /apps/anaconda/2.3/lib/python2.7/site-packages/tensorflowonspark/TFCluster.py:271), which has no missing parents\r\n18/03/12 13:18:23 INFO storage.MemoryStore: Block broadcast_2 stored as values in memory (estimated size 11.7 KB, free 1059.4 MB)\r\n18/03/12 13:18:23 INFO storage.MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 8.0 KB, free 1059.4 MB)\r\n18/03/12 13:18:23 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in memory on 10.100.194.217:39801 (size: 8.0 KB, free: 1060.0 MB)\r\n18/03/12 13:18:23 INFO spark.SparkContext: Created broadcast 2 from broadcast at DAGScheduler.scala:1004\r\n18/03/12 13:18:23 INFO scheduler.DAGScheduler: Submitting 4 missing tasks from ResultStage 0 (PythonRDD[8] at foreachPartition at /apps/anaconda/2.3/lib/python2.7/site-packages/tensorflowonspark/TFCluster.py:271) (first 15 tasks are for partitions Vector(0, 1, 2, 3))\r\n18/03/12 13:18:23 INFO cluster.YarnScheduler: Adding task set 0.0 with 4 tasks\r\n18/03/12 13:18:23 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 0.0 (TID 0, node194090, executor 2, partition 0, PROCESS_LOCAL, 1990 bytes)\r\n18/03/12 13:18:23 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 0.0 (TID 1, node194215, executor 1, partition 1, PROCESS_LOCAL, 1990 bytes)\r\n18/03/12 13:18:23 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 0.0 (TID 2, node194090, executor 3, partition 2, PROCESS_LOCAL, 1990 bytes)\r\n18/03/12 13:18:23 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 0.0 (TID 3, node194217, executor 4, partition 3, PROCESS_LOCAL, 1990 bytes)\r\n18/03/12 13:18:23 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in memory on node194215:39167 (size: 8.0 KB, free: 2.1 GB)\r\n18/03/12 13:18:23 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in memory on node194090:43201 (size: 8.0 KB, free: 2.1 GB)\r\n18/03/12 13:18:23 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in memory on node194090:34955 (size: 8.0 KB, free: 2.1 GB)\r\n18/03/12 13:18:23 INFO storage.BlockManagerInfo: Added broadcast_2_piece0 in memory on node194217:36373 (size: 8.0 KB, free: 2.1 GB)\r\n2018-03-12 13:18:24,494 INFO (MainThread-76707) waiting for 4 reservations\r\n2018-03-12 13:18:25,495 INFO (MainThread-76707) waiting for 1 reservations\r\n2018-03-12 13:18:26,496 INFO (MainThread-76707) all reservations completed\r\n2018-03-12 13:18:26,497 INFO (MainThread-76707) All TFSparkNodes started\r\n2018-03-12 13:18:26,497 INFO (MainThread-76707) {'addr': '/tmp/pymp-g_uEG1/listener-nFtokO', 'task_index': 0, 'port': 38993, 'authkey': '\\xc4y\\x85\\xc8\\xb6!G3\\xacm\\x13!\\xfb\\xca\\x82\\xe6', 'worker_num': 1, 'host': '10.100.194.215', 'ppid': 62585, 'job_name': 'worker', 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:26,497 INFO (MainThread-76707) {'addr': '/tmp/pymp-h267A9/listener-FAcTff', 'task_index': 1, 'port': 46096, 'authkey': 'F\\xa0\\nge\\xeeJ\\xb5\\xa0\\xf8\\xbfr.f\\xc0K', 'worker_num': 2, 'host': '10.100.194.90', 'ppid': 75053, 'job_name': 'worker', 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:26,497 INFO (MainThread-76707) {'addr': ('10.100.194.90', 41401), 'task_index': 0, 'port': 37805, 'authkey': '\\xf5\\xc9*C\\x84EC\\xf2\\xb5\\xd7j\\x8d\\x04\\x8b\\x80\\xea', 'worker_num': 0, 'host': '10.100.194.90', 'ppid': 75051, 'job_name': 'ps', 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:26,497 INFO (MainThread-76707) {'addr': '/tmp/pymp-wkzZQO/listener-xo8DCy', 'task_index': 2, 'port': 42757, 'authkey': '\\x89\\xf1~j\\xae\\xacM\\xfc\\xb2\\xb8\\x14\\xa8\\xcd\\x81jt', 'worker_num': 3, 'host': '10.100.194.217', 'ppid': 78242, 'job_name': 'worker', 'tb_pid': 0, 'tb_port': 0}\r\n----------<tensorflowonspark.TFCluster.TFCluster object at 0x7f37551ae550>\r\n2018-03-12 13:18:26,497 INFO (MainThread-76707) Feeding training data\r\n18/03/12 13:18:26 INFO spark.SparkContext: Starting job: collect at PythonRDD.scala:405\r\n18/03/12 13:18:26 INFO scheduler.DAGScheduler: Got job 1 (collect at PythonRDD.scala:405) with 10 output partitions\r\n18/03/12 13:18:26 INFO scheduler.DAGScheduler: Final stage: ResultStage 1 (collect at PythonRDD.scala:405)\r\n18/03/12 13:18:26 INFO scheduler.DAGScheduler: Parents of final stage: List()\r\n18/03/12 13:18:26 INFO scheduler.DAGScheduler: Missing parents: List()\r\n18/03/12 13:18:26 INFO scheduler.DAGScheduler: Submitting ResultStage 1 (PythonRDD[10] at RDD at PythonRDD.scala:43), which has no missing parents\r\n18/03/12 13:18:26 INFO storage.MemoryStore: Block broadcast_3 stored as values in memory (estimated size 14.0 KB, free 1059.4 MB)\r\n18/03/12 13:18:26 INFO storage.MemoryStore: Block broadcast_3_piece0 stored as bytes in memory (estimated size 7.2 KB, free 1059.4 MB)\r\n18/03/12 13:18:26 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in memory on 10.100.194.217:39801 (size: 7.2 KB, free: 1060.0 MB)\r\n18/03/12 13:18:26 INFO spark.SparkContext: Created broadcast 3 from broadcast at DAGScheduler.scala:1004\r\n18/03/12 13:18:26 INFO scheduler.DAGScheduler: Submitting 10 missing tasks from ResultStage 1 (PythonRDD[10] at RDD at PythonRDD.scala:43) (first 15 tasks are for partitions Vector(0, 1, 2, 3, 4, 5, 6, 7, 8, 9))\r\n18/03/12 13:18:26 INFO cluster.YarnScheduler: Adding task set 1.0 with 10 tasks\r\n18/03/12 13:18:27 INFO scheduler.TaskSetManager: Starting task 0.0 in stage 1.0 (TID 4, node194217, executor 4, partition 0, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:27 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 0.0 (TID 3) in 3399 ms on node194217 (executor 4) (1/4)\r\n18/03/12 13:18:27 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in memory on node194217:36373 (size: 7.2 KB, free: 2.1 GB)\r\n18/03/12 13:18:27 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in memory on node194217:36373 (size: 25.4 KB, free: 2.1 GB)\r\n18/03/12 13:18:27 INFO scheduler.TaskSetManager: Starting task 1.0 in stage 1.0 (TID 5, node194215, executor 1, partition 1, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:27 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 0.0 (TID 1) in 4197 ms on node194215 (executor 1) (2/4)\r\n18/03/12 13:18:27 INFO scheduler.TaskSetManager: Finished task 2.0 in stage 0.0 (TID 2) in 4213 ms on node194090 (executor 3) (3/4)\r\n18/03/12 13:18:27 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in memory on node194215:39167 (size: 7.2 KB, free: 2.1 GB)\r\n18/03/12 13:18:27 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in memory on node194215:39167 (size: 25.4 KB, free: 2.1 GB)\r\n18/03/12 13:18:28 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in memory on node194217:36373 (size: 25.4 KB, free: 2.1 GB)\r\n18/03/12 13:18:28 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in memory on node194215:39167 (size: 25.4 KB, free: 2.1 GB)\r\n18/03/12 13:18:31 INFO scheduler.TaskSetManager: Starting task 2.0 in stage 1.0 (TID 6, node194090, executor 3, partition 2, RACK_LOCAL, 2682 bytes)\r\n18/03/12 13:18:31 INFO storage.BlockManagerInfo: Added broadcast_3_piece0 in memory on node194090:34955 (size: 7.2 KB, free: 2.1 GB)\r\n18/03/12 13:18:31 INFO storage.BlockManagerInfo: Added broadcast_0_piece0 in memory on node194090:34955 (size: 25.4 KB, free: 2.1 GB)\r\n18/03/12 13:18:31 INFO storage.BlockManagerInfo: Added broadcast_1_piece0 in memory on node194090:34955 (size: 25.4 KB, free: 2.1 GB)\r\n2018-03-12 13:18:50,075 INFO (Thread-2-76707) setting server.done\r\n18/03/12 13:18:50 INFO scheduler.TaskSetManager: Starting task 3.0 in stage 1.0 (TID 7, node194215, executor 1, partition 3, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:50 INFO scheduler.TaskSetManager: Finished task 1.0 in stage 1.0 (TID 5) in 22294 ms on node194215 (executor 1) (1/10)\r\n18/03/12 13:18:50 INFO scheduler.TaskSetManager: Starting task 4.0 in stage 1.0 (TID 8, node194215, executor 1, partition 4, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:50 INFO scheduler.TaskSetManager: Finished task 3.0 in stage 1.0 (TID 7) in 398 ms on node194215 (executor 1) (2/10)\r\n18/03/12 13:18:50 INFO scheduler.TaskSetManager: Starting task 5.0 in stage 1.0 (TID 9, node194215, executor 1, partition 5, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:50 INFO scheduler.TaskSetManager: Finished task 4.0 in stage 1.0 (TID 8) in 373 ms on node194215 (executor 1) (3/10)\r\n18/03/12 13:18:51 INFO scheduler.TaskSetManager: Starting task 6.0 in stage 1.0 (TID 10, node194215, executor 1, partition 6, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:51 INFO scheduler.TaskSetManager: Finished task 5.0 in stage 1.0 (TID 9) in 378 ms on node194215 (executor 1) (4/10)\r\n18/03/12 13:18:51 INFO scheduler.TaskSetManager: Starting task 7.0 in stage 1.0 (TID 11, node194215, executor 1, partition 7, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:51 INFO scheduler.TaskSetManager: Finished task 6.0 in stage 1.0 (TID 10) in 387 ms on node194215 (executor 1) (5/10)\r\n18/03/12 13:18:52 INFO scheduler.TaskSetManager: Starting task 8.0 in stage 1.0 (TID 12, node194215, executor 1, partition 8, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:52 INFO scheduler.TaskSetManager: Finished task 7.0 in stage 1.0 (TID 11) in 401 ms on node194215 (executor 1) (6/10)\r\n18/03/12 13:18:52 INFO scheduler.TaskSetManager: Starting task 9.0 in stage 1.0 (TID 13, node194215, executor 1, partition 9, NODE_LOCAL, 2682 bytes)\r\n18/03/12 13:18:52 INFO scheduler.TaskSetManager: Finished task 8.0 in stage 1.0 (TID 12) in 398 ms on node194215 (executor 1) (7/10)\r\n18/03/12 13:18:52 INFO scheduler.TaskSetManager: Finished task 9.0 in stage 1.0 (TID 13) in 395 ms on node194215 (executor 1) (8/10)\r\n\r\n```\r\nps Log:\r\n```\r\n18/03/12 13:18:09 INFO executor.CoarseGrainedExecutorBackend: Started daemon with process name: 74403@node194090\r\n18/03/12 13:18:09 INFO executor.CoarseGrainedExecutorBackend: Registered signal handlers for [TERM, HUP, INT]\r\n18/03/12 13:18:09 INFO spark.SecurityManager: Changing view acls to: yarn,root\r\n18/03/12 13:18:09 INFO spark.SecurityManager: Changing modify acls to: yarn,root\r\n18/03/12 13:18:09 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(yarn, root); users with modify permissions: Set(yarn, root)\r\n18/03/12 13:18:10 INFO spark.SecurityManager: Changing view acls to: yarn,root\r\n18/03/12 13:18:10 INFO spark.SecurityManager: Changing modify acls to: yarn,root\r\n18/03/12 13:18:10 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(yarn, root); users with modify permissions: Set(yarn, root)\r\n18/03/12 13:18:10 INFO slf4j.Slf4jLogger: Slf4jLogger started\r\n18/03/12 13:18:10 INFO Remoting: Starting remoting\r\n18/03/12 13:18:10 INFO Remoting: Remoting started; listening on addresses :[akka.tcp://sparkExecutorActorSystem@node194090:39440]\r\n18/03/12 13:18:10 INFO Remoting: Remoting now listens on addresses: [akka.tcp://sparkExecutorActorSystem@node194090:39440]\r\n18/03/12 13:18:10 INFO util.Utils: Successfully started service 'sparkExecutorActorSystem' on port 39440.\r\n18/03/12 13:18:10 INFO storage.DiskBlockManager: Created local directory at /data1/yarn/nm/usercache/root/appcache/application_1520874763502_0012/blockmgr-086a4998-4b05-4aae-beee-dda2b122c936\r\n18/03/12 13:18:10 INFO storage.MemoryStore: MemoryStore started with capacity 2.1 GB\r\n18/03/12 13:18:10 INFO executor.CoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrainedScheduler@10.100.194.217:37199\r\n18/03/12 13:18:10 INFO executor.CoarseGrainedExecutorBackend: Successfully registered with driver\r\n18/03/12 13:18:10 INFO executor.Executor: Starting executor ID 2 on host node194090\r\n18/03/12 13:18:10 INFO util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 43201.\r\n18/03/12 13:18:10 INFO netty.NettyBlockTransferService: Server created on 43201\r\n18/03/12 13:18:10 INFO storage.BlockManager: external shuffle service port = 7337\r\n18/03/12 13:18:10 INFO storage.BlockManagerMaster: Trying to register BlockManager\r\n18/03/12 13:18:10 INFO storage.BlockManagerMaster: Registered BlockManager\r\n18/03/12 13:18:10 INFO storage.BlockManager: Registering executor with local external shuffle service.\r\n18/03/12 13:18:12 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 0\r\n18/03/12 13:18:12 INFO executor.Executor: Running task 0.0 in stage 0.0 (TID 0)\r\n18/03/12 13:18:12 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 2\r\n18/03/12 13:18:12 INFO storage.MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 8.0 KB, free 2.1 GB)\r\n18/03/12 13:18:12 INFO broadcast.TorrentBroadcast: Reading broadcast variable 2 took 100 ms\r\n18/03/12 13:18:12 INFO storage.MemoryStore: Block broadcast_2 stored as values in memory (estimated size 11.7 KB, free 2.1 GB)\r\n2018-03-12 13:18:13,624 INFO (MainThread-75240) connected to server at ('10.100.194.217', 42756)\r\n2018-03-12 13:18:13,626 INFO (MainThread-75240) TFSparkNode.reserve: {'authkey': '\\xf5\\xc9*C\\x84EC\\xf2\\xb5\\xd7j\\x8d\\x04\\x8b\\x80\\xea', 'worker_num': 0, 'host': '10.100.194.90', 'tb_port': 0, 'addr': ('10.100.194.90', 41401), 'ppid': 75051, 'task_index': 0, 'job_name': 'ps', 'tb_pid': 0, 'port': 37805}\r\n2018-03-12 13:18:16,631 INFO (MainThread-75240) node: {'addr': ('10.100.194.90', 41401), 'task_index': 0, 'job_name': 'ps', 'authkey': '\\xf5\\xc9*C\\x84EC\\xf2\\xb5\\xd7j\\x8d\\x04\\x8b\\x80\\xea', 'worker_num': 0, 'host': '10.100.194.90', 'ppid': 75051, 'port': 37805, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,632 INFO (MainThread-75240) node: {'addr': '/tmp/pymp-g_uEG1/listener-nFtokO', 'task_index': 0, 'job_name': 'worker', 'authkey': '\\xc4y\\x85\\xc8\\xb6!G3\\xacm\\x13!\\xfb\\xca\\x82\\xe6', 'worker_num': 1, 'host': '10.100.194.215', 'ppid': 62585, 'port': 38993, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,632 INFO (MainThread-75240) node: {'addr': '/tmp/pymp-h267A9/listener-FAcTff', 'task_index': 1, 'job_name': 'worker', 'authkey': 'F\\xa0\\nge\\xeeJ\\xb5\\xa0\\xf8\\xbfr.f\\xc0K', 'worker_num': 2, 'host': '10.100.194.90', 'ppid': 75053, 'port': 46096, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,632 INFO (MainThread-75240) node: {'addr': '/tmp/pymp-wkzZQO/listener-xo8DCy', 'task_index': 2, 'job_name': 'worker', 'authkey': '\\x89\\xf1~j\\xae\\xacM\\xfc\\xb2\\xb8\\x14\\xa8\\xcd\\x81jt', 'worker_num': 3, 'host': '10.100.194.217', 'ppid': 78242, 'port': 42757, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,632 INFO (MainThread-75240) Starting TensorFlow ps:0 as ps on cluster node 0 on background process\r\n2018-03-12 13:18:22,268 INFO (MainThread-75450) 0: ======== ps:0 ========\r\n2018-03-12 13:18:22,268 INFO (MainThread-75450) 0: Cluster spec: {'ps': ['10.100.194.90:37805'], 'worker': ['10.100.194.215:38993', '10.100.194.90:46096', '10.100.194.217:42757']}\r\n2018-03-12 13:18:30,656 INFO (MainThread-75450) 0: Using GPU: 1\r\n2018-03-12 13:18:30.662680: I tensorflow/core/platform/cpu_feature_guard.cc:137] Your CPU supports instructions that this TensorFlow binary was not compiled to use: SSE4.1 SSE4.2 AVX AVX2 FMA\r\n2018-03-12 13:18:33.773353: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1105] Found device 0 with properties: \r\nname: Tesla M40 major: 5 minor: 2 memoryClockRate(GHz): 1.112\r\npciBusID: 0000:83:00.0\r\ntotalMemory: 11.17GiB freeMemory: 10.95GiB\r\n2018-03-12 13:18:33.773397: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1195] Creating TensorFlow device (/device:GPU:0) -> (device: 0, name: Tesla M40, pci bus id: 0000:83:00.0, compute capability: 5.2)\r\n2018-03-12 13:18:34.015885: I tensorflow/core/distributed_runtime/rpc/grpc_channel.cc:215] Initialize GrpcChannelCache for job ps -> {0 -> localhost:37805}\r\n2018-03-12 13:18:34.015935: I tensorflow/core/distributed_runtime/rpc/grpc_channel.cc:215] Initialize GrpcChannelCache for job worker -> {0 -> 10.100.194.215:38993, 1 -> 10.100.194.90:46096, 2 -> 10.100.194.217:42757}\r\n2018-03-12 13:18:34.018356: I tensorflow/core/distributed_runtime/rpc/grpc_server_lib.cc:324] Started server with target: grpc://localhost:37805\r\n======== PS SERVER===========\r\n18/03/12 13:18:36 WARN util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable\r\n```\r\n\r\nWorker 1 where we see the below waiting message :\r\n```\r\n18/03/12 13:18:09 INFO executor.CoarseGrainedExecutorBackend: Started daemon with process name: 74402@node194090\r\n18/03/12 13:18:09 INFO executor.CoarseGrainedExecutorBackend: Registered signal handlers for [TERM, HUP, INT]\r\n18/03/12 13:18:09 INFO spark.SecurityManager: Changing view acls to: yarn,root\r\n18/03/12 13:18:09 INFO spark.SecurityManager: Changing modify acls to: yarn,root\r\n18/03/12 13:18:09 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(yarn, root); users with modify permissions: Set(yarn, root)\r\n18/03/12 13:18:10 INFO spark.SecurityManager: Changing view acls to: yarn,root\r\n18/03/12 13:18:10 INFO spark.SecurityManager: Changing modify acls to: yarn,root\r\n18/03/12 13:18:10 INFO spark.SecurityManager: SecurityManager: authentication disabled; ui acls disabled; users with view permissions: Set(yarn, root); users with modify permissions: Set(yarn, root)\r\n18/03/12 13:18:10 INFO slf4j.Slf4jLogger: Slf4jLogger started\r\n18/03/12 13:18:10 INFO Remoting: Starting remoting\r\n18/03/12 13:18:10 INFO Remoting: Remoting started; listening on addresses :[akka.tcp://sparkExecutorActorSystem@node194090:36506]\r\n18/03/12 13:18:10 INFO Remoting: Remoting now listens on addresses: [akka.tcp://sparkExecutorActorSystem@node194090:36506]\r\n18/03/12 13:18:10 INFO util.Utils: Successfully started service 'sparkExecutorActorSystem' on port 36506.\r\n18/03/12 13:18:10 INFO storage.DiskBlockManager: Created local directory at /data1/yarn/nm/usercache/root/appcache/application_1520874763502_0012/blockmgr-a6cdb7fe-6dda-4597-8380-f958764e26bb\r\n18/03/12 13:18:10 INFO storage.MemoryStore: MemoryStore started with capacity 2.1 GB\r\n18/03/12 13:18:10 INFO executor.CoarseGrainedExecutorBackend: Connecting to driver: spark://CoarseGrainedScheduler@10.100.194.217:37199\r\n18/03/12 13:18:10 INFO executor.CoarseGrainedExecutorBackend: Successfully registered with driver\r\n18/03/12 13:18:10 INFO executor.Executor: Starting executor ID 3 on host node194090\r\n18/03/12 13:18:10 INFO util.Utils: Successfully started service 'org.apache.spark.network.netty.NettyBlockTransferService' on port 34955.\r\n18/03/12 13:18:10 INFO netty.NettyBlockTransferService: Server created on 34955\r\n18/03/12 13:18:10 INFO storage.BlockManager: external shuffle service port = 7337\r\n18/03/12 13:18:10 INFO storage.BlockManagerMaster: Trying to register BlockManager\r\n18/03/12 13:18:10 INFO storage.BlockManagerMaster: Registered BlockManager\r\n18/03/12 13:18:10 INFO storage.BlockManager: Registering executor with local external shuffle service.\r\n18/03/12 13:18:12 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 2\r\n18/03/12 13:18:12 INFO executor.Executor: Running task 2.0 in stage 0.0 (TID 2)\r\n18/03/12 13:18:12 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 2\r\n18/03/12 13:18:12 INFO storage.MemoryStore: Block broadcast_2_piece0 stored as bytes in memory (estimated size 8.0 KB, free 2.1 GB)\r\n18/03/12 13:18:12 INFO broadcast.TorrentBroadcast: Reading broadcast variable 2 took 95 ms\r\n18/03/12 13:18:12 INFO storage.MemoryStore: Block broadcast_2 stored as values in memory (estimated size 11.7 KB, free 2.1 GB)\r\n2018-03-12 13:18:13,474 INFO (MainThread-75245) connected to server at ('10.100.194.217', 42756)\r\n2018-03-12 13:18:13,475 INFO (MainThread-75245) TFSparkNode.reserve: {'authkey': 'F\\xa0\\nge\\xeeJ\\xb5\\xa0\\xf8\\xbfr.f\\xc0K', 'worker_num': 2, 'host': '10.100.194.90', 'tb_port': 0, 'addr': '/tmp/pymp-h267A9/listener-FAcTff', 'ppid': 75053, 'task_index': 1, 'job_name': 'worker', 'tb_pid': 0, 'port': 46096}\r\n2018-03-12 13:18:16,481 INFO (MainThread-75245) node: {'addr': ('10.100.194.90', 41401), 'task_index': 0, 'job_name': 'ps', 'authkey': '\\xf5\\xc9*C\\x84EC\\xf2\\xb5\\xd7j\\x8d\\x04\\x8b\\x80\\xea', 'worker_num': 0, 'host': '10.100.194.90', 'ppid': 75051, 'port': 37805, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,482 INFO (MainThread-75245) node: {'addr': '/tmp/pymp-g_uEG1/listener-nFtokO', 'task_index': 0, 'job_name': 'worker', 'authkey': '\\xc4y\\x85\\xc8\\xb6!G3\\xacm\\x13!\\xfb\\xca\\x82\\xe6', 'worker_num': 1, 'host': '10.100.194.215', 'ppid': 62585, 'port': 38993, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,482 INFO (MainThread-75245) node: {'addr': '/tmp/pymp-h267A9/listener-FAcTff', 'task_index': 1, 'job_name': 'worker', 'authkey': 'F\\xa0\\nge\\xeeJ\\xb5\\xa0\\xf8\\xbfr.f\\xc0K', 'worker_num': 2, 'host': '10.100.194.90', 'ppid': 75053, 'port': 46096, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,482 INFO (MainThread-75245) node: {'addr': '/tmp/pymp-wkzZQO/listener-xo8DCy', 'task_index': 2, 'job_name': 'worker', 'authkey': '\\x89\\xf1~j\\xae\\xacM\\xfc\\xb2\\xb8\\x14\\xa8\\xcd\\x81jt', 'worker_num': 3, 'host': '10.100.194.217', 'ppid': 78242, 'port': 42757, 'tb_pid': 0, 'tb_port': 0}\r\n2018-03-12 13:18:16,482 INFO (MainThread-75245) Starting TensorFlow worker:1 as worker on cluster node 2 on background process\r\n18/03/12 13:18:16 INFO python.PythonRunner: Times: total = 3788, boot = 575, init = 17, finish = 3196\r\n18/03/12 13:18:16 INFO executor.Executor: Finished task 2.0 in stage 0.0 (TID 2). 977 bytes result sent to driver\r\n2018-03-12 13:18:17,123 INFO (MainThread-75449) 2: ======== worker:1 ========\r\n2018-03-12 13:18:17,123 INFO (MainThread-75449) 2: Cluster spec: {'ps': ['10.100.194.90:37805'], 'worker': ['10.100.194.215:38993', '10.100.194.90:46096', '10.100.194.217:42757']}\r\n18/03/12 13:18:19 INFO executor.CoarseGrainedExecutorBackend: Got assigned task 6\r\n18/03/12 13:18:19 INFO executor.Executor: Running task 2.0 in stage 1.0 (TID 6)\r\n18/03/12 13:18:19 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 3\r\n18/03/12 13:18:19 INFO storage.MemoryStore: Block broadcast_3_piece0 stored as bytes in memory (estimated size 7.2 KB, free 2.1 GB)\r\n18/03/12 13:18:19 INFO broadcast.TorrentBroadcast: Reading broadcast variable 3 took 46 ms\r\n18/03/12 13:18:19 INFO storage.MemoryStore: Block broadcast_3 stored as values in memory (estimated size 14.0 KB, free 2.1 GB)\r\n18/03/12 13:18:19 INFO rdd.HadoopRDD: Input split: hdfs://node194215:8020/user/vap_admin_fid/tensorflow/images/part-00002:0+1811128\r\n18/03/12 13:18:19 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 0\r\n18/03/12 13:18:19 INFO storage.MemoryStore: Block broadcast_0_piece0 stored as bytes in memory (estimated size 25.4 KB, free 2.1 GB)\r\n18/03/12 13:18:19 INFO broadcast.TorrentBroadcast: Reading broadcast variable 0 took 15 ms\r\n18/03/12 13:18:19 INFO storage.MemoryStore: Block broadcast_0 stored as values in memory (estimated size 377.5 KB, free 2.1 GB)\r\n18/03/12 13:18:20 INFO Configuration.deprecation: mapred.tip.id is deprecated. Instead, use mapreduce.task.id\r\n18/03/12 13:18:20 INFO Configuration.deprecation: mapred.task.id is deprecated. Instead, use mapreduce.task.attempt.id\r\n18/03/12 13:18:20 INFO Configuration.deprecation: mapred.task.is.map is deprecated. Instead, use mapreduce.task.ismap\r\n18/03/12 13:18:20 INFO Configuration.deprecation: mapred.task.partition is deprecated. Instead, use mapreduce.task.partition\r\n18/03/12 13:18:20 INFO Configuration.deprecation: mapred.job.id is deprecated. Instead, use mapreduce.job.id\r\n18/03/12 13:18:20 INFO rdd.HadoopRDD: Input split: hdfs://node194215:8020/user/vap_admin_fid/tensorflow/labels/part-00002:0+40000\r\n18/03/12 13:18:20 INFO broadcast.TorrentBroadcast: Started reading broadcast variable 1\r\n18/03/12 13:18:20 INFO storage.MemoryStore: Block broadcast_1_piece0 stored as bytes in memory (estimated size 25.4 KB, free 2.1 GB)\r\n18/03/12 13:18:20 INFO broadcast.TorrentBroadcast: Reading broadcast variable 1 took 11 ms\r\n18/03/12 13:18:20 INFO storage.MemoryStore: Block broadcast_1 stored as values in memory (estimated size 377.5 KB, free 2.1 GB)\r\n2018-03-12 13:18:20,719 INFO (MainThread-75474) ********[{'addr': '/tmp/pymp-g_uEG1/listener-nFtokO', 'task_index': 0, 'job_name': 'worker', 'authkey': '\\xc4y\\x85\\xc8\\xb6!G3\\xacm\\x13!\\xfb\\xca\\x82\\xe6', 'worker_num': 1, 'host': '10.100.194.215', 'ppid': 62585, 'port': 38993, 'tb_pid': 0, 'tb_port': 0}, {'addr': '/tmp/pymp-h267A9/listener-FAcTff', 'task_index': 1, 'job_name': 'worker', 'authkey': 'F\\xa0\\nge\\xeeJ\\xb5\\xa0\\xf8\\xbfr.f\\xc0K', 'worker_num': 2, 'host': '10.100.194.90', 'ppid': 75053, 'port': 46096, 'tb_pid': 0, 'tb_port': 0}, {'addr': ('10.100.194.90', 41401), 'task_index': 0, 'job_name': 'ps', 'authkey': '\\xf5\\xc9*C\\x84EC\\xf2\\xb5\\xd7j\\x8d\\x04\\x8b\\x80\\xea', 'worker_num': 0, 'host': '10.100.194.90', 'ppid': 75051, 'port': 37805, 'tb_pid': 0, 'tb_port': 0}, {'addr': '/tmp/pymp-wkzZQO/listener-xo8DCy', 'task_index': 2, 'job_name': 'worker', 'authkey': '\\x89\\xf1~j\\xae\\xacM\\xfc\\xb2\\xb8\\x14\\xa8\\xcd\\x81jt', 'worker_num': 3, 'host': '10.100.194.217', 'ppid': 78242, 'port': 42757, 'tb_pid': 0, 'tb_port': 0}]\r\n2018-03-12 13:18:20,720 INFO (MainThread-75474) ********10.100.194.90\r\n2018-03-12 13:18:20,720 INFO (MainThread-75474) ********75053\r\n2018-03-12 13:18:20,720 INFO (MainThread-75474) ----------------------------------\r\n2018-03-12 13:18:20,725 INFO (MainThread-75474) Connected to TFSparkNode.mgr on 10.100.194.90, ppid=75053, state='running'\r\n2018-03-12 13:18:20,728 INFO (MainThread-75474) mgr.state='running'\r\n2018-03-12 13:18:20,728 INFO (MainThread-75474) Feeding partition <generator object load_stream at 0x7fb62621dfa0> into input queue <multiprocessing.queues.JoinableQueue object at 0x7fb6261afa50>\r\n18/03/12 13:18:20 INFO python.PythonRunner: Times: total = 404, boot = -4034, init = 4077, finish = 361\r\n18/03/12 13:18:20 INFO python.PythonRunner: Times: total = 15, boot = 2, init = 6, finish = 7\r\n2018-03-12 13:18:28,377 INFO (MainThread-75449) 2: Using GPU: 1\r\n2018-03-12 13:18:28.379503: I tensorflow/core/platform/cpu_feature_guard.cc:137] Your CPU supports instructions that this TensorFlow binary was not compiled to use: SSE4.1 SSE4.2 AVX AVX2 FMA\r\n2018-03-12 13:18:33.730500: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1105] Found device 0 with properties: \r\nname: Tesla M40 major: 5 minor: 2 memoryClockRate(GHz): 1.112\r\npciBusID: 0000:83:00.0\r\ntotalMemory: 11.17GiB freeMemory: 11.06GiB\r\n2018-03-12 13:18:33.730588: I tensorflow/core/common_runtime/gpu/gpu_device.cc:1195] Creating TensorFlow device (/device:GPU:0) -> (device: 0, name: Tesla M40, pci bus id: 0000:83:00.0, compute capability: 5.2)\r\n2018-03-12 13:18:34.140095: I tensorflow/core/distributed_runtime/rpc/grpc_channel.cc:215] Initialize GrpcChannelCache for job ps -> {0 -> 10.100.194.90:37805}\r\n2018-03-12 13:18:34.140131: I tensorflow/core/distributed_runtime/rpc/grpc_channel.cc:215] Initialize GrpcChannelCache for job worker -> {0 -> 10.100.194.215:38993, 1 -> localhost:46096, 2 -> 10.100.194.217:42757}\r\n2018-03-12 13:18:34.142438: I tensorflow/core/distributed_runtime/rpc/grpc_server_lib.cc:324] Started server with target: grpc://localhost:46096\r\ntensorflow model path: hdfs://node194215:8020/user/vap_admin_fid/tensorflow/mnist_model\r\n2018-03-12 13:18:34,477 WARNING (MainThread-75449) From /data1/yarn/nm/usercache/root/appcache/application_1520874763502_0012/container_1520874763502_0012_01_000004/__pyfiles__/mnist_dist.py:125: __init__ (from tensorflow.python.training.supervisor) is deprecated and will be removed in a future version.\r\nInstructions for updating:\r\nPlease switch to tf.train.MonitoredTrainingSession\r\n2018-03-12 13:18:34.653706: I tensorflow/core/distributed_runtime/master_session.cc:1017] Start master session bfd00b4d908af7d4 with config: \r\n2018-03-12 13:18:34,672 INFO (MainThread-75449) Waiting for model to be ready.  Ready_for_local_init_op:  None, ready: Variables not initialized: hid_w, hid_b, sm_w, sm_b, Variable, hid_w/Adagrad, hid_b/Adagrad, sm_w/Adagrad, sm_b/Adagrad\r\n2018-03-12 13:19:14.748934: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:19:24.749101: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:19:34.749245: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:19:44.749423: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:19:54.749576: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:20:04.749778: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:20:14.750193: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:20:24.750365: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:20:34.750553: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:20:44.750743: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:20:54.750937: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:21:04.751136: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:21:14.751305: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:21:24.751452: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:21:34.751600: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:21:44.751747: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:21:54.751902: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:22:04.752167: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:22:14.752332: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:22:24.752496: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:22:34.752667: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:22:44.752811: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n2018-03-12 13:22:54.753002: I tensorflow/core/distributed_runtime/master.cc:221] CreateSession still waiting for response from worker: /job:worker/replica:0/task:0\r\n```\r\nWhat could be the reason why worker 1 is not able to establish a session Let me know if am missing anything?\r\n"},"comment":{"url":"https://api.github.com/repos/yahoo/TensorFlowOnSpark/issues/comments/372503145","html_url":"https://github.com/yahoo/TensorFlowOnSpark/issues/244#issuecomment-372503145","issue_url":"https://api.github.com/repos/yahoo/TensorFlowOnSpark/issues/244","id":372503145,"user":{"login":"leewyang","id":3676078,"avatar_url":"https://avatars2.githubusercontent.com/u/3676078?v=4","gravatar_id":"","url":"https://api.github.com/users/leewyang","html_url":"https://github.com/leewyang","followers_url":"https://api.github.com/users/leewyang/followers","following_url":"https://api.github.com/users/leewyang/following{/other_user}","gists_url":"https://api.github.com/users/leewyang/gists{/gist_id}","starred_url":"https://api.github.com/users/leewyang/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/leewyang/subscriptions","organizations_url":"https://api.github.com/users/leewyang/orgs","repos_url":"https://api.github.com/users/leewyang/repos","events_url":"https://api.github.com/users/leewyang/events{/privacy}","received_events_url":"https://api.github.com/users/leewyang/received_events","type":"User","site_admin":false},"created_at":"2018-03-13T00:09:08Z","updated_at":"2018-03-13T00:09:08Z","author_association":"CONTRIBUTOR","body":"Can you try `--steps 10000 --epochs 10`?   When you use `--steps 10`, it's entirely possible that one node \"finishes\" before the other nodes even start, so they'll be unable to correctly form the cluster."}}
{"actor":{"display_login":"leewyang"}}