TMSS-404: add django-debug-toolbar and tweak performance of task and scheduling unit models

Docker/lofar-ci/Dockerfile_ci_sas

@@ -16,7 +16,7 @@ RUN yum erase -y postgresql postgresql-server postgresql-devel && \
     cd /bin && ln -s /usr/pgsql-9.6/bin/initdb && ln -s /usr/pgsql-9.6/bin/postgres
 ENV PATH /usr/pgsql-9.6/bin:$PATH 
 
-RUN pip3 install cython kombu lxml requests pygcn xmljson mysql-connector-python python-dateutil Django==3.0.9 djangorestframework==3.11.1 djangorestframework-xml ldap==1.0.2 flask fabric coverage python-qpid-proton PyGreSQL numpy h5py psycopg2 testing.postgresql Flask-Testing scipy Markdown django-filter python-ldap python-ldap-test ldap3 django-jsonforms django-json-widget django-jsoneditor drf-yasg flex swagger-spec-validator django-auth-ldap mozilla-django-oidc jsonschema comet pyxb==1.2.5 graphviz isodate astropy packaging
+RUN pip3 install cython kombu lxml requests pygcn xmljson mysql-connector-python python-dateutil Django==3.0.9 djangorestframework==3.11.1 djangorestframework-xml ldap==1.0.2 flask fabric coverage python-qpid-proton PyGreSQL numpy h5py psycopg2 testing.postgresql Flask-Testing scipy Markdown django-filter python-ldap python-ldap-test ldap3 django-jsonforms django-json-widget django-jsoneditor drf-yasg flex swagger-spec-validator django-auth-ldap mozilla-django-oidc jsonschema comet pyxb==1.2.5 graphviz isodate astropy packaging django-debug-toolbar 
 
 #Viewflow package 
 RUN pip3 install django-material django-viewflow

SAS/TMSS/src/tmss/settings.py

@@ -121,8 +121,16 @@ INSTALLED_APPS = [
     'viewflow',
     'viewflow.frontend',
     'lofar.sas.tmss.tmss.workflowapp',
+    'debug_toolbar',
 ]
 
+def show_debug_toolbar(*args, **kwargs):
+    return os.environ.get('SHOW_DJANGO_DEBUG_TOOLBAR', False)
+
+DEBUG_TOOLBAR_CONFIG = {
+    'SHOW_TOOLBAR_CALLBACK': show_debug_toolbar
+}
+
 MIDDLEWARE = [
     'django.middleware.gzip.GZipMiddleware',
     'django.middleware.security.SecurityMiddleware',
@@ -134,6 +142,7 @@ MIDDLEWARE = [
     'django.middleware.clickjacking.XFrameOptionsMiddleware'
 ]
 
+
 ROOT_URLCONF = 'lofar.sas.tmss.tmss.urls'
 
 TEMPLATES = [

SAS/TMSS/src/tmss/tmssapp/models/scheduling.py

@@ -149,7 +149,7 @@ class Subtask(BasicCommon):
         super().__init__(*args, **kwargs)
 
         # keep original state for logging
-        self.__original_state = self.state
+        self.__original_state_id = self.state_id
 
     @staticmethod
     def _send_state_change_event_message(subtask_id:int, old_state: str, new_state: str):
@@ -189,7 +189,7 @@ class Subtask(BasicCommon):
 
         annotate_validate_add_defaults_to_doc_using_template(self, 'specifications_doc', 'specifications_template')
 
-        if self.state.value == SubtaskState.Choices.SCHEDULED.value and self.__original_state.value == SubtaskState.Choices.SCHEDULING.value:
+        if self.state.value == SubtaskState.Choices.SCHEDULED.value and self.__original_state_id == SubtaskState.Choices.SCHEDULING.value:
             if self.start_time is None:
                 if self.predecessors.all().count() == 0:
                     raise SubtaskSchedulingException("Cannot schedule subtask id=%s when start time is 'None'." % (self.pk, ))
@@ -202,12 +202,12 @@ class Subtask(BasicCommon):
         super().save(force_insert, force_update, using, update_fields)
 
         # log if either state update or new entry:
-        if self.state != self.__original_state or creating == True:
+        if self.state_id != self.__original_state_id or creating == True:
             if self.created_or_updated_by_user is None:
                 identifier = None
             else:
                 identifier = self.created_or_updated_by_user.email
-            log_entry = SubtaskStateLog(subtask=self, old_state=self.__original_state, new_state=self.state,
+            log_entry = SubtaskStateLog(subtask=self, old_state=SubtaskState.objects.get(value=self.__original_state_id), new_state=self.state,
                                            user=self.created_or_updated_by_user, user_identifier=identifier)
             log_entry.save()
 
@@ -217,7 +217,7 @@ class Subtask(BasicCommon):
                 logger.error("Could not send state change to messagebus: %s", e)
 
             # update the previous state value
-            self.__original_state = self.state
+            self.__original_state_id = self.state_id
 
 class SubtaskStateLog(BasicCommon):
     """

SAS/TMSS/src/tmss/tmssapp/models/specification.py

@@ -19,7 +19,7 @@ import json
 import jsonschema
 from django.urls import reverse as revese_url
 from collections import Counter
-
+from django.utils.functional import cached_property
 
 #
 # Common
@@ -412,7 +412,7 @@ class Cycle(NamedCommonPK):
     start = DateTimeField(help_text='Moment at which the cycle starts, that is, when its projects can run.')
     stop = DateTimeField(help_text='Moment at which the cycle officially ends.')
 
-    @property
+    @cached_property
     def duration(self) -> datetime.timedelta:
         '''the duration of the cycle (stop-start date)'''
         return self.stop - self.start
@@ -559,13 +559,13 @@ class SchedulingUnitDraft(NamedCommon):
         annotate_validate_add_defaults_to_doc_using_template(self, 'scheduling_constraints_doc', 'scheduling_constraints_template')
         super().save(force_insert, force_update, using, update_fields)
 
-    @property
+    @cached_property
     def duration(self) -> datetime.timedelta:
         '''return the overall duration of all tasks of this scheduling unit
         '''
         return self.relative_stop_time - self.relative_start_time
 
-    @property
+    @cached_property
     def relative_start_time(self) -> datetime.timedelta:
         '''return the earliest relative start time of all tasks of this scheduling unit
         '''
@@ -575,7 +575,7 @@ class SchedulingUnitDraft(NamedCommon):
         else:
             return datetime.timedelta(seconds=0)
 
-    @property
+    @cached_property
     def relative_stop_time(self) -> datetime.timedelta:
         '''return the latest relative stop time of all tasks of this scheduling unit
         '''
@@ -597,7 +597,7 @@ class SchedulingUnitBlueprint(NamedCommon):
 
         super().save(force_insert, force_update, using, update_fields)
 
-    @property
+    @cached_property
     def duration(self) -> datetime.timedelta:
         '''return the overall duration of all tasks of this scheduling unit
         '''
@@ -606,7 +606,7 @@ class SchedulingUnitBlueprint(NamedCommon):
         else:
             return self.stop_time - self.start_time   # <- todo: do we ever want this?
 
-    @property
+    @cached_property
     def relative_start_time(self) -> datetime.timedelta:
         '''return the earliest relative start time of all tasks of this scheduling unit
         '''
@@ -616,7 +616,7 @@ class SchedulingUnitBlueprint(NamedCommon):
         else:
             return datetime.timedelta(seconds=0)
 
-    @property
+    @cached_property
     def relative_stop_time(self) -> datetime.timedelta:
         '''return the latest relative stop time of all tasks of this scheduling unit
         '''
@@ -626,7 +626,7 @@ class SchedulingUnitBlueprint(NamedCommon):
         else:
             return datetime.timedelta(seconds=0)
 
-    @property
+    @cached_property
     def start_time(self) -> datetime or None:
         '''return the earliest start time of all tasks of this scheduling unit
         '''
@@ -636,7 +636,7 @@ class SchedulingUnitBlueprint(NamedCommon):
         else:
             return None
 
-    @property
+    @cached_property
     def stop_time(self) -> datetime or None:
         '''return the latest stop time of all tasks of this scheduling unit
         '''
@@ -646,7 +646,7 @@ class SchedulingUnitBlueprint(NamedCommon):
         else:
             return None
 
-    @property
+    @cached_property
     def status(self):
         """
         Return the schedulingunit blueprint status which is derived from the taskblueprint status (which is derived
@@ -758,7 +758,7 @@ class TaskDraft(NamedCommon):
         annotate_validate_add_defaults_to_doc_using_template(self, 'specifications_doc', 'specifications_template')
         super().save(force_insert, force_update, using, update_fields)
 
-    @property
+    @cached_property
     def successors(self) -> QuerySet:
         '''return the connect successor taskdraft(s) as queryset (over which you can perform extended queries, or return via the serializers/viewsets)
            If you want the result, add .all() like so: my_taskdraft.successors.all()
@@ -768,7 +768,7 @@ class TaskDraft(NamedCommon):
                                                       "INNER JOIN tmssapp_taskrelationdraft as task_rel on task_rel.consumer_id = successor_task.id\n"
                                                       "WHERE task_rel.producer_id = %s", params=[self.id]))
 
-    @property
+    @cached_property
     def predecessors(self) -> QuerySet:
         '''return the connect predecessor taskdraft(s) as queryset (over which you can perform extended queries, or return via the serializers/viewsets)
         If you want the result, add .all() like so: my_taskdraft.predecessors.all()
@@ -778,26 +778,26 @@ class TaskDraft(NamedCommon):
                                                       "INNER JOIN tmssapp_taskrelationdraft as task_rel on task_rel.producer_id = successor_task.id\n"
                                                       "WHERE task_rel.consumer_id = %s", params=[self.id]))
 
-    @property
+    @cached_property
     def duration(self) -> datetime.timedelta:
          '''returns the overall duration of this task
          '''
          return self.relative_stop_time - self.relative_start_time
 
-    @property
+    @cached_property
     def relative_start_time(self) -> datetime.timedelta:
         '''return the earliest relative start time of all subtasks of this task
         '''
         scheduling_relations = list(self.first_to_connect.all()) + list(self.second_to_connect.all())
         for scheduling_relation in scheduling_relations:
-            if scheduling_relation.first.id == self.id and scheduling_relation.placement.value == "after":
+            if scheduling_relation.first.id == self._id and scheduling_relation.placement_id == "after":
                 previous_related_task_draft = TaskDraft.objects.get(id=scheduling_relation.second.id)
                 time_offset = scheduling_relation.time_offset
                 # todo: max of several relations
                 if previous_related_task_draft.relative_stop_time:
                     return previous_related_task_draft.relative_stop_time + datetime.timedelta(seconds=time_offset)
 
-            if scheduling_relation.second.id == self.id and scheduling_relation.placement.value == "before":
+            if scheduling_relation.second.id == self._id and scheduling_relation.placement_id == "before":
                 previous_related_task_draft = TaskDraft.objects.get(id=scheduling_relation.first.id)
                 time_offset = scheduling_relation.time_offset
                 # todo: max of several relations
@@ -805,7 +805,7 @@ class TaskDraft(NamedCommon):
                     return previous_related_task_draft.relative_stop_time + datetime.timedelta(seconds=time_offset)
         return datetime.timedelta(seconds=0)
 
-    @property
+    @cached_property
     def relative_stop_time(self) -> datetime.timedelta:
         '''return the latest relative stop time of all subtasks of this task
         '''
@@ -825,7 +825,7 @@ class TaskDraft(NamedCommon):
     #  Only on the blueprints, we also aggregate start_stop times as they are in the system
     #  I'll leave these code bits here for now, until we made up our minds about this, but this can probably be removed
     #
-    # @property
+    # @cached_property
     # def duration(self) -> datetime.timedelta:
     #     '''returns the overall duration in seconds of all blueprints of this task
     #     # todo: is this the wanted behavior? Do you want to consider all the blueprints created from your draft or do you want to preview a new blueprint?
@@ -836,7 +836,7 @@ class TaskDraft(NamedCommon):
     #     else:
     #         return self.stop_time - self.start_time
     #
-    # @property
+    # @cached_property
     # def start_time(self) -> datetime or None:
     #     '''return the earliest start time of all blueprints of this task
     #     # todo: is this the wanted behavior? Do you want to consider all the blueprints created from your draft or do you want to preview a new blueprint?
@@ -848,7 +848,7 @@ class TaskDraft(NamedCommon):
     #         # todo: calculate?
     #         return None
     #
-    # @property
+    # @cached_property
     # def stop_time(self) -> datetime or None:
     #     '''return the latest stop time of all blueprints of this task
     #     # todo: is this the wanted behavior? Do you want to consider all the blueprints created from your draft or do you want to preview a new blueprint?
@@ -872,7 +872,7 @@ class TaskBlueprint(NamedCommon):
         annotate_validate_add_defaults_to_doc_using_template(self, 'specifications_doc', 'specifications_template')
         super().save(force_insert, force_update, using, update_fields)
 
-    @property
+    @cached_property
     def successors(self) -> QuerySet:
         '''return the connect successor taskblueprint(s) as queryset (over which you can perform extended queries, or return via the serializers/viewsets)
            If you want the result, add .all() like so: my_taskblueprint.successors.all()
@@ -882,7 +882,7 @@ class TaskBlueprint(NamedCommon):
                                                           "INNER JOIN tmssapp_taskrelationblueprint as task_rel on task_rel.consumer_id = successor_task.id\n"
                                                           "WHERE task_rel.producer_id = %s", params=[self.id]))
 
-    @property
+    @cached_property
     def predecessors(self) -> QuerySet:
         '''return the connect predecessor taskblueprint(s) as queryset (over which you can perform extended queries, or return via the serializers/viewsets)
         If you want the result, add .all() like so: my_taskblueprint.predecessors.all()
@@ -892,7 +892,7 @@ class TaskBlueprint(NamedCommon):
                                                           "INNER JOIN tmssapp_taskrelationblueprint as task_rel on task_rel.producer_id = predecessor_task.id\n"
                                                           "WHERE task_rel.consumer_id = %s", params=[self.id]))
 
-    @property
+    @cached_property
     def duration(self) -> datetime.timedelta:
         '''return the overall duration of this task
         '''
@@ -901,20 +901,20 @@ class TaskBlueprint(NamedCommon):
         else:
             return self.stop_time - self.start_time
 
-    @property
+    @cached_property
     def relative_start_time(self) -> datetime.timedelta:
         '''return the earliest relative start time of all subtasks of this task
         '''
         scheduling_relations = list(self.first_to_connect.all()) + list(self.second_to_connect.all())
         for scheduling_relation in scheduling_relations:
-                if scheduling_relation.first.id == self.id and scheduling_relation.placement.value == "after":
+            if scheduling_relation.first.id == self._id and scheduling_relation.placement_id == "after":   # self.id and placement.value will hit the db, this does not
                     previous_related_task_blueprint = TaskBlueprint.objects.get(id=scheduling_relation.second.id)
                     time_offset = scheduling_relation.time_offset
                     # todo: max of several relations
                     if previous_related_task_blueprint.relative_stop_time:
                         return previous_related_task_blueprint.relative_stop_time + datetime.timedelta(seconds=time_offset)
 
-                if scheduling_relation.second.id == self.id and scheduling_relation.placement.value == "before":
+            if scheduling_relation.second.id == self._id and scheduling_relation.placement_id == "before":   # self.id and placement.value will hit the db, this does not
                     previous_related_task_blueprint = TaskBlueprint.objects.get(id=scheduling_relation.first.id)
                     time_offset = scheduling_relation.time_offset
                     # todo: max of several relations
@@ -922,7 +922,7 @@ class TaskBlueprint(NamedCommon):
                         return previous_related_task_blueprint.relative_stop_time + datetime.timedelta(seconds=time_offset)
         return datetime.timedelta(seconds=666660)
 
-    @property
+    @cached_property
     def relative_stop_time(self) -> datetime.timedelta:
         '''return the latest relative stop time of all subtasks of this task
         '''
@@ -934,7 +934,7 @@ class TaskBlueprint(NamedCommon):
             pass
         return self.relative_start_time
 
-    @property
+    @cached_property
     def start_time(self) -> datetime or None:
         '''return the earliest start time of all subtasks of this task
         '''
@@ -944,7 +944,7 @@ class TaskBlueprint(NamedCommon):
         else:
             return None
 
-    @property
+    @cached_property
     def stop_time(self) -> datetime or None:
         '''return the latest stop time of all subtasks of this task
         '''
@@ -954,7 +954,7 @@ class TaskBlueprint(NamedCommon):
         else:
             return None
 
-    @property
+    @cached_property
     def status(self):
         """
         Return the taskblueprint status which is derived from the subtasks status

SAS/TMSS/src/tmss/tmssapp/viewsets/scheduling.py

@@ -144,6 +144,8 @@ class SubtaskViewSet(LOFARViewSet):
     filter_class = SubTaskFilter
     ordering = ('start_time',)
 
+    queryset = queryset.prefetch_related('state')
+
     @swagger_auto_schema(auto_schema=TextPlainAutoSchema,
                          responses={200: 'A LOFAR parset for this subtask (as plain text)',
                                     403: 'forbidden',

SAS/TMSS/src/tmss/tmssapp/viewsets/specification.py

@@ -307,6 +307,16 @@ class SchedulingUnitDraftViewSet(LOFARViewSet):
     queryset = models.SchedulingUnitDraft.objects.all()
     serializer_class = serializers.SchedulingUnitDraftSerializer
 
+    # prefetch all reverse related references from other models on their related_name to avoid a ton of duplicate queries
+    queryset = queryset.prefetch_related('copied_from') \
+                       .prefetch_related('scheduling_unit_blueprints')\
+                       .prefetch_related('task_drafts')
+
+    # preselect all references to other models to avoid even more duplicate queries
+    queryset = queryset.select_related('copies') \
+                       .select_related('copy_reason') \
+                       .select_related('scheduling_set')
+
     @swagger_auto_schema(responses={201: 'The Created SchedulingUnitBlueprint, see Location in Response header',
                                     403: 'forbidden'},
                          operation_description="Carve SchedulingUnitDraft in stone, and make an (uneditable) blueprint out of it.")
@@ -580,6 +590,9 @@ class SchedulingUnitBlueprintViewSet(LOFARViewSet):
     queryset = models.SchedulingUnitBlueprint.objects.all()
     serializer_class = serializers.SchedulingUnitBlueprintSerializer
 
+    # prefetch all reverse related references from other models on their related_name to avoid a ton of duplicate queries
+    queryset = queryset.prefetch_related('task_blueprints')
+
     @swagger_auto_schema(responses={201: "This SchedulingUnitBlueprint, with references to its created TaskBlueprints and (scheduled) Subtasks.",
                                     403: 'forbidden'},
                          operation_description="Create TaskBlueprint(s) for this scheduling unit, create subtasks, and schedule the ones that are not dependend on predecessors.")
@@ -633,6 +646,22 @@ class TaskDraftViewSet(LOFARViewSet):
     queryset = models.TaskDraft.objects.all()
     serializer_class = serializers.TaskDraftSerializer
 
+    # prefetch all reverse related references from other models on their related_name to avoid a ton of duplicate queries
+    queryset = queryset.prefetch_related('first_to_connect') \
+                       .prefetch_related('second_to_connect')\
+                       .prefetch_related('produced_by')\
+                       .prefetch_related('consumed_by')\
+                       .prefetch_related('task_blueprints')\
+                       .prefetch_related('copied_from')
+
+    # prefetch nested references in reverse models to avoid duplicate lookup queries
+    queryset = queryset.prefetch_related('first_to_connect__placement') \
+                       .prefetch_related('second_to_connect__placement')
+
+    # select all references to other models to avoid even more duplicate queries
+    queryset = queryset.select_related('copies') \
+                       .select_related('copy_reason')
+
     @swagger_auto_schema(responses={201: 'The created task blueprint, see Location in Response header',
                                     403: 'forbidden'},
                          operation_description="Carve this draft task specification in stone, and make an (uneditable) blueprint out of it.")
@@ -726,6 +755,17 @@ class TaskBlueprintViewSet(LOFARViewSet):
     queryset = models.TaskBlueprint.objects.all()
     serializer_class = serializers.TaskBlueprintSerializer
 
+    # prefetch all reverse related references from other models on their related_name to avoid a ton of duplicate queries
+    queryset = queryset.prefetch_related('first_to_connect')\
+                       .prefetch_related('second_to_connect')\
+                       .prefetch_related('produced_by')\
+                       .prefetch_related('consumed_by')\
+                       .prefetch_related('subtasks')
+
+    # prefetch nested references in reverse models to avoid duplicate lookup queries
+    queryset = queryset.prefetch_related('first_to_connect__placement') \
+                       .prefetch_related('second_to_connect__placement')
+
     @swagger_auto_schema(responses={201: "This TaskBlueprint, with it is created subtasks",
                                     403: 'forbidden'},
                          operation_description="Create subtasks.")

SAS/TMSS/src/tmss/urls.py

@@ -33,6 +33,8 @@ from datetime import datetime
 from material.frontend import urls as frontend_urls
 from viewflow.flow.viewset import FlowViewSet
 
+import debug_toolbar
+
 #
 # Django style patterns
 #
@@ -63,7 +65,8 @@ urlpatterns = [
     path('schemas/<str:template>/<str:name>/<str:version>', views.get_template_json_schema, name='get_template_json_schema'), #TODO: how to make trailing slash optional?
     path('schemas/<str:template>/<str:name>/<str:version>/', views.get_template_json_schema, name='get_template_json_schema'),
     path(r'util/utc', views.utc, name="system-utc"),
-    path(r'util/lst', views.lst, name="conversion-lst")
+    path(r'util/lst', views.lst, name="conversion-lst"),
+    path('__debug__/', include(debug_toolbar.urls)),
 ]