SW-41: measure and log several sql procedures to see where the time is spend.

SAS/ResourceAssignment/ResourceAssignmentDatabase/radb.py

@@ -68,6 +68,7 @@ class RADatabase:
                                      port=self.dbcreds.port,
                                      connect_timeout=5)
         self.cursor = self.conn.cursor(cursor_factory = psycopg2.extras.RealDictCursor)
+        self.conn.notices = collections.deque()
 
     def _queryAsSingleLine(self, query, qargs=None):
         line = ' '.join(query.replace('\n', ' ').split())
@@ -124,7 +125,19 @@ class RADatabase:
         if self.conn.notices:
             for notice in self.conn.notices:
                 logger.info('database log message %s', notice.strip())
-            del self.conn.notices[:]
+
+            took_msgs = [m for m in self.conn.notices if ' took ' in m]
+            agg_msgs = {}
+            for m in took_msgs:
+                parts = [p.strip() for p in m.split()]
+                if parts[1] not in agg_msgs:
+                    agg_msgs[parts[1]] = []
+                agg_msgs[parts[1]].append(totalSeconds(datetime.strptime(parts[3], "%H:%M:%S.%f")-datetime(1900,1,1)))
+
+            for key in sorted(agg_msgs.keys()):
+                logger.info("%s took total %s", key, sum(agg_msgs[key]))
+
+            self.conn.notices.clear()
 
     def commit(self):
         logger.info('commit')

SAS/ResourceAssignment/ResourceAssignmentDatabase/radb/sql/add_functions_and_triggers.sql

@@ -242,11 +242,19 @@ DECLARE
     usage_at_or_before_start resource_allocation.resource_usage;
     usage_at_or_before_end resource_allocation.resource_usage;
     intermediate_usage resource_allocation.resource_usage;
+    proc_start timestamp with time zone;
+    proc_end timestamp with time zone;
+    part_start timestamp with time zone;
+    part_end timestamp with time zone;
 BEGIN
+    SELECT * from clock_timestamp() into proc_start;
+
     -- find resource_usage at claim starttime
     SELECT * FROM resource_allocation.get_resource_usage_at_or_before(new_claim.resource_id, new_claim.status_id, new_claim.starttime, false, false, false) into usage_at_or_before_start;
     SELECT * FROM resource_allocation.get_resource_usage_at_or_before(new_claim.resource_id, new_claim.status_id, new_claim.endtime, false, false, false) into usage_at_or_before_end;
 
+    SELECT * from clock_timestamp() into part_start;
+
     --add new_claim.claim_size at claim starttime to resource_usage depending on state of usage_at_or_before_start
     IF usage_at_or_before_start IS NOT NULL THEN
         IF usage_at_or_before_start.as_of_timestamp = new_claim.starttime THEN
@@ -278,16 +286,32 @@ BEGIN
         VALUES (new_claim.resource_id, new_claim.status_id, new_claim.endtime, 0);
     END IF;
 
+    SELECT * from clock_timestamp() into part_end;
+    RAISE NOTICE 'process_new_claim_into_resource_usages1 took %', part_end - part_start;
+    SELECT * from clock_timestamp() into part_start;
+
     --now modify any existing usages between new_claim claim starttime and endtime
     FOR intermediate_usage IN SELECT * FROM resource_allocation.resource_usage ru
     WHERE ru.resource_id = new_claim.resource_id
     AND ru.status_id = new_claim.status_id
-    AND ru.as_of_timestamp > new_claim.starttime
-    AND ru.as_of_timestamp < new_claim.endtime
+    AND ru.as_of_timestamp between new_claim.starttime and new_claim.endtime
     LOOP
         UPDATE resource_allocation.resource_usage ru SET usage = intermediate_usage.usage + new_claim.claim_size
         WHERE ru.id = intermediate_usage.id;
     END LOOP;
+
+    -- 20181024: possible candidate for speedup of for loop above?
+--    UPDATE resource_allocation.resource_usage ru
+--    SET usage = ru.usage + new_claim.claim_size
+--    WHERE ru.resource_id = new_claim.resource_id
+--    AND ru.status_id = new_claim.status_id
+--    AND between new_claim.starttime and new_claim.endtime;
+
+    SELECT * from clock_timestamp() into part_end;
+    RAISE NOTICE 'process_new_claim_into_resource_usages2 took %', part_end - part_start;
+
+    SELECT * from clock_timestamp() into proc_end;
+    RAISE NOTICE 'process_new_claim_into_resource_usages  took %', proc_end - proc_start;
 END;
 $$ LANGUAGE plpgsql;
 ALTER FUNCTION resource_allocation.process_new_claim_into_resource_usages(new_claim resource_allocation.resource_claim) OWNER TO resourceassignment;
@@ -552,7 +576,11 @@ DECLARE
     usage_before_start RECORD;
     usage_at_end RECORD;
     intermediate_usage RECORD;
+    proc_start timestamp with time zone;
+    proc_end timestamp with time zone;
 BEGIN
+    SELECT * from clock_timestamp() into proc_start;
+
     -- find resource_usage at claim starttime
     SELECT * FROM resource_allocation.get_resource_usage_at_or_before(old_claim.resource_id, old_claim.status_id, old_claim.starttime, true, false, true) into usage_at_start;
 
@@ -606,6 +634,9 @@ BEGIN
         UPDATE resource_allocation.resource_usage ru SET usage = intermediate_usage.usage - old_claim.claim_size
         WHERE ru.id = intermediate_usage.id;
     END LOOP;
+
+    SELECT * from clock_timestamp() into proc_end;
+    RAISE NOTICE 'process_old_claim_outof_resource_usages took %', proc_end - proc_start;
 END;
 $$ LANGUAGE plpgsql;
 ALTER FUNCTION resource_allocation.process_old_claim_outof_resource_usages(old_claim resource_allocation.resource_claim) OWNER TO resourceassignment;
@@ -619,7 +650,11 @@ CREATE OR REPLACE FUNCTION resource_allocation.get_resource_usage_at_or_before(_
 $$
 DECLARE
     result resource_allocation.resource_usage;
+    proc_start timestamp with time zone;
+    proc_end timestamp with time zone;
 BEGIN
+    SELECT * from clock_timestamp() into proc_start;
+
     SELECT * FROM resource_allocation.resource_usage ru
     WHERE ru.resource_id = _resource_id
     AND ru.status_id = _claim_status_id
@@ -652,6 +687,9 @@ BEGIN
         RAISE NOTICE 'get_resource_usage_at_or_before(_resource_id=%, status_id=%, timestamp=%, exactly_at=%, only_before=%, rebuild_usage_when_not_found=%): after rebuild, result=%.', _resource_id, _claim_status_id, _timestamp, exactly_at, only_before, false, result;
     END IF;
 
+    SELECT * from clock_timestamp() into proc_end;
+    RAISE NOTICE 'get_resource_usage_at_or_before         took %', proc_end - proc_start;
+
     RETURN result;
 END;
 $$ LANGUAGE plpgsql;
@@ -851,9 +889,22 @@ DECLARE
     task_scheduled_status_id int := 400; --beware: hard coded instead of lookup for performance
     task_queued_status_id int := 500; --beware: hard coded instead of lookup for performance
     claim_has_conflicts boolean;
+    proc_start timestamp with time zone;
+    proc_end timestamp with time zone;
 BEGIN
-    --order of following steps is important, do not reorder the steps
+    SELECT * from clock_timestamp() into proc_start;
+
+--    IF TG_OP = 'INSERT' THEN
+--        RAISE NOTICE 'before_claim_insertupdatedelete % %', TG_OP, NEW;
+--    END IF;
+--    IF TG_OP = 'UPDATE' THEN
+--        RAISE NOTICE 'before_claim_insertupdatedelete % % %', TG_OP, OLD, NEW;
+--    END IF;
+--    IF TG_OP = 'DELETE' THEN
+--        RAISE NOTICE 'before_claim_insertupdatedelete % %', TG_OP, OLD;
+--    END IF;
 
+    --order of following steps is important, do not reorder the steps
     IF TG_OP = 'INSERT' OR TG_OP = 'UPDATE' THEN
         IF NEW.starttime >= NEW.endtime THEN
             -- Conceptually, you can't claim and release a resource at the same timestamp.
@@ -931,6 +982,9 @@ BEGIN
         END IF;
     END IF;
 
+    SELECT * from clock_timestamp() into proc_end;
+    RAISE NOTICE 'before_claim_insertupdatedelete         took %', proc_end - proc_start;
+
     IF TG_OP = 'DELETE' THEN
         RETURN OLD;
     END IF;
@@ -965,7 +1019,11 @@ DECLARE
     task_conflict_status_id int := 335; --beware: hard coded instead of lookup for performance
     affected_claim resource_allocation.resource_claim;
     claim_has_conflicts boolean;
+    proc_start timestamp with time zone;
+    proc_end timestamp with time zone;
 BEGIN
+    SELECT * from clock_timestamp() into proc_start;
+
     -- in the before trigger function, everything on the claim has been checked and adapted.
     -- now (in the after trigger, when all claims were inserted/updated in the database), let's check if the task should also be updated (to conflict status for example)
     -- only if claim status was changed or inserted...
@@ -1029,6 +1087,9 @@ BEGIN
         END LOOP;
     END IF;
 
+    SELECT * from clock_timestamp() into proc_end;
+    RAISE NOTICE 'after_claim_insertupdatedelete          took %', proc_end - proc_start;
+
     IF TG_OP = 'DELETE' THEN
         RETURN OLD;
     END IF;