optimize germline study rendering (#1519), add logging (#1507), cleanup

bihealth · Nov 4, 2022 · d5c36bf · d5c36bf
1 parent 5de4280
commit d5c36bf
Show file tree

Hide file tree

Showing 6 changed files with 57 additions and 32 deletions.
diff --git a/CHANGELOG.rst b/CHANGELOG.rst
@@ -22,6 +22,8 @@ Changed
     - Move include examples to ``include_examples`` (#1493)
 - **Samplesheets**
     - Upgrade Vue app dependencies (#1518)
+    - Improve study app logging (#1507)
+    - Optimize germline study app ``get_shortcut_column()`` (#1519)
 - **Taskflowbackend**
     - Improve project lock error messages (#1496, #1500, #1511)
 

diff --git a/samplesheets/plugins.py b/samplesheets/plugins.py
@@ -2,6 +2,7 @@
 
 import logging
 import os
+import time
 
 from copy import deepcopy
 from irods.exception import NetworkException
@@ -980,18 +981,26 @@ def get_irods_content(inv, study, irods_backend, ret_data):
     ret_data = deepcopy(ret_data)
     if not (inv.irods_status and irods_backend):
         return ret_data
+    logger.debug('Retrieving iRODS content..')
+    time_start = time.time()
 
-    # Get study plugin for shortcut data
+    # Get study content if plugin is found
     study_plugin = study.get_plugin()
     if study_plugin:
+        logger.debug(
+            'Retrieving study shortcuts for study "{}" (plugin={})..'.format(
+                study.get_display_name(), study_plugin.name
+            )
+        )
         shortcuts = study_plugin.get_shortcut_column(study, ret_data['tables'])
         ret_data['tables']['study']['shortcuts'] = shortcuts
+    else:
+        logger.debug('Study plugin not found')
 
     # Get assay content if corresponding assay plugin exists
     for a_uuid, a_data in ret_data['tables']['assays'].items():
         assay = Assay.objects.filter(sodar_uuid=a_uuid).first()
         assay_path = irods_backend.get_path(assay)
-        assay_plugin = assay.get_plugin()
         a_data['irods_paths'] = []
         # Default shortcuts
         a_data['shortcuts'] = [
@@ -1009,7 +1018,14 @@ def get_irods_content(inv, study, irods_backend, ret_data):
             },
         ]
 
+        assay_plugin = assay.get_plugin()
         if assay_plugin:
+            logger.debug(
+                'Retrieving assay shortcuts for assay "{}" '
+                '(plugin={})..'.format(
+                    assay.get_display_name(), assay_plugin.name
+                )
+            )
             cache_item = cache_backend.get_cache_item(
                 name='irods/rows/{}'.format(a_uuid),
                 app_name=assay_plugin.app_name,
@@ -1034,16 +1050,16 @@ def get_irods_content(inv, study, irods_backend, ret_data):
                 # Update row links
                 assay_plugin.update_row(row, a_data, assay)
 
-            assay_shortcuts = assay_plugin.get_shortcuts(assay) or []
-
             # Add visual notification to all shortcuts coming from assay plugin
+            assay_shortcuts = assay_plugin.get_shortcuts(assay) or []
             for a in assay_shortcuts:
                 a['icon'] = 'mdi:puzzle'
                 a['title'] = 'Defined in assay plugin'
                 a['assay_plugin'] = True
-
             # Add extra table if available
             a_data['shortcuts'].extend(assay_shortcuts)
+        else:
+            logger.debug('Assay plugin not found')
 
         # Check assay shortcut cache and set initial enabled value
         cache_item = cache_backend.get_cache_item(
@@ -1053,10 +1069,10 @@ def get_irods_content(inv, study, irods_backend, ret_data):
         )
 
         # Add track hub shortcuts
+        logger.debug('Setting up track hub shortcuts..')
         track_hubs = (
             cache_item and cache_item.data['shortcuts'].get('track_hubs')
         ) or []
-
         for i, track_hub in enumerate(track_hubs):
             tickets = IrodsAccessTicket.active_objects.filter(
                 path=track_hub
@@ -1084,13 +1100,14 @@ def get_irods_content(inv, study, irods_backend, ret_data):
                     else [],
                 }
             )
-
         for i in range(len(a_data['shortcuts'])):
             if cache_item:
                 a_data['shortcuts'][i]['enabled'] = cache_item.data[
                     'shortcuts'
                 ].get(a_data['shortcuts'][i]['id'])
             else:
                 a_data['shortcuts'][i]['enabled'] = True
-
+    logger.debug(
+        'iRODS content retrieved ({:.1f}s)'.format(time.time() - time_start)
+    )
     return ret_data
diff --git a/samplesheets/rendering.py b/samplesheets/rendering.py
@@ -796,8 +796,8 @@ def build_study_tables(self, study, edit=False, use_config=True, ui=True):
         """
         s_start = time.time()
         logger.debug(
-            'Building study "{}" (pk={}, edit={})..'.format(
-                study.get_name(), study.pk, edit
+            'Building study "{}" (UUID={}, edit={})..'.format(
+                study.get_name(), study.sodar_uuid, edit
             )
         )
 
@@ -860,8 +860,8 @@ def build_study_tables(self, study, edit=False, use_config=True, ui=True):
         for assay in study.assays.all().order_by('pk'):
             a_start = time.time()
             logger.debug(
-                'Building assay "{}" (pk={}, edit={})..'.format(
-                    assay.get_name(), assay.pk, edit
+                'Building assay "{}" (UUID={}, edit={})..'.format(
+                    assay.get_name(), assay.sodar_uuid, edit
                 )
             )
             assay_refs = self.get_assay_refs(all_refs, assay_id, sample_idx)

diff --git a/samplesheets/studyapps/germline/plugins.py b/samplesheets/studyapps/germline/plugins.py
@@ -1,5 +1,7 @@
 """BIH germline config study app plugin for samplesheets"""
 
+import logging
+
 from django.conf import settings
 from django.contrib import auth
 from django.urls import reverse
@@ -11,11 +13,17 @@
 from samplesheets.models import Investigation, Study, GenericMaterial
 from samplesheets.plugins import SampleSheetStudyPluginPoint
 from samplesheets.rendering import SampleSheetTableBuilder
+from samplesheets.studyapps.utils import get_igv_session_url, get_igv_irods_url
 from samplesheets.utils import get_index_by_header
 
-from samplesheets.studyapps.utils import get_igv_session_url, get_igv_irods_url
+from samplesheets.studyapps.germline.utils import (
+    get_pedigree_file_path,
+    get_families,
+    get_family_sources,
+)
 
-from .utils import get_pedigree_file_path, get_families, get_family_sources
+logger = logging.getLogger(__name__)
+User = auth.get_user_model()
 
 
 # SODAR constants
@@ -24,8 +32,6 @@
 # Local constants
 APP_NAME = 'samplesheets.studyapps.germline'
 
-User = auth.get_user_model()
-
 
 class SampleSheetStudyPlugin(SampleSheetStudyPluginPoint):
     """Plugin for germline studies in sample sheets"""
@@ -55,7 +61,6 @@ def get_shortcut_column(self, study, study_tables):
         """
         cache_backend = get_backend_api('sodar_cache')
         cache_item = None
-
         # Get iRODS URLs from cache if it's available
         if cache_backend:
             cache_item = cache_backend.get_cache_item(
@@ -86,34 +91,40 @@ def get_shortcut_column(self, study, study_tables):
         igv_urls = {}
         id_idx = 0  # Default is the source name
         query_key = 'source'  # Default is source
-
+        study_sources = study.get_sources()
         # Group by family
         if family_idx and study_tables['study']['col_values'][family_idx] == 1:
+            logger.debug('Grouping by family')
             id_idx = family_idx
             query_key = 'family'
-
+            source_lookup = {}
+            for source in study_sources:
+                family = None
+                if source.characteristics.get(
+                    'Family'
+                ) and source.characteristics['Family'].get('value'):
+                    family = source.characteristics['Family']['value']
+                if family and family not in source_lookup:
+                    source_lookup[family] = source
             for family in get_families(study):
-                sources = get_family_sources(study, family)
                 igv_urls[family] = get_igv_session_url(
-                    sources.first(), APP_NAME
+                    source_lookup[family], APP_NAME
                 )
-
         # Else group by source
         else:
-            for source in study.get_sources():
+            logger.debug('Grouping by source')
+            for source in study_sources:
                 igv_urls[source.name] = get_igv_session_url(source, APP_NAME)
-
         if not igv_urls:
             return ret  # Nothing else to do
 
+        logger.debug('Set shortcut column data..')
         for row in study_tables['study']['table_data']:
             ped_id = row[id_idx]['value']
             source_id = row[0]['value']
             enabled = True
-
             # Fix potential crash due to pedigree mapping failure (issue #589)
             igv_url = igv_urls[ped_id] if ped_id in igv_urls else None
-
             # Set initial state based on URL and cache
             if not igv_url or (
                 cache_item
@@ -123,7 +134,6 @@ def get_shortcut_column(self, study, study_tables):
                 and not cache_item.data['vcf'][ped_id]
             ):
                 enabled = False
-
             ret['data'].append(
                 {
                     'igv': {
@@ -136,7 +146,6 @@ def get_shortcut_column(self, study, study_tables):
                     },
                 }
             )
-
         return ret
 
     def get_shortcut_links(self, study, study_tables, **kwargs):
@@ -328,7 +337,6 @@ def update_cache(self, name=None, project=None, user=None):
                         study_tables=study_tables,
                     )
                     bam_paths[source.name.strip()] = bam_path
-
                     # Get family ID
                     if (
                         'Family' in source.characteristics
@@ -337,7 +345,6 @@ def update_cache(self, name=None, project=None, user=None):
                         query_id = source.characteristics['Family']['value']
                     else:
                         query_id = source.name.strip()
-
                     # One VCF path for each family (or source if no family)
                     if (
                         query_id != prev_query_id
@@ -349,7 +356,6 @@ def update_cache(self, name=None, project=None, user=None):
                             study_tables=study_tables,
                         )
                         vcf_paths[query_id] = vcf_path
-
                     prev_query_id = query_id
 
                 # Update data

diff --git a/samplesheets/studyapps/germline/utils.py b/samplesheets/studyapps/germline/utils.py
@@ -114,7 +114,6 @@ def get_families(study):
             )
         )
     )
-
     if not ret or not ret[0]:
         ret = (
             GenericMaterial.objects.filter(study=study, item_type='SOURCE')

diff --git a/samplesheets/views_ajax.py b/samplesheets/views_ajax.py
@@ -594,6 +594,7 @@ def get(self, request, *args, **kwargs):
 
         # Get iRODS content if NOT editing and collections have been created
         if not edit:
+            logger.debug('Retrieving iRODS content for study..')
             ret_data = get_irods_content(inv, study, irods_backend, ret_data)
 
         # Get/build sheet config