<p dir="auto">Hello,</p>
<p dir="auto">I'm following the tf.profiler.Profiler guide to profile my code.<br>
When generating the timelines, all of them except the first one (for the first batch) are scaled in hundreds of years, rather than seconds.</p>
<p dir="auto">There is something happening at year 0, then something going on after 583 years.<br>
No, my DNN code is not that slow.<br>
<a target="_blank" rel="noopener noreferrer nofollow" href="https://user-images.githubusercontent.com/6018251/45128332-5c24b680-b175-11e8-96f6-c5cc9abee2d4.png"><img src="https://user-images.githubusercontent.com/6018251/45128332-5c24b680-b175-11e8-96f6-c5cc9abee2d4.png" alt="screenshot_2018-09-05_23-19-38" style="max-width: 100%;"></a><br>
Running the latest stable version of everything.</p>
<p dir="auto">Could you please recommend me a fix?<br>
Thank you</p>
<h3 dir="auto">System information</h3>
<ul dir="auto">
<li><strong>Have I written custom code (as opposed to using a stock example script provided in TensorFlow)</strong>:yes</li>
<li><strong>OS Platform and Distribution (e.g., Linux Ubuntu 16.04)</strong>:Ubuntu 16.04</li>
<li><strong>TensorFlow installed from (source or binary)</strong>:binary</li>
<li><strong>TensorFlow version (use command below)</strong>:v1.9.0-0-g25c197e023 1.9.0</li>
<li><strong>Python version</strong>: 3.6</li>
<li><strong>Bazel version (if compiling from source)</strong>:n/a</li>
<li><strong>GCC/Compiler version (if compiling from source)</strong>:n/a</li>
<li><strong>CUDA/cuDNN version</strong>:9.0.176/7.1.1</li>
<li><strong>GPU model and memory</strong>:P100 16G (can reproduce on other GPU model as well)</li>
<li><strong>Exact command to reproduce</strong>: see below</li>
</ul>
<div class="highlight highlight-source-python notranslate position-relative overflow-auto" dir="auto" data-snippet-clipboard-copy-content="#!/usr/bin/env python
# -*- coding: utf-8 -*-

import sys
import os
import tqdm
from datetime import datetime
import tensorflow as tf
from tensorflow.python.client import timeline

def build():
    image = tf.random_normal(shape=[64,32,32,3], dtype=tf.float32)
    label = tf.random_uniform(shape=[64], maxval=10, dtype=tf.int32)
    l = tf.transpose(image, [0, 3, 1, 2])
    for k in range(1, 100):
        l = tf.layers.conv2d(l, 16, 3, data_format='channels_first',
                name='conv{}'.format(k), padding='SAME')
    l = tf.reduce_mean(l, [2, 3])

    logits = tf.layers.dense(l, 10, name='linear')
    cost = tf.nn.sparse_softmax_cross_entropy_with_logits(logits=logits, labels=label)
    cost = tf.reduce_mean(cost, name='cross_entropy_loss')
    return cost

if __name__ == '__main__':
    with tf.device('/gpu:0'):
        cost1 = build()
    with tf.device('/gpu:1'), tf.variable_scope(tf.get_variable_scope(), reuse=True):
        cost2 = build()
    cost = cost1 + cost2
    opt = tf.train.GradientDescentOptimizer(0.1)
    train_op = opt.minimize(cost)

    def write_tracing(idx, metadata):
        tl = timeline.Timeline(step_stats=metadata.step_stats)
        fname = os.path.join(
            '.', 'chrome-trace-{}.json'.format(idx))
        with open(fname, 'w') as f:
            f.write(tl.generate_chrome_trace_format(
                show_dataflow=True, show_memory=True))

    config = tf.ConfigProto()
    config.allow_soft_placement = True
    with tf.Session(config=config) as sess:
        sess.run(tf.global_variables_initializer())
        opt = tf.RunOptions()
        opt.trace_level = tf.RunOptions.FULL_TRACE

        for k in tqdm.trange(100):
            meta = tf.RunMetadata()
            sess.run(train_op, options=opt, run_metadata=meta)

            write_tracing(k, meta)

            for devst in meta.step_stats.dev_stats:
                for ns in devst.node_stats:
                    micro = timestamp = ns.all_start_micros // 1000000
                    timestamp = datetime.fromtimestamp(timestamp)
                    diff = timestamp - datetime.now()
                    if diff.days &gt; 100:
                        print(k, micro, timestamp)
                        #import IPython as IP; IP.embed()
                        #sys.exit()"><pre class="notranslate"><span class="pl-c">#!/usr/bin/env python</span>
<span class="pl-c"># -*- coding: utf-8 -*-</span>

<span class="pl-k">import</span> <span class="pl-s1">sys</span>
<span class="pl-k">import</span> <span class="pl-s1">os</span>
<span class="pl-k">import</span> <span class="pl-s1">tqdm</span>
<span class="pl-k">from</span> <span class="pl-s1">datetime</span> <span class="pl-k">import</span> <span class="pl-s1">datetime</span>
<span class="pl-k">import</span> <span class="pl-s1">tensorflow</span> <span class="pl-k">as</span> <span class="pl-s1">tf</span>
<span class="pl-k">from</span> <span class="pl-s1">tensorflow</span>.<span class="pl-s1">python</span>.<span class="pl-s1">client</span> <span class="pl-k">import</span> <span class="pl-s1">timeline</span>

<span class="pl-k">def</span> <span class="pl-en">build</span>():
    <span class="pl-s1">image</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-en">random_normal</span>(<span class="pl-s1">shape</span><span class="pl-c1">=</span>[<span class="pl-c1">64</span>,<span class="pl-c1">32</span>,<span class="pl-c1">32</span>,<span class="pl-c1">3</span>], <span class="pl-s1">dtype</span><span class="pl-c1">=</span><span class="pl-s1">tf</span>.<span class="pl-s1">float32</span>)
    <span class="pl-s1">label</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-en">random_uniform</span>(<span class="pl-s1">shape</span><span class="pl-c1">=</span>[<span class="pl-c1">64</span>], <span class="pl-s1">maxval</span><span class="pl-c1">=</span><span class="pl-c1">10</span>, <span class="pl-s1">dtype</span><span class="pl-c1">=</span><span class="pl-s1">tf</span>.<span class="pl-s1">int32</span>)
    <span class="pl-s1">l</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-en">transpose</span>(<span class="pl-s1">image</span>, [<span class="pl-c1">0</span>, <span class="pl-c1">3</span>, <span class="pl-c1">1</span>, <span class="pl-c1">2</span>])
    <span class="pl-k">for</span> <span class="pl-s1">k</span> <span class="pl-c1">in</span> <span class="pl-en">range</span>(<span class="pl-c1">1</span>, <span class="pl-c1">100</span>):
        <span class="pl-s1">l</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-s1">layers</span>.<span class="pl-en">conv2d</span>(<span class="pl-s1">l</span>, <span class="pl-c1">16</span>, <span class="pl-c1">3</span>, <span class="pl-s1">data_format</span><span class="pl-c1">=</span><span class="pl-s">'channels_first'</span>,
                <span class="pl-s1">name</span><span class="pl-c1">=</span><span class="pl-s">'conv{}'</span>.<span class="pl-en">format</span>(<span class="pl-s1">k</span>), <span class="pl-s1">padding</span><span class="pl-c1">=</span><span class="pl-s">'SAME'</span>)
    <span class="pl-s1">l</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-en">reduce_mean</span>(<span class="pl-s1">l</span>, [<span class="pl-c1">2</span>, <span class="pl-c1">3</span>])

    <span class="pl-s1">logits</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-s1">layers</span>.<span class="pl-en">dense</span>(<span class="pl-s1">l</span>, <span class="pl-c1">10</span>, <span class="pl-s1">name</span><span class="pl-c1">=</span><span class="pl-s">'linear'</span>)
    <span class="pl-s1">cost</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-s1">nn</span>.<span class="pl-en">sparse_softmax_cross_entropy_with_logits</span>(<span class="pl-s1">logits</span><span class="pl-c1">=</span><span class="pl-s1">logits</span>, <span class="pl-s1">labels</span><span class="pl-c1">=</span><span class="pl-s1">label</span>)
    <span class="pl-s1">cost</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-en">reduce_mean</span>(<span class="pl-s1">cost</span>, <span class="pl-s1">name</span><span class="pl-c1">=</span><span class="pl-s">'cross_entropy_loss'</span>)
    <span class="pl-k">return</span> <span class="pl-s1">cost</span>

<span class="pl-k">if</span> <span class="pl-s1">__name__</span> <span class="pl-c1">==</span> <span class="pl-s">'__main__'</span>:
    <span class="pl-k">with</span> <span class="pl-s1">tf</span>.<span class="pl-en">device</span>(<span class="pl-s">'/gpu:0'</span>):
        <span class="pl-s1">cost1</span> <span class="pl-c1">=</span> <span class="pl-en">build</span>()
    <span class="pl-k">with</span> <span class="pl-s1">tf</span>.<span class="pl-en">device</span>(<span class="pl-s">'/gpu:1'</span>), <span class="pl-s1">tf</span>.<span class="pl-en">variable_scope</span>(<span class="pl-s1">tf</span>.<span class="pl-en">get_variable_scope</span>(), <span class="pl-s1">reuse</span><span class="pl-c1">=</span><span class="pl-c1">True</span>):
        <span class="pl-s1">cost2</span> <span class="pl-c1">=</span> <span class="pl-en">build</span>()
    <span class="pl-s1">cost</span> <span class="pl-c1">=</span> <span class="pl-s1">cost1</span> <span class="pl-c1">+</span> <span class="pl-s1">cost2</span>
    <span class="pl-s1">opt</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-s1">train</span>.<span class="pl-v">GradientDescentOptimizer</span>(<span class="pl-c1">0.1</span>)
    <span class="pl-s1">train_op</span> <span class="pl-c1">=</span> <span class="pl-s1">opt</span>.<span class="pl-en">minimize</span>(<span class="pl-s1">cost</span>)

    <span class="pl-k">def</span> <span class="pl-en">write_tracing</span>(<span class="pl-s1">idx</span>, <span class="pl-s1">metadata</span>):
        <span class="pl-s1">tl</span> <span class="pl-c1">=</span> <span class="pl-s1">timeline</span>.<span class="pl-v">Timeline</span>(<span class="pl-s1">step_stats</span><span class="pl-c1">=</span><span class="pl-s1">metadata</span>.<span class="pl-s1">step_stats</span>)
        <span class="pl-s1">fname</span> <span class="pl-c1">=</span> <span class="pl-s1">os</span>.<span class="pl-s1">path</span>.<span class="pl-en">join</span>(
            <span class="pl-s">'.'</span>, <span class="pl-s">'chrome-trace-{}.json'</span>.<span class="pl-en">format</span>(<span class="pl-s1">idx</span>))
        <span class="pl-k">with</span> <span class="pl-en">open</span>(<span class="pl-s1">fname</span>, <span class="pl-s">'w'</span>) <span class="pl-k">as</span> <span class="pl-s1">f</span>:
            <span class="pl-s1">f</span>.<span class="pl-en">write</span>(<span class="pl-s1">tl</span>.<span class="pl-en">generate_chrome_trace_format</span>(
                <span class="pl-s1">show_dataflow</span><span class="pl-c1">=</span><span class="pl-c1">True</span>, <span class="pl-s1">show_memory</span><span class="pl-c1">=</span><span class="pl-c1">True</span>))

    <span class="pl-s1">config</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-v">ConfigProto</span>()
    <span class="pl-s1">config</span>.<span class="pl-s1">allow_soft_placement</span> <span class="pl-c1">=</span> <span class="pl-c1">True</span>
    <span class="pl-k">with</span> <span class="pl-s1">tf</span>.<span class="pl-v">Session</span>(<span class="pl-s1">config</span><span class="pl-c1">=</span><span class="pl-s1">config</span>) <span class="pl-k">as</span> <span class="pl-s1">sess</span>:
        <span class="pl-s1">sess</span>.<span class="pl-en">run</span>(<span class="pl-s1">tf</span>.<span class="pl-en">global_variables_initializer</span>())
        <span class="pl-s1">opt</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-v">RunOptions</span>()
        <span class="pl-s1">opt</span>.<span class="pl-s1">trace_level</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-v">RunOptions</span>.<span class="pl-v">FULL_TRACE</span>

        <span class="pl-k">for</span> <span class="pl-s1">k</span> <span class="pl-c1">in</span> <span class="pl-s1">tqdm</span>.<span class="pl-en">trange</span>(<span class="pl-c1">100</span>):
            <span class="pl-s1">meta</span> <span class="pl-c1">=</span> <span class="pl-s1">tf</span>.<span class="pl-v">RunMetadata</span>()
            <span class="pl-s1">sess</span>.<span class="pl-en">run</span>(<span class="pl-s1">train_op</span>, <span class="pl-s1">options</span><span class="pl-c1">=</span><span class="pl-s1">opt</span>, <span class="pl-s1">run_metadata</span><span class="pl-c1">=</span><span class="pl-s1">meta</span>)

            <span class="pl-en">write_tracing</span>(<span class="pl-s1">k</span>, <span class="pl-s1">meta</span>)

            <span class="pl-k">for</span> <span class="pl-s1">devst</span> <span class="pl-c1">in</span> <span class="pl-s1">meta</span>.<span class="pl-s1">step_stats</span>.<span class="pl-s1">dev_stats</span>:
                <span class="pl-k">for</span> <span class="pl-s1">ns</span> <span class="pl-c1">in</span> <span class="pl-s1">devst</span>.<span class="pl-s1">node_stats</span>:
                    <span class="pl-s1">micro</span> <span class="pl-c1">=</span> <span class="pl-s1">timestamp</span> <span class="pl-c1">=</span> <span class="pl-s1">ns</span>.<span class="pl-s1">all_start_micros</span> <span class="pl-c1">//</span> <span class="pl-c1">1000000</span>
                    <span class="pl-s1">timestamp</span> <span class="pl-c1">=</span> <span class="pl-s1">datetime</span>.<span class="pl-en">fromtimestamp</span>(<span class="pl-s1">timestamp</span>)
                    <span class="pl-s1">diff</span> <span class="pl-c1">=</span> <span class="pl-s1">timestamp</span> <span class="pl-c1">-</span> <span class="pl-s1">datetime</span>.<span class="pl-en">now</span>()
                    <span class="pl-k">if</span> <span class="pl-s1">diff</span>.<span class="pl-s1">days</span> <span class="pl-c1">&gt;</span> <span class="pl-c1">100</span>:
                        <span class="pl-en">print</span>(<span class="pl-s1">k</span>, <span class="pl-s1">micro</span>, <span class="pl-s1">timestamp</span>)
                        <span class="pl-c">#import IPython as IP; IP.embed()</span>
                        <span class="pl-c">#sys.exit()</span></pre></div>
<p dir="auto">The code above trains a CNN on two GPUs with <code class="notranslate">FULL_TRACE</code> enabled. The returned profiling information contains correct timestamps, but sometimes contains timestamps that are many years in the future. It prints the following output:</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="...
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33
..."><pre class="notranslate"><code class="notranslate">...
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33                                                                                                                                                                  
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33               
13 18446744073 2554-07-21 16:34:33
...
</code></pre></div>
<p dir="auto">The issue was originally reported at <a class="issue-link js-issue-link" data-error-text="Failed to load title" data-id="340169545" data-permission-text="Title is private" data-url="https://github.com/tensorpack/tensorpack/issues/819" data-hovercard-type="issue" data-hovercard-url="/tensorpack/tensorpack/issues/819/hovercard" href="https://github.com/tensorpack/tensorpack/issues/819">tensorpack/tensorpack#819</a>.<br>
The issue is more likely to happen after running about 50 steps.<br>
The issue seems to disappear when training on one GPU, or training a small model.</p>