Increase detail when reporting computational throughput and latency

[felker]

Currently, FRNN reports the following metrics related to computational speed/efficiency during training:
Per step, per epoch:

• Examples/sec
• sec/batch
  • % of batch time spent in calculation vs. synchronization
• overall batch size = batch size per GPU x N_GPU

As we become more cognizant about our performance expectations for the code on various architectures, I think it would be valuable to make these metrics more informative.

• At end of each epoch: summarize Min/Max, Mean, Std-dev of Examples/sec, sec/batch, % calc, % sync of all steps within that epoch
• At end of all epochs: same statistics across epochs?
• Add greater granularity of timing information within an epoch?

For the final performance metrics (at the end of all epochs), we should probably exclude the first epoch or so, due to TensorFlow invocation of cuDNN autotuner on the first invocation of tf.Session.run() when the undocumented environment variable TF_CUDNN_USE_AUTOTUNE=1. See https://github.com/tensorflow/tensorflow/blob/fddd829a0795a98b1bdac63c5acaed2c3d8122ff/tensorflow/core/util/use_cudnn.cc#L36 and https://stackoverflow.com/questions/45063489/first-tf-session-run-performs-dramatically-different-from-later-runs-why for an explanation

Although I wonder if the initial run that is thrown away in order to force compilation already accomplishes this?

plasma-python/plasma/models/mpi_runner.py

Lines 549 to 564 in c82ba61

	# run the model once to force compilation. Don't actually use these
	# values.
	if first_run:
	first_run = False
	t0_comp = time.time()
	# print('input_dimension:',batch_xs.shape)
	# print('output_dimension:',batch_ys.shape)
	_, _ = self.train_on_batch_and_get_deltas(
	batch_xs, batch_ys, verbose)
	self.comm.Barrier()
	sys.stdout.flush()
	# TODO(KGF): check line feed/carriage returns around this
	g.print_unique('\nCompilation finished in {:.2f}s'.format(
	time.time() - t0_comp))
	t_start = time.time()
	sys.stdout.flush()

since it calls Keras train_on_batch().

Note, I have tested the effects of the TF_CUDNN_USE_AUTOTUNE variable on the https://github.com/tensorflow/benchmarks , specifically

srun -n 1 python tf_cnn_benchmarks.py --num_gpus=1 --batch_size=32 --model=resnet50 --variable_update=parameter_server

on Traverse V100s and TigerGPU P100s, and disabling the autotuner leads to a loss of about 10% performance:

P100:

Click to expand!

TensorFlow: 1.13
Model: resnet50
Dataset: imagenet (synthetic)
Mode: training
SingleSess: False
Batch size: 32 global
 32 per device
Num batches: 100
Num epochs: 0.00
Devices: ['/gpu:0']
NUMA bind: False
Data format: NCHW
Optimizer: sgd
Variables: parameter_server
==========
Generating training model
Initializing graph
Running warm up
Done warm up
Step Img/sec total_loss
1 images/sec: 223.9 +/- 0.0 (jitter = 0.0) 8.169
10 images/sec: 223.9 +/- 0.1 (jitter = 0.3) 7.593
20 images/sec: 223.7 +/- 0.1 (jitter = 0.3) 7.696
30 images/sec: 223.6 +/- 0.1 (jitter = 0.3) 7.753
40 images/sec: 223.6 +/- 0.1 (jitter = 0.3) 8.007
50 images/sec: 223.4 +/- 0.1 (jitter = 0.3) 7.520
60 images/sec: 223.3 +/- 0.1 (jitter = 0.4) 7.988
70 images/sec: 223.3 +/- 0.1 (jitter = 0.4) 8.028
80 images/sec: 223.4 +/- 0.1 (jitter = 0.4) 7.932
90 images/sec: 223.5 +/- 0.1 (jitter = 0.5) 7.848
100 images/sec: 223.5 +/- 0.1 (jitter = 0.5) 7.796
----------------------------------------------------------------
total images/sec: 223.38
----------------------------------------------------------------

-----------------------------------------------------------------------------
export TF_CUDNN_USE_AUTOTUNE=0
-----------------------------------------------------------------------------

TensorFlow: 1.13
Model: resnet50
Dataset: imagenet (synthetic)
Mode: training
SingleSess: False
Batch size: 32 global
 32 per device
Num batches: 100
Num epochs: 0.00
Devices: ['/gpu:0']
NUMA bind: False
Data format: NCHW
Optimizer: sgd
Variables: parameter_server
==========
Generating training model
Initializing graph
Running warm up
Done warm up
Step Img/sec total_loss
1 images/sec: 204.8 +/- 0.0 (jitter = 0.0) 8.169
10 images/sec: 204.8 +/- 0.0 (jitter = 0.1) 7.593
20 images/sec: 204.8 +/- 0.0 (jitter = 0.2) 7.696
30 images/sec: 204.8 +/- 0.1 (jitter = 0.2) 7.753
40 images/sec: 204.8 +/- 0.1 (jitter = 0.2) 8.007
50 images/sec: 204.8 +/- 0.0 (jitter = 0.2) 7.520
60 images/sec: 204.8 +/- 0.0 (jitter = 0.2) 7.988
70 images/sec: 204.8 +/- 0.1 (jitter = 0.2) 8.027
80 images/sec: 204.8 +/- 0.1 (jitter = 0.2) 7.931
90 images/sec: 204.9 +/- 0.1 (jitter = 0.3) 7.850
100 images/sec: 204.9 +/- 0.1 (jitter = 0.3) 7.797
----------------------------------------------------------------
total images/sec: 204.77
----------------------------------------------------------------

V100:

Click to expand!

TensorFlow: 1.14
Model: resnet50
Dataset: imagenet (synthetic)
Mode: training
SingleSess: False
Batch size: 32 global
 32 per device
Num batches: 100
Num epochs: 0.00
Devices: ['/gpu:0']
NUMA bind: False
Data format: NCHW
Optimizer: sgd
Variables: parameter_server
==========
Generating training model
Initializing graph
Running warm up
Done warm up
Step Img/sec total_loss
1 images/sec: 339.6 +/- 0.0 (jitter = 0.0) 8.169
10 images/sec: 339.9 +/- 0.1 (jitter = 0.4) 7.593
20 images/sec: 340.0 +/- 0.1 (jitter = 0.3) 7.696
30 images/sec: 340.1 +/- 0.1 (jitter = 0.4) 7.753
40 images/sec: 340.1 +/- 0.1 (jitter = 0.4) 8.007
50 images/sec: 340.0 +/- 0.1 (jitter = 0.4) 7.519
60 images/sec: 340.0 +/- 0.1 (jitter = 0.4) 7.988
70 images/sec: 340.0 +/- 0.1 (jitter = 0.5) 8.027
80 images/sec: 340.0 +/- 0.1 (jitter = 0.5) 7.931
90 images/sec: 340.0 +/- 0.1 (jitter = 0.5) 7.849
100 images/sec: 340.0 +/- 0.1 (jitter = 0.5) 7.797
----------------------------------------------------------------
total images/sec: 339.79
----------------------------------------------------------------

-----------------------------------------------------------------------------
export TF_CUDNN_USE_AUTOTUNE=0
-----------------------------------------------------------------------------

TensorFlow: 1.14
Model: resnet50
Dataset: imagenet (synthetic)
Mode: training
SingleSess: False
Batch size: 32 global
 32 per device
Num batches: 100
Num epochs: 0.00
Devices: ['/gpu:0']
NUMA bind: False
Data format: NCHW
Optimizer: sgd
Variables: parameter_server
==========
Generating training model
Initializing graph
Running warm up
Done warm up
Step Img/sec total_loss
1 images/sec: 312.1 +/- 0.0 (jitter = 0.0) 8.169
10 images/sec: 312.1 +/- 0.1 (jitter = 0.2) 7.593
20 images/sec: 312.1 +/- 0.1 (jitter = 0.2) 7.696
30 images/sec: 312.1 +/- 0.1 (jitter = 0.3) 7.753
40 images/sec: 312.2 +/- 0.1 (jitter = 0.3) 8.007
50 images/sec: 312.2 +/- 0.1 (jitter = 0.3) 7.520
60 images/sec: 312.1 +/- 0.1 (jitter = 0.3) 7.989
70 images/sec: 312.1 +/- 0.1 (jitter = 0.4) 8.026
80 images/sec: 312.1 +/- 0.1 (jitter = 0.4) 7.932
90 images/sec: 312.1 +/- 0.0 (jitter = 0.4) 7.849
100 images/sec: 312.1 +/- 0.0 (jitter = 0.4) 7.795
----------------------------------------------------------------
total images/sec: 312.01
----------------------------------------------------------------