Optimise checking of existing image data.

When checking existing image data go from the end backwards until
a good hash is found rather than from the start forwards until
a bad hash is found.  This is a lot quicker for long files but
may miss a corrupted frame somewhere (however unlikely this is).

4 files changed, 107 insertions, 67 deletions

diff --git a/ChangeLog b/ChangeLog
index d808ddf3e..ee9ebfcb9 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,12 @@
 2015-09-03  c.hetherington  <cth@carlh.net>
 
+	* Quicker, though slightly less safe,
+	check for existing picture data; go back
+	from the last frame written until we
+	find a good one rather than going
+	through from the beginning until we find
+	a bad one (#519, #504).
+
 	* Add frame counter to progress
 	when transcoding (#111).
 
diff --git a/src/lib/writer.cc b/src/lib/writer.cc
index 3bee0e963..ccf47ed34 100644
--- a/src/lib/writer.cc
+++ b/src/lib/writer.cc
@@ -55,6 +55,7 @@
 #include "i18n.h"
 
 #define LOG_GENERAL(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_GENERAL);
+#define LOG_GENERAL_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_GENERAL);
 #define LOG_DEBUG_ENCODE(...) _film->log()->log (String::compose (__VA_ARGS__), Log::TYPE_DEBUG_ENCODE);
 #define LOG_TIMING(...) _film->log()->microsecond_log (String::compose (__VA_ARGS__), Log::TYPE_TIMING);
 #define LOG_WARNING_NC(...) _film->log()->log (__VA_ARGS__, Log::TYPE_WARNING);
@@ -73,6 +74,8 @@ using boost::shared_ptr;
 using boost::weak_ptr;
 using boost::dynamic_pointer_cast;
 
+int const Writer::_info_size = 48;
+
 Writer::Writer (shared_ptr<const Film> film, weak_ptr<Job> j)
 	: _film (film)
 	, _job (j)
@@ -636,77 +639,73 @@ Writer::finish ()
 		);
 }
 
-bool
-Writer::check_existing_picture_asset_frame (FILE* asset, int f, Eyes eyes)
-{
-	/* Read the frame info as written */
-	FILE* file = fopen_boost (_film->info_file (), "rb");
-	if (!file) {
-		LOG_GENERAL ("Existing frame %1 has no info file", f);
-		return false;
-	}
-
-	dcp::FrameInfo info = read_frame_info (file, f, eyes);
-	fclose (file);
-	if (info.size == 0) {
-		LOG_GENERAL ("Existing frame %1 has no info file", f);
-		return false;
-	}
-
-	/* Read the data from the asset and hash it */
-	dcpomatic_fseek (asset, info.offset, SEEK_SET);
-	Data data (info.size);
-	size_t const read = fread (data.data().get(), 1, data.size(), asset);
-	if (read != static_cast<size_t> (data.size ())) {
-		LOG_GENERAL ("Existing frame %1 is incomplete", f);
-		return false;
-	}
-
-	MD5Digester digester;
-	digester.add (data.data().get(), data.size());
-	if (digester.get() != info.hash) {
-		LOG_GENERAL ("Existing frame %1 failed hash check", f);
-		return false;
-	}
-
-	return true;
-}
-
 void
 Writer::check_existing_picture_asset ()
 {
 	/* Try to open the existing asset */
-	FILE* asset = fopen_boost (_picture_asset->file(), "rb");
-	if (!asset) {
+	FILE* asset_file = fopen_boost (_picture_asset->file(), "rb");
+	if (!asset_file) {
 		LOG_GENERAL ("Could not open existing asset at %1 (errno=%2)", _picture_asset->file().string(), errno);
 		return;
 	}
 
-	while (true) {
+	/* Offset of the last dcp::FrameInfo in the info file */
+	int const n = (boost::filesystem::file_size (_film->info_file ()) / _info_size) - 1;
 
-		shared_ptr<Job> job = _job.lock ();
-		DCPOMATIC_ASSERT (job);
+	FILE* info_file = fopen_boost (_film->info_file (), "rb");
+	if (!info_file) {
+		LOG_GENERAL_NC ("Could not open film info file");
+		fclose (asset_file);
+		return;
+	}
+
+	if (_film->three_d ()) {
+		/* Start looking at the last left frame */
+		_first_nonexistant_frame = n / 2;
+	} else {
+		_first_nonexistant_frame = n;
+	}
 
-		job->set_progress_unknown ();
+	bool ok = false;
 
-		if (_film->three_d ()) {
-			if (!check_existing_picture_asset_frame (asset, _first_nonexistant_frame, EYES_LEFT)) {
-				break;
-			}
-			if (!check_existing_picture_asset_frame (asset, _first_nonexistant_frame, EYES_RIGHT)) {
-				break;
-			}
+	while (!ok) {
+		/* Read the data from the info file; for 3D we just check the left
+		   frames until we find a good one.
+		*/
+		dcp::FrameInfo info = read_frame_info (info_file, _first_nonexistant_frame, _film->three_d () ? EYES_LEFT : EYES_BOTH);
+
+		ok = true;
+
+		/* Read the data from the asset and hash it */
+		dcpomatic_fseek (asset_file, info.offset, SEEK_SET);
+		Data data (info.size);
+		size_t const read = fread (data.data().get(), 1, data.size(), asset_file);
+		if (read != static_cast<size_t> (data.size ())) {
+			LOG_GENERAL ("Existing frame %1 is incomplete", _first_nonexistant_frame);
+			ok = false;
 		} else {
-			if (!check_existing_picture_asset_frame (asset, _first_nonexistant_frame, EYES_BOTH)) {
-				break;
+			MD5Digester digester;
+			digester.add (data.data().get(), data.size());
+			if (digester.get() != info.hash) {
+				LOG_GENERAL ("Existing frame %1 failed hash check", _first_nonexistant_frame);
+				ok = false;
 			}
 		}
 
-		LOG_DEBUG_ENCODE ("Have existing frame %1", _first_nonexistant_frame);
+		if (!ok) {
+			--_first_nonexistant_frame;
+		}
+	}
+
+	if (!_film->three_d ()) {
+		/* If we are doing 3D we might have found a good L frame with no R, so only
+		   do this if we're in 2D and we've just found a good B(oth) frame.
+		*/
 		++_first_nonexistant_frame;
 	}
 
-	fclose (asset);
+	fclose (asset_file);
+	fclose (info_file);
 }
 
 /** @param frame Frame index.
@@ -788,15 +787,13 @@ Writer::set_encoder_threads (int threads)
 long
 Writer::frame_info_position (int frame, Eyes eyes) const
 {
-	static int const info_size = 48;
-
 	switch (eyes) {
 	case EYES_BOTH:
-		return frame * info_size;
+		return frame * _info_size;
 	case EYES_LEFT:
-		return frame * info_size * 2;
+		return frame * _info_size * 2;
 	case EYES_RIGHT:
-		return frame * info_size * 2 + info_size;
+		return frame * _info_size * 2 + _info_size;
 	default:
 		DCPOMATIC_ASSERT (false);
 	}
diff --git a/src/lib/writer.h b/src/lib/writer.h
index cec6ba527..120e1f338 100644
--- a/src/lib/writer.h
+++ b/src/lib/writer.h
@@ -116,7 +116,6 @@ private:
 	void thread ();
 	void terminate_thread (bool);
 	void check_existing_picture_asset ();
-	bool check_existing_picture_asset_frame (FILE *, int, Eyes);
 	bool have_sequenced_image_at_queue_head ();
 	void write_frame_info (int frame, Eyes eyes, dcp::FrameInfo info) const;
 	long frame_info_position (int frame, Eyes eyes) const;
@@ -169,4 +168,6 @@ private:
 	boost::shared_ptr<dcp::SubtitleAsset> _subtitle_asset;
 
 	std::list<boost::shared_ptr<Font> > _fonts;
+
+	static int const _info_size;
 };
diff --git a/test/recover_test.cc b/test/recover_test.cc
index a70357e94..45791ae0d 100644
--- a/test/recover_test.cc
+++ b/test/recover_test.cc
@@ -21,13 +21,15 @@
  *  @brief Test recovery of a DCP transcode after a crash.
  */
 
-#include <boost/test/unit_test.hpp>
-#include <dcp/stereo_picture_asset.h>
+#include "test.h"
 #include "lib/film.h"
 #include "lib/dcp_content_type.h"
 #include "lib/image_content.h"
+#include "lib/ffmpeg_content.h"
 #include "lib/ratio.h"
-#include "test.h"
+#include <dcp/mono_picture_asset.h>
+#include <dcp/stereo_picture_asset.h>
+#include <boost/test/unit_test.hpp>
 
 using std::cout;
 using std::string;
@@ -41,9 +43,42 @@ note (dcp::NoteType t, string n)
 	}
 }
 
-BOOST_AUTO_TEST_CASE (recover_test)
+BOOST_AUTO_TEST_CASE (recover_test_2d)
+{
+	shared_ptr<Film> film = new_test_film ("recover_test_2d");
+	film->set_dcp_content_type (DCPContentType::from_isdcf_name ("FTR"));
+	film->set_container (Ratio::from_id ("185"));
+	film->set_name ("recover_test");
+
+	shared_ptr<FFmpegContent> content (new FFmpegContent (film, "test/data/count300bd24.m2ts"));
+	film->examine_and_add_content (content);
+	wait_for_jobs ();
+
+	film->make_dcp ();
+	wait_for_jobs ();
+
+	boost::filesystem::path const video = "build/test/recover_test_2d/video/185_2K_d2b23c22cff43b0247c7108dcd32323c_24_100000000_P_S.mxf";
+
+	boost::filesystem::copy_file (
+		video,
+		"build/test/recover_test_2d/original.mxf"
+		);
+
+	boost::filesystem::resize_file (video, 2 * 1024 * 1024);
+
+	film->make_dcp ();
+	wait_for_jobs ();
+
+	shared_ptr<dcp::MonoPictureAsset> A (new dcp::MonoPictureAsset ("build/test/recover_test_2d/original.mxf"));
+	shared_ptr<dcp::MonoPictureAsset> B (new dcp::MonoPictureAsset (video));
+
+	dcp::EqualityOptions eq;
+	BOOST_CHECK (A->equals (B, eq, boost::bind (&note, _1, _2)));
+}
+
+BOOST_AUTO_TEST_CASE (recover_test_3d)
 {
-	shared_ptr<Film> film = new_test_film ("recover_test");
+	shared_ptr<Film> film = new_test_film ("recover_test_3d");
 	film->set_dcp_content_type (DCPContentType::from_isdcf_name ("FTR"));
 	film->set_container (Ratio::from_id ("185"));
 	film->set_name ("recover_test");
@@ -57,11 +92,11 @@ BOOST_AUTO_TEST_CASE (recover_test)
 	film->make_dcp ();
 	wait_for_jobs ();
 
-	boost::filesystem::path const video = "build/test/recover_test/video/185_2K_961f053444e90c5ddbf978eb0ebfa772_24_100000000_P_S_3D.mxf";
+	boost::filesystem::path const video = "build/test/recover_test_3d/video/185_2K_961f053444e90c5ddbf978eb0ebfa772_24_100000000_P_S_3D.mxf";
 
 	boost::filesystem::copy_file (
 		video,
-		"build/test/recover_test/original.mxf"
+		"build/test/recover_test_3d/original.mxf"
 		);
 
 	boost::filesystem::resize_file (video, 2 * 1024 * 1024);
@@ -69,7 +104,7 @@ BOOST_AUTO_TEST_CASE (recover_test)
 	film->make_dcp ();
 	wait_for_jobs ();
 
-	shared_ptr<dcp::StereoPictureAsset> A (new dcp::StereoPictureAsset ("build/test/recover_test/original.mxf"));
+	shared_ptr<dcp::StereoPictureAsset> A (new dcp::StereoPictureAsset ("build/test/recover_test_3d/original.mxf"));
 	shared_ptr<dcp::StereoPictureAsset> B (new dcp::StereoPictureAsset (video));
 
 	dcp::EqualityOptions eq;