From fc43f4c0d7c4f775c056bc77c56609cc9aabbd61 Mon Sep 17 00:00:00 2001
From: GRiker <griker@hotmail.com>
Date: Wed, 20 Mar 2013 06:07:23 -0700
Subject: [PATCH] Added diagnostic timing information to catalog creation

---
 src/calibre/library/catalogs/epub_mobi.py     | 20 ++++++++++++++-----
 .../library/catalogs/epub_mobi_builder.py     | 10 ++++++++--
 2 files changed, 23 insertions(+), 7 deletions(-)

diff --git a/src/calibre/library/catalogs/epub_mobi.py b/src/calibre/library/catalogs/epub_mobi.py
index 965394a44e..b201136044 100644
--- a/src/calibre/library/catalogs/epub_mobi.py
+++ b/src/calibre/library/catalogs/epub_mobi.py
@@ -7,7 +7,7 @@ __license__ = 'GPL v3'
 __copyright__ = '2012, Kovid Goyal <kovid@kovidgoyal.net>'
 __docformat__ = 'restructuredtext en'
 
-import os
+import datetime, os, time
 from collections import namedtuple
 
 from calibre import strftime
@@ -388,18 +388,24 @@ class EPUB_MOBI(CatalogPlugin):
                 build_log.append("  %s: %s" % (key, repr(opts_dict[key])))
         if opts.verbose:
             log('\n'.join(line for line in build_log))
+
+        # Capture start_time
+        opts.start_time = time.time()
+
         self.opts = opts
 
+        if opts.verbose:
+            log.info(" Begin catalog source generation (%s)" %
+                     str(datetime.timedelta(seconds = int(time.time() - opts.start_time))))
+
         # Launch the Catalog builder
         catalog = CatalogBuilder(db, opts, self, report_progress=notification)
 
-        if opts.verbose:
-            log.info(" Begin catalog source generation")
-
         try:
             catalog.build_sources()
             if opts.verbose:
-                log.info(" Completed catalog source generation\n")
+                log.info(" Completed catalog source generation (%s)\n"  %
+                         str(datetime.timedelta(seconds = int(time.time() - opts.start_time))))
         except (AuthorSortMismatchException, EmptyCatalogException), e:
             log.error(" *** Terminated catalog generation: %s ***" % e)
         except:
@@ -489,5 +495,9 @@ class EPUB_MOBI(CatalogPlugin):
                 os.remove(epub_shell)
                 zip_rebuilder(input_path, os.path.join(catalog_debug_path, 'input.epub'))
 
+            if opts.verbose:
+                log.info(" Catalog creation complete (%s)\n" %
+                     str(datetime.timedelta(seconds = int(time.time() - opts.start_time))))
+
         # returns to gui2.actions.catalog:catalog_generated()
         return catalog.error
diff --git a/src/calibre/library/catalogs/epub_mobi_builder.py b/src/calibre/library/catalogs/epub_mobi_builder.py
index 32175cdbd3..04116cb0e3 100644
--- a/src/calibre/library/catalogs/epub_mobi_builder.py
+++ b/src/calibre/library/catalogs/epub_mobi_builder.py
@@ -3,7 +3,7 @@
 __license__ = 'GPL v3'
 __copyright__ = '2010, Greg Riker'
 
-import datetime, htmlentitydefs, os, platform, re, shutil, unicodedata, zlib
+import datetime, htmlentitydefs, os, platform, re, shutil, time, unicodedata, zlib
 from copy import deepcopy
 from xml.sax.saxutils import escape
 
@@ -4855,7 +4855,13 @@ class CatalogBuilder(object):
             self.progress_int = 0.01
         self.reporter(self.progress_int, self.progress_string)
         if self.opts.cli_environment:
-            self.opts.log(u"%3.0f%% %s" % (self.progress_int * 100, self.progress_string))
+            log_msg = u"%3.0f%% %s" % (self.progress_int * 100, self.progress_string)
+            if self.opts.verbose:
+                log_msg += " (%s)" % str(datetime.timedelta(seconds=int(time.time() - self.opts.start_time)))
+        else:
+            log_msg = ("%s (%s)" % (self.progress_string,
+                str(datetime.timedelta(seconds=int(time.time() - self.opts.start_time)))))
+        self.opts.log(log_msg)
 
     def update_progress_micro_step(self, description, micro_step_pct):
         """ Update calibre's job status UI.