title: distributed Tensorflow tracking timestamps for synchronization operations
body: <p>I am new to TensorFlow. Currently, I am trying to evaluate the performance of distributed TensorFlow using <code>Inception</code> model provided by TensorFlow team.</p>
  
  <p>The thing I want is to generate timestamps for some critical operations in a Parameter Server - Worker architecture, so I can measure the bottleneck (the network lag due to parameter transfer/synchronization or parameter computation cost) on replicas for one iteration (batch).</p>
  
  <p>I came up with the idea of adding a customized dummy <code>py_func</code> operator designated of printing timestamps inside <code>inception_distributed_train.py</code>, with some control dependencies. Here are some pieces of code that I added:</p>
  
  <pre><code>def timer(s):
    print ("-------- thread ID ", threading.current_thread().ident, ", ---- Process ID ----- ", getpid(), " ~~~~~~~~~~~~~~~ ", s, datetime.fromtimestamp(time.time()).strftime('%Y-%m-%d %H:%M:%S.%f'))
    return Falsedf
  
  dummy1 = tf.py_func(timer, ["got gradients, before dequeues token  "], tf.bool)
  dummy2 = tf.py_func(timer, ["finished dequeueing the token         "], tf.bool)
  </code></pre>
  
  <p>I modified </p>
  
  <pre><code>apply_gradients_op = opt.apply_gradients(grads, global_step=global_step)
  with tf.control_dependencies([apply_gradients_op]):
    train_op = tf.identity(total_loss, name='train_op')
  </code></pre>
  
  <p>into</p>
  
  <pre><code>with tf.control_dependencies([dummy1]):
      apply_gradients_op = opt.apply_gradients(grads, global_step=global_step)
      with tf.control_dependencies([apply_gradients_op]):
        with tf.control_dependencies([dummy2]):
          train_op = tf.identity(total_loss, name='train_op')  
  </code></pre>
  
  <p>hoping to print the timestamps before evaluating the <code>apply_gradient_op</code> and after finishing evaluating the <code>apply_gradient_op</code> by enforcing node dependencies.</p>
  
  <p>I did similar things inside <code>sync_replicas_optimizer.apply_gradients</code>, by adding two dummy print nodes before and after <code>update_op</code>:</p>
  
  <pre><code>        dummy1 = py_func(timer, ["---------- before update_op   "], tf_bool)
          dummy2 = py_func(timer, ["---------- finished update_op "], tf_bool)
  
          # sync_op will be assigned to the same device as the global step.
          with ops.device(global_step.device), ops.name_scope(""):
              with ops.control_dependencies([dummy1]):
                  update_op = self._opt.apply_gradients(aggregated_grads_and_vars, global_step)
  
          # Clear all the gradients queues in case there are stale gradients.
          clear_queue_ops = []
          with ops.control_dependencies([update_op]):
              with ops.control_dependencies([dummy2]):
                  for queue, dev in self._one_element_queue_list:
                      with ops.device(dev):
                          stale_grads = queue.dequeue_many(queue.size())
                          clear_queue_ops.append(stale_grads)
  </code></pre>
  
  <p>I understand that <code>apply_gradient_op</code> is the <code>train_op</code> returned by <code>sync_replicas_optimizer.apply_gradient</code>. And <code>apply_gradient_op</code> is the op to dequeue a token (<code>global_step</code>) from <code>sync_queue</code> managed by the chief worker using <code>chief_queue_runner</code>, so that replica can exit current batch and start a new batch. </p>
  
  <p>In theory, <code>apply_gradient_op</code> should take some time as replica has to wait before it can dequeue the token (<code>global_step</code>) from <code>sync_queue</code>, but the print result for one replica I got, such as the time differences for executing apply_gradient_op is pretty short (~1/1000 sec) and sometimes the print output is indeterministic (especially for chief worker). Here is a snippet of the output on the workers (I am running 2 workers and 1 PS):</p>
  
  <p><a href="https://i.stack.imgur.com/cHbG7.png" rel="nofollow noreferrer">chief worker (worker 0) output</a></p>
  
  <p><a href="https://i.stack.imgur.com/ZsTkI.png" rel="nofollow noreferrer">worker 1 output</a></p>
  
  <blockquote>
    <p>My questions are:</p>
    
    <p>1) I need to record the time TensorFlow takes to execute an <code>op</code> (such as <code>train_op</code>, <code>apply_gradients_op</code>, <code>compute_gradients_op</code>, etc.)</p>
    
    <p>2) Is this the right direction to go, given my ultimate goal is to record the elapsed time for executing certain operations (such as the difference between the time a replica finishes computing gradients and the time it gets the <code>global_step</code> from <code>sync_token</code>)?</p>
    
    <p>3) If this is not the way it should go, please guide me with some insights about the possible ways I could achieve my ultimate goal.</p>
    
    <p>Thank you so much for reading my long long posts. as I have spent weeks working on this!</p>
  </blockquote>