Perf logging

.gitignore

@@ -6,6 +6,9 @@ __pycache__/
 # C extensions
 *.so
 
+#Mac meta files
+.DS_Store
+
 # Distribution / packaging
 .Python
 env/

views/legger_network_widget.py

@@ -1,5 +1,6 @@
 import datetime
 import logging
+import os
 from collections import OrderedDict
 from qgis.PyQt.QtCore import QMetaObject, QSize, Qt, pyqtSignal, QVariant, QSortFilterProxyModel
 from qgis.PyQt.QtWidgets import (QApplication, QComboBox, QDockWidget, QGroupBox, QHBoxLayout, QLabel, QPlainTextEdit,
@@ -26,6 +27,7 @@
 from legger.views.input_widget import NewWindow
 from legger.views.kijk_legger_popup import KijkProfielPopup
 from sqlalchemy import and_, or_
+import inspect
 
 from .network_graph_widgets import LeggerPlotWidget, LeggerSideViewPlotWidget
 from .network_table_widgets import LeggerTreeWidget, StartpointTreeWidget, VariantenTable
@@ -52,6 +54,27 @@ def _translate(context, text, disambig):
 STRATEGY_DONWSTREAM_ALL = 'benedenstr. altijd'
 STRATEGY_DONWSTREAM_LESS = 'benedenstr. of meer'
 
+performance_log = []
+
+
+def perf_log(linenr, step, obj=None):
+    global performance_log
+    now = datetime.datetime.now()
+    if len(performance_log) > 0:
+        last = performance_log[-1][3]
+        performance_log.append((linenr, step, obj, now, now - last))
+    else:
+        performance_log.append((linenr, step, obj, now, None))
+
+
+def log_performance():
+    global performance_log
+    # write as csv
+    with open(os.path.join(os.path.dirname(__file__), os.pardir, 'performance_log.csv'), 'w') as f:
+        for row in performance_log:
+            f.write(f'{row[0]};{row[1]};{row[2]};{row[3]};{row[4]}\n')
+    performance_log = []
+
 
 class ExtendedCombo(QComboBox):
     def __init__(self, parent=None):
@@ -714,6 +737,8 @@ def data_changed_area_model(self, index, to_index):
         index (QIndex): index of changed field
         """
 
+        self.performance_log = []
+
         if self.area_model.columns[index.column()].get('field') == 'selected':
             # clear display elements
 
@@ -877,6 +902,8 @@ def on_select_edit_hydrovak(self, item):
         return: -
         """
 
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno, 'on_select_edit_hydrovak - start')
+
         hydro_object = self.session.query(HydroObject).filter_by(id=item.hydrovak.get('hydro_id')).first()
         if hydro_object is None:
             self.selected_variant_remark.setPlainText('')
@@ -890,10 +917,20 @@ def on_select_edit_hydrovak(self, item):
         self.selected_hydrovak_db = hydro_object
 
         self.selected_variant_remark.setDisabled(False)
+
         self.kijk_variant_knop.setDisabled(False)
         self.selected_variant_remark.setPlainText(item.hydrovak.get('opmerkingen'))
+
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'on_select_edit_hydrovak - till update_available_variants')
+
         self.update_available_variants()
 
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'on_select_edit_hydrovak - finished update available variants')
+
+        log_performance()
+
     def save_remarks(self):
         if self.selected_hydrovak:
             session = load_spatialite(self.path_legger_db)
@@ -923,6 +960,9 @@ def save_remarks(self):
 
     def update_available_variants(self):
 
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'update_available_variants - start')
+
         item = self.selected_hydrovak
         hydro_object = self.selected_hydrovak_db
 
@@ -933,9 +973,11 @@ def update_available_variants(self):
 
         selected_variant_id = item.hydrovak.get('selected_variant_id')
 
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'update_available_variants - start query variants')
+
         var = self.session.query(Varianten) \
             .join(BegroeiingsVariant) \
-            .outerjoin(ProfielFiguren) \
             .filter(Varianten.hydro == hydro_object) \
             .order_by(Varianten.diepte)
 
@@ -947,14 +989,20 @@ def update_available_variants(self):
         elif self.active_begroeiings_variant == STANDARD:
             var = self.session.query(Varianten) \
                 .join(BegroeiingsVariant) \
-                .outerjoin(ProfielFiguren) \
                 .filter(Varianten.hydro == hydro_object) \
                 .filter(Varianten.standaard_profiel_code != None) \
                 .order_by(Varianten.diepte)
         elif self.active_begroeiings_variant is not None:
             var = var.filter(or_(BegroeiingsVariant.naam == self.active_begroeiings_variant,
                                  Varianten.id == selected_variant_id))
 
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'update_available_variants - finished definition variants')
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 str(var))
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 f"hydro_id = {hydro_object.id}, selected_variant_id = {selected_variant_id}")
+
         from legger import settings
         verhang = 3.0
         color_map = (
@@ -963,7 +1011,14 @@ def update_available_variants(self):
             (4.0, settings.HIGH_COLOR),
         )
         profs = []
-        for profile in var.all():
+
+        # force query
+        profiles = list(var.all())
+
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'update_available_variants - finished fetching variants - start loop')
+
+        for profile in profiles:
             active = selected_variant_id == profile.id
             over_width = None
             over_depth = None
@@ -1007,8 +1062,15 @@ def update_available_variants(self):
                     (0.5 * profile.waterbreedte, hydro_object.streefpeil),
                 ]
             })
+
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'update_available_variants - finished loop - start update model')
+
         self.variant_model.insertRows(profs)
 
+        perf_log(inspect.getframeinfo(inspect.currentframe()).lineno,
+                 'update_available_variants - finished update model')
+
     def update_available_profiles(self, item, variant):
         """
             used for updating ranges after adding a profile manually