Skip to content
Snippets Groups Projects
Commit e0bf0fe5 authored by Jorrit Schaap's avatar Jorrit Schaap
Browse files

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

SW-41: measure and log some more sql procedures to see where the time is spend. report on too slow queries.
parent ad1fefa1
No related branches found
No related tags found
No related merge requests found
Hide whitespace changes
Inline Side-by-side
SAS/ResourceAssignment/ResourceAssignmentDatabase/radb/sql/add_functions_and_triggers.sql
+ 22
− 2
View file @ e0bf0fe5
......@@ -248,11 +248,14 @@ DECLARE
part_end timestamp with time zone;
BEGIN
SELECT * from clock_timestamp() into proc_start;
SELECT * from clock_timestamp() into part_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_end;
RAISE NOTICE 'process_new_claim_into_resource_usages1 took %', part_end - part_start;
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
......@@ -287,7 +290,7 @@ BEGIN
END IF;
SELECT * from clock_timestamp() into part_end;
RAISE NOTICE 'process_new_claim_into_resource_usages1 took %', part_end - part_start;
RAISE NOTICE 'process_new_claim_into_resource_usages2 took %', part_end - part_start;
SELECT * from clock_timestamp() into part_start;
--now modify any existing usages between new_claim claim starttime and endtime
......@@ -308,7 +311,7 @@ BEGIN
-- 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;
RAISE NOTICE 'process_new_claim_into_resource_usages3 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;
......@@ -578,8 +581,11 @@ DECLARE
intermediate_usage RECORD;
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;
SELECT * from clock_timestamp() into part_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;
......@@ -596,6 +602,9 @@ BEGIN
RAISE EXCEPTION 'process_old_claim_outof_resource_usages(%) cannot find usage_at_end', old_claim;
END IF;
SELECT * from clock_timestamp() into part_end;
RAISE NOTICE 'process_old_claim_outof_resource_usage1 took %', part_end - part_start;
SELECT * from clock_timestamp() into part_start;
IF usage_at_start.usage = old_claim.claim_size THEN
IF usage_at_end.usage = 0 THEN
......@@ -624,6 +633,10 @@ BEGIN
DELETE FROM resource_allocation.resource_usage ru WHERE ru.id = usage_at_end.id;
END IF;
SELECT * from clock_timestamp() into part_end;
RAISE NOTICE 'process_old_claim_outof_resource_usage2 took %', part_end - part_start;
SELECT * from clock_timestamp() into part_start;
--now modify any existing usages between old_claim claim starttime and endtime
FOR intermediate_usage IN SELECT * FROM resource_allocation.resource_usage ru
WHERE ru.resource_id = old_claim.resource_id
......@@ -820,11 +833,18 @@ CREATE OR REPLACE FUNCTION resource_allocation.has_conflict_with_overlapping_cla
$$
DECLARE
free_claimable_capacity bigint;
proc_start timestamp with time zone;
proc_end timestamp with time zone;
BEGIN
SELECT * from clock_timestamp() into proc_start;
-- get the free free_claimable_capacity for this resource for the claim's time window
-- this does not include the current claim which is (or at least should be) tentative.
SELECT * FROM resource_allocation.get_resource_claimable_capacity_between(claim.resource_id, claim.starttime, claim.endtime) INTO free_claimable_capacity;
SELECT * from clock_timestamp() into proc_end;
RAISE NOTICE 'has_conflict_with_overlapping_claims took %', proc_end - proc_start;
return claim.claim_size > free_claimable_capacity;
END;
$$ LANGUAGE plpgsql;
......
SAS/ResourceAssignment/ResourceAssignmentDatabase/tests/radb_performance_test.py
+ 47
− 42
View file @ e0bf0fe5
......@@ -41,8 +41,7 @@ def tearDownModule():
class ResourceAssignmentDatabaseTest(radb_common_testing.RADBCommonTest):
def test_resource_usages_performance(self):
RESOURCE_ID = 117
self.radb.updateResourceAvailability(RESOURCE_ID, available_capacity=10000000, total_capacity=10000000)
num_resources = self.radb._executeQuery('select count(id) from virtual_instrument.resource;', fetch=_FETCH_ONE)['count']
insert_elapsed_list = []
......@@ -53,44 +52,50 @@ class ResourceAssignmentDatabaseTest(radb_common_testing.RADBCommonTest):
with open(filename, 'w') as file:
file.write('#tasks, #claims, #claims_per_resource, #inserted_claims, elapsed_insert, elapsed_rebuild\n')
counter = 0
for num_claims_per_resource in [1, 2, 5, 10, 20, 50, 100, 200]:
for num_claims_to_insert in [1, 2, 5, 10, 20, 50, 100, 200]:
counter += 1
result = self.radb.insertSpecificationAndTask(counter, counter, 'approved', 'observation',
now+timedelta(hours=3*counter),
now + timedelta(hours=1 + 3*counter),
'content', 'CEP4')
task_id = result['task_id']
task = self.radb.getTask(task_id)
spec_ids.append(task['specification_id'])
claims = [{'resource_id': q/num_claims_per_resource,
'starttime': task['starttime']-timedelta(minutes=randint(0, 1800)),
'endtime': task['starttime']+timedelta(seconds=randint(1801, 3600)),
'status': 'tentative',
'claim_size': q}
for q in range(num_claims_to_insert)]
start = datetime.utcnow()
self.radb.insertResourceClaims(task_id, claims, 'foo', 1, 1)
elapsed_insert = totalSeconds(datetime.utcnow() - start)
insert_elapsed_list.append(elapsed_insert)
# enforce perfomance criterion: inserting claims should take less than 0.5 sec
self.assertLess(elapsed_insert, 0.5)
start = datetime.utcnow()
# make sure the usage table is wiped, so asserts fail when rebuild_resource_usages_from_claims is erroneously roll'ed back.
# self.radb.rebuild_resource_usages_from_claims(RESOURCE_ID, 'tentative')
elapsed_rebuild = -1 #totalSeconds(datetime.utcnow() - start)
num_tasks = self.radb._executeQuery('select count(id) from resource_allocation.task;', fetch=_FETCH_ONE)['count']
num_claims = self.radb._executeQuery('select count(id) from resource_allocation.resource_claim;', fetch=_FETCH_ONE)['count']
logger.info('TEST RESULT: radb now contains %d tasks, %d claims, insert of %d claims with %d claims per resource takes on average %.3fsec and a rebuild of the whole usage table takes %.3fsec',
num_tasks, num_claims, num_claims_to_insert, num_claims_per_resource, elapsed_insert, elapsed_rebuild)
file.write('%d, %d, %d, %d, %.3f, %.3f\n' % (num_tasks, num_claims, num_claims_per_resource, num_claims_to_insert, elapsed_insert, elapsed_rebuild))
file.flush()
for repeat_nr in range(10):
# it is not common to claim a single resource multiple times for the same task, but it can happen, so test for it.
for num_claims_per_resource in [1, 2, 5, 10, 20]:
# let's test over a feasible range of #claims. A lofar observation usually has ~200 claims.
for num_claims_to_insert in [1, 2, 5, 10, 20, 50, 100, 200, 500]:
num_claims_to_insert = min(num_claims_to_insert, num_claims_per_resource*num_resources)
counter += 1
result = self.radb.insertSpecificationAndTask(counter, counter, 'approved', 'observation',
now+timedelta(hours=3*counter),
now + timedelta(hours=1 + 3*counter),
'content', 'CEP4')
task_id = result['task_id']
task = self.radb.getTask(task_id)
spec_ids.append(task['specification_id'])
claims = [{'resource_id': q/num_claims_per_resource,
'starttime': task['starttime']-timedelta(minutes=randint(0, 1800)),
'endtime': task['starttime']+timedelta(seconds=randint(1801, 3600)),
'status': 'tentative',
'claim_size': q}
for q in range(num_claims_to_insert)]
start = datetime.utcnow()
self.radb.insertResourceClaims(task_id, claims, 'foo', 1, 1)
elapsed_insert = totalSeconds(datetime.utcnow() - start)
insert_elapsed_list.append(elapsed_insert)
num_tasks = self.radb._executeQuery('select count(id) from resource_allocation.task;', fetch=_FETCH_ONE)['count']
num_claims = self.radb._executeQuery('select count(id) from resource_allocation.resource_claim;', fetch=_FETCH_ONE)['count']
# enforce perfomance criterion: inserting claims should take less than 1.0 sec
self.assertLess(elapsed_insert, 1.0, msg="insertResourceClaims took longer than allowed. (%ssec > %ssec) num_tasks=%s num_claims=%s num_claims_to_insert=%s num_claims_per_resource=%s" %(
elapsed_insert, 1.0, num_tasks, num_claims, num_claims_to_insert, num_claims_per_resource))
start = datetime.utcnow()
# make sure the usage table is wiped, so asserts fail when rebuild_resource_usages_from_claims is erroneously roll'ed back.
# self.radb.rebuild_resource_usages_from_claims(RESOURCE_ID, 'tentative')
elapsed_rebuild = -1 #totalSeconds(datetime.utcnow() - start)
logger.info('TEST RESULT: radb now contains %d tasks, %d claims, insert of %d claims with %d claims per resource takes on average %.3fsec and a rebuild of the whole usage table takes %.3fsec',
num_tasks, num_claims, num_claims_to_insert, num_claims_per_resource, elapsed_insert, elapsed_rebuild)
file.write('%d, %d, %d, %d, %.3f, %.3f\n' % (num_tasks, num_claims, num_claims_per_resource, num_claims_to_insert, elapsed_insert, elapsed_rebuild))
file.flush()
logger.info('removing all test specs/tasks/claims from db')
delete_elapsed_list = []
......@@ -105,8 +110,8 @@ class ResourceAssignmentDatabaseTest(radb_common_testing.RADBCommonTest):
elapsed = totalSeconds(datetime.utcnow() - start)
delete_elapsed_list.append(elapsed)
# enforce perfomance criterion: (cascading) delete of spec should take less than 0.5 sec
self.assertLess(elapsed, 0.5)
# enforce perfomance criterion: (cascading) delete of spec should take less than 1.0 sec
self.assertLess(elapsed, 1.0)
file.write('%d, %d, %.3f\n' % (num_tasks, num_claims, elapsed))
file.flush()
......
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment