Better timing reporting for viewer in debug mode

src/calibre/gui2/viewer/__init__.py

@@ -3,6 +3,12 @@
 # License: GPL v3 Copyright: 2018, Kovid Goyal <kovid at kovidgoyal.net>
 
 
+import sys
+from time import monotonic
+
+from calibre.constants import DEBUG
+
+
 def get_current_book_data(set_val=False):
     if set_val is not False:
         setattr(get_current_book_data, 'ans', set_val)
@@ -27,3 +33,21 @@ def link_prefix_for_location_links(add_open_at=True):
         if add_open_at:
             link_prefix += '?open_at='
     return link_prefix
+
+
+class PerformanceMonitor:
+
+    def __init__(self):
+        self.start_time = monotonic()
+
+    def __call__(self, desc='', reset=False):
+        if DEBUG:
+            at = monotonic()
+            if reset:
+                self.start_time = at
+            if desc:
+                ts = at - self.start_time
+                print(f'[{ts:.3f}] {desc}', file=sys.stderr)
+
+
+performance_monitor = PerformanceMonitor()

src/calibre/gui2/viewer/ui.py

@@ -17,14 +17,13 @@ from qt.core import (
 from threading import Thread
 
 from calibre import prints
-from calibre.constants import DEBUG
 from calibre.customize.ui import available_input_formats
 from calibre.db.annotations import merge_annotations
 from calibre.gui2 import choose_files, error_dialog
 from calibre.gui2.dialogs.drm_error import DRMErrorMessage
 from calibre.gui2.image_popup import ImagePopup
 from calibre.gui2.main_window import MainWindow
-from calibre.gui2.viewer import get_current_book_data
+from calibre.gui2.viewer import get_current_book_data, performance_monitor
 from calibre.gui2.viewer.annotations import (
     AnnotationsSaveWorker, annotations_dir, parse_annotations
 )
@@ -44,7 +43,6 @@ from calibre.gui2.viewer.web_view import WebView, get_path_for_name, set_book_pa
 from calibre.utils.date import utcnow
 from calibre.utils.img import image_from_path
 from calibre.utils.ipc.simple_worker import WorkerError
-from calibre.utils.monotonic import monotonic
 from polyglot.builtins import as_bytes, as_unicode, iteritems, itervalues
 
 
@@ -411,6 +409,7 @@ class EbookViewer(MainWindow):
         if msg:
             self.loading_overlay(msg)
         else:
+            performance_monitor('loading finished')
             self.loading_overlay.hide()
 
     def show_error(self, title, msg, details):
@@ -456,6 +455,7 @@ class EbookViewer(MainWindow):
             self.load_ebook(entry['pathtoebook'])
 
     def load_ebook(self, pathtoebook, open_at=None, reload_book=False):
+        performance_monitor('Load of book started', reset=True)
         self.web_view.show_home_page_on_ready = False
         if open_at:
             self.pending_open_at = open_at
@@ -474,8 +474,6 @@ class EbookViewer(MainWindow):
             self.load_ebook(self.current_book_data['pathtoebook'], reload_book=True)
 
     def _load_ebook_worker(self, pathtoebook, open_at, reload_book):
-        if DEBUG:
-            start_time = monotonic()
         try:
             ans = prepare_book(pathtoebook, force=reload_book, prepare_notify=self.prepare_notify)
         except WorkerError as e:
@@ -484,8 +482,7 @@ class EbookViewer(MainWindow):
             import traceback
             self.book_prepared.emit(False, {'exception': e, 'tb': traceback.format_exc(), 'pathtoebook': pathtoebook})
         else:
-            if DEBUG:
-                print('Book prepared in {:.2f} seconds'.format(monotonic() - start_time))
+            performance_monitor('prepared emitted')
             self.book_prepared.emit(True, {'base': ans, 'pathtoebook': pathtoebook, 'open_at': open_at, 'reloaded': reload_book})
 
     def prepare_notify(self):
@@ -546,6 +543,7 @@ class EbookViewer(MainWindow):
         highlights = self.current_book_data['annotations_map']['highlight']
         self.highlights_widget.load(highlights)
         self.web_view.start_book_load(initial_position=initial_position, highlights=highlights, current_book_data=self.current_book_data)
+        performance_monitor('webview loading requested')
 
     def load_book_data(self, calibre_book_data=None):
         self.current_book_data['book_library_details'] = get_book_library_details(self.current_book_data['pathtoebook'])

src/calibre/gui2/viewer/web_view.py

@@ -28,7 +28,7 @@ from calibre.constants import (
 from calibre.ebooks.metadata.book.base import field_metadata
 from calibre.ebooks.oeb.polish.utils import guess_type
 from calibre.gui2 import choose_images, error_dialog, safe_open_url
-from calibre.gui2.viewer import link_prefix_for_location_links
+from calibre.gui2.viewer import link_prefix_for_location_links, performance_monitor
 from calibre.gui2.viewer.config import viewer_config_dir, vprefs
 from calibre.gui2.viewer.tts import TTS
 from calibre.gui2.webengine import (
@@ -618,6 +618,7 @@ class WebView(RestartingWebEngineView):
         }
         self.bridge.create_view(
             vprefs['session_data'], vprefs['local_storage'], field_metadata.all_metadata(), ui_data)
+        performance_monitor('bridge ready')
         for func, args in iteritems(self.pending_bridge_ready_actions):
             getattr(self.bridge, func)(*args)