Benchmark of HowTo: Reading Data

Question

I'm using tensorflow 0.10 and I was benchmarking the examples found in the official HowTo on reading data. This HowTo illustrates different methods to move data to tensorflow, using the same MNIST example.

I was surprised by the results and I was wondering if anyone has enough low-level understanding to explain what is happening.

In the HowTo there are basically 3 methods to read in data:

• Feeding: building the mini-batch in python and passing it with sess.run(..., feed_dict={x: mini_batch})
• Reading from files: use tf operations to open the files and create mini-batches. (Bypass handling data in python.)
• Preloaded data: load all the data in either a single tf variable or constant and use tf functions to break that up in mini-batches. The variable or constant is pinned to the cpu, not gpu.

The scripts I used to run my benchmarks are found within tensorflow:

• Feeding: examples/tutorials/mnist/fully_connected_feed.py
• Reading from files: examples/how_tos/reading_data/convert_to_records.py and examples/how_tos/reading_data/fully_connected_reader.py
• Preloaded data (constant): examples/how_tos/reading_data/fully_connected_preloaded.py
• Preloaded data (variable): examples/how_tos/reading_data/fully_connected_preloaded_var.py

I ran those scripts unmodified, except for the last two because they crash --for version 0.10 at least-- unless I add an extra sess.run(tf.initialize_local_variables()).

Main Question

The time to execute 100 mini-batches of 100 examples running on a GTX1060:

• Feeding: ~0.001 s
• Reading from files: ~0.010 s
• Preloaded data (constant): ~0.010 s
• Preloaded data (variable): ~0.010 s

Those results are quite surprising to me. I would have expected Feeding to be the slowest since it does almost everything in python, while the other methods use lower-level tensorflow/C++ to carry similar operations. It is the complete opposite of what I expected. Does anyone understand what is going on?

Secondary question

I have access to another machine which has a Titan X and older NVidia drivers. The relative results were roughly in line with the above, except for Preloaded data (constant) which was catastrophically slow, taking many seconds for a single mini-batch.

Is this some known issue that performance can vary greatly with hardware/drivers?

Answer 1

Update Oct 9 the slowness comes because the computation runs too fast for Python to pre-empt the computation thread and to schedule the pre-fetching threads. Computation in main thread takes 2ms and apparently that's too little for the pre-fetching thread to grab the GIL. Pre-fetching thread has larger delay and hence can always be pre-empted by computation thread. So the computation thread runs through all of the examples, and then spends most of the time blocked on GIL as some prefetching thread gets scheduled and enqueues a single example. The solution is to increase number of Python threads, increase queue size to fit the entire dataset, start queue runners, and then pause main thread for a couple of seconds to give queue runners to pre-populate the queue.

Old stuff

That's surprisingly slow.

This looks some kind of special cases making the last 3 examples unnecessarily slow (most effort went into optimizing large models like ImageNet, so MNIST didn't get as much attention).

You can diagnose the problems by getting timelines, as described here

Here are 3 of those examples with timeline collection enabled.

Here's the timeline for feed_dict implementation

The important thing to notice is that matmul takes a good chunk of the time, so the reading overhead is not significant

Now here's the timeline for reader implementation

You can see that operation is bottlenecked on QueueDequeueMany which takes whopping 45ms.

If you zoom in, you'll see a bunch of tiny MEMCPY and Cast operations, which is a sign of some op being CPU only (parse_single_example), and the dequeue having to schedule multiple independent CPU->GPU transfers

For the var example below with GPU disabled, I don't see tiny little ops, but QueueDequeueMany still takes over 10ms. The timing seems to scale linearly with batch size, so there's some fundamental slowness there. Filed #4740