Issue 1:
Hello,

I'm following the tf.profiler.Profiler guide to profile my code.

When generating the timelines, all of them except the first one (for the first batch) are scaled in hundreds of years, rather than seconds.

There is something happening at year 0, then something going on after 583 years.

No, my DNN code is not that slow.

Running the latest stable version of everything.

Could you please recommend me a fix?

Thank you

Issue 2:
System information

Have I written custom code (as opposed to using a stock example script provided in TensorFlow):yes

OS Platform and Distribution (e.g., Linux Ubuntu 16.04):Ubuntu 16.04

TensorFlow installed from (source or binary):binary

TensorFlow version (use command below):v1.9.0-0-g25c197e023 1.9.0

Python version: 3.6

Bazel version (if compiling from source):n/a

GCC/Compiler version (if compiling from source):n/a

CUDA/cuDNN version:9.0.176/7.1.1

GPU model and memory:P100 16G (can reproduce on other GPU model as well)

Exact command to reproduce: see below

#!/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 > 100:
print(k, micro, timestamp)
#import IPython as IP; IP.embed()
#sys.exit()

The code above trains a CNN on two GPUs with FULL_TRACE enabled. The returned profiling information contains correct timestamps, but sometimes contains timestamps that are many years in the future. It prints the following output:

...
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
...

The issue was originally reported at tensorpack/tensorpack#819.

The issue is more likely to happen after running about 50 steps.

The issue seems to disappear when training on one GPU, or training a small model.