From ad1fefa1f93be80a21494b296539582175ba1e52 Mon Sep 17 00:00:00 2001
From: Jorrit Schaap <schaap@astron.nl>
Date: Wed, 24 Oct 2018 14:30:04 +0000
Subject: [PATCH] SW-41: measure and log several sql procedures to see where
the time is spend.
---
.../ResourceAssignmentDatabase/radb.py | 15 ++++-
.../radb/sql/add_functions_and_triggers.sql | 67 ++++++++++++++++++-
2 files changed, 78 insertions(+), 4 deletions(-)
diff --git a/SAS/ResourceAssignment/ResourceAssignmentDatabase/radb.py b/SAS/ResourceAssignment/ResourceAssignmentDatabase/radb.py
index e84053fdb51..ca3b66f20ab 100644
--- a/SAS/ResourceAssignment/ResourceAssignmentDatabase/radb.py
+++ b/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')
diff --git a/SAS/ResourceAssignment/ResourceAssignmentDatabase/radb/sql/add_functions_and_triggers.sql b/SAS/ResourceAssignment/ResourceAssignmentDatabase/radb/sql/add_functions_and_triggers.sql
index 9d4127f4ae7..350650dbbf7 100644
--- a/SAS/ResourceAssignment/ResourceAssignmentDatabase/radb/sql/add_functions_and_triggers.sql
+++ b/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;
--
GitLab