{"action":"created","issue":{"url":"https://api.github.com/repos/tensorflow/tensorflow/issues/16942","repository_url":"https://api.github.com/repos/tensorflow/tensorflow","labels_url":"https://api.github.com/repos/tensorflow/tensorflow/issues/16942/labels{/name}","comments_url":"https://api.github.com/repos/tensorflow/tensorflow/issues/16942/comments","events_url":"https://api.github.com/repos/tensorflow/tensorflow/issues/16942/events","html_url":"https://github.com/tensorflow/tensorflow/issues/16942","id":296277286,"number":16942,"title":"wrapping op in while_loop makes it run faster, even with single iteration","user":{"login":"apisutilis","id":2754832,"avatar_url":"https://avatars3.githubusercontent.com/u/2754832?v=4","gravatar_id":"","url":"https://api.github.com/users/apisutilis","html_url":"https://github.com/apisutilis","followers_url":"https://api.github.com/users/apisutilis/followers","following_url":"https://api.github.com/users/apisutilis/following{/other_user}","gists_url":"https://api.github.com/users/apisutilis/gists{/gist_id}","starred_url":"https://api.github.com/users/apisutilis/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/apisutilis/subscriptions","organizations_url":"https://api.github.com/users/apisutilis/orgs","repos_url":"https://api.github.com/users/apisutilis/repos","events_url":"https://api.github.com/users/apisutilis/events{/privacy}","received_events_url":"https://api.github.com/users/apisutilis/received_events","type":"User","site_admin":false},"labels":[{"id":386191887,"url":"https://api.github.com/repos/tensorflow/tensorflow/labels/stat:awaiting%20response","name":"stat:awaiting response","color":"5319e7","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2018-02-12T06:28:02Z","updated_at":"2018-02-14T17:29:40Z","closed_at":null,"author_association":"NONE","body":"### System information\r\n- **Have I written custom code (as opposed to using a stock example script provided in TensorFlow)**: Yes\r\n- **OS Platform and Distribution (e.g., Linux Ubuntu 16.04)**:  Linux Ubuntu 16.04\r\n- **TensorFlow installed from (source or binary)**: Source\r\n- **TensorFlow version (use command below)**: v1.5.0-0-g37aa430 (1.5.0)\r\n- **Python version**: 3.5.2\r\n- **Bazel version (if compiling from source)**: 0.9.0\r\n- **GCC/Compiler version (if compiling from source)**:\r\n- **CUDA/cuDNN version**: CUDA 9.1, CuDNN 7\r\n- **GPU model and memory**: GeForce GTX 1050, 4042MiB\r\n- **Exact command to reproduce**: See below\r\n\r\n### Describe the problem\r\n\r\nI am working on an object detector. I have one entry point to my code that detects objects in a single image, and another that reads in a batch of images. The batch version uses `tf.while_loop` to apply the same inference code to each image in the batch. I can't put all the images into a single tensor because they are all likely to be different dimensions, so I am using a `TensorArray`. The final results work as expected, but the timing behavior is odd.\r\n\r\nThe first `sess.run` call in the loop over the dataset is always slower than the rest, presumably due to caching, memory allocation, etc. However, the first call in the non-batch version is WAY slower than the first call in the batch version. I distilled this down to the minimal examples below. The first version does a dot product in a straightforward way. On my machine, it takes about 13 seconds to run. The second version does the same dot product, but wrapped in a `while_loop` and writing the result to an intermediate `TensorArray` and then reading it out again. On my machine, it takes about 4 seconds to run. Presumably, version 2 has to do the same data copying, memory allocation, etc. as version 1, in addition to the overhead of the `while_loop` and `TensorArray` calls. So, the timing behavior is unexpected.\r\n\r\nVersion 2 can even be modified to compute the same dot product 10 (or more) times, and it will still run faster. This behavior holds even if the loop body is modified to use a random vector every time, so I don't think it is due to caching. It also holds even if `parallel_iterations` is held to `1`, so I don't think it is due to parallelism. Is this a bug, or is something else going on under the hood?\r\n\r\n### Source code / logs\r\n\r\n```python\r\n# version 1 (~13 seconds on my machine)\r\ngraph = tf.Graph()\r\nwith graph.as_default(), tf.device('/gpu:0'):\r\n    nums = tf.range(200000000, dtype=tf.float32)\r\n    dot_product = tf.reduce_sum((nums/2) * (nums-5))\r\nwith tf.Session(graph=graph) as sess:\r\n    print(sess.run(dot_product))\r\n```\r\n\r\n```python\r\n# version 2 (~4 seconds on my machine)\r\ngraph = tf.Graph()\r\nwith graph.as_default(), tf.device('/gpu:0'):\r\n    arr = tf.TensorArray(size=1, dtype=tf.float32)\r\n    nums = tf.range(200000000, dtype=tf.float32)\r\n    i = tf.constant(0)\r\n    def body(i, arr):\r\n        arr = arr.write(i, tf.reduce_sum((nums/2) * (nums-5)))\r\n        return i+1, arr\r\n    i, arr = tf.while_loop(\r\n        cond=lambda i, x: i < 1,\r\n        body=body,\r\n        loop_vars=[i, arr],\r\n        parallel_iterations=1)\r\n    dot_product = arr.read(0)\r\nwith tf.Session(graph=graph) as sess:\r\n    print(sess.run(dot_product))\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/tensorflow/tensorflow/issues/comments/365683126","html_url":"https://github.com/tensorflow/tensorflow/issues/16942#issuecomment-365683126","issue_url":"https://api.github.com/repos/tensorflow/tensorflow/issues/16942","id":365683126,"user":{"login":"prb12","id":11547801,"avatar_url":"https://avatars1.githubusercontent.com/u/11547801?v=4","gravatar_id":"","url":"https://api.github.com/users/prb12","html_url":"https://github.com/prb12","followers_url":"https://api.github.com/users/prb12/followers","following_url":"https://api.github.com/users/prb12/following{/other_user}","gists_url":"https://api.github.com/users/prb12/gists{/gist_id}","starred_url":"https://api.github.com/users/prb12/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/prb12/subscriptions","organizations_url":"https://api.github.com/users/prb12/orgs","repos_url":"https://api.github.com/users/prb12/repos","events_url":"https://api.github.com/users/prb12/events{/privacy}","received_events_url":"https://api.github.com/users/prb12/received_events","type":"User","site_admin":false},"created_at":"2018-02-14T17:29:40Z","updated_at":"2018-02-14T17:29:40Z","author_association":"MEMBER","body":"The first session.run call being slower is almost certainly due to running the constant folder to optimize the graph.  When session.run is called for the first time on a set of feeds/fetches, the constant folder will run and parts of the graph will be replaced with a tf.constant node that has a protobuf containing the constant values.  Potential constants are always evaluated on the CPU device.  (Also, if the resulting value is larger than a certain threshold then it is discarded and the graph is left alone).\r\n\r\nIt it likely that when the same expression is computed in a loop the constant folder doesn't consider it a candidate.\r\n\r\nIn your code snippets above, you only time a single session.run call for each variant...   I would expect constant folding overheads (and many other overheads) to only affect the first execution of each graph.  \r\n\r\nIf you do a warmup sess.run(dot_product) call, then put a loop around multiple calls of sess.run(dot_product) and evaluate it repeatedly, do you still see the loop version runnig faster?   If so then this is worth looking into further!\r\n\r\ni.e. something like:\r\n```\r\nwith tf.Session(graph=graph) as sess:\r\n   print(sess.run(dot_product))\r\n   t1 = default_timer()\r\n   for _ in xrange(10):\r\n       sess.run(dot_product)\r\n   print(\"time v1: {}\".format(default_timer() - t1))\r\n```"}}
{"actor":{"display_login":"prb12"}}