Merge "Introduce Instrumentation"

3 files changed, 46 insertions, 21 deletions

diff --git a/cps-ri/src/test/groovy/org/onap/cps/spi/impl/CpsPersistencePerfSpecBase.groovy b/cps-ri/src/test/groovy/org/onap/cps/spi/impl/CpsPersistencePerfSpecBase.groovy
index 3bbae2d08c..b67a5cc686 100644
--- a/cps-ri/src/test/groovy/org/onap/cps/spi/impl/CpsPersistencePerfSpecBase.groovy
+++ b/cps-ri/src/test/groovy/org/onap/cps/spi/impl/CpsPersistencePerfSpecBase.groovy
@@ -22,6 +22,7 @@ package org.onap.cps.spi.impl
 
 import org.onap.cps.spi.model.DataNode
 import org.onap.cps.spi.model.DataNodeBuilder
+import org.springframework.util.StopWatch
 
 class CpsPersistencePerfSpecBase extends CpsPersistenceSpecBase {
 
@@ -32,6 +33,18 @@ class CpsPersistencePerfSpecBase extends CpsPersistenceSpecBase {
 
     static def xpathsToAllGrandChildren = []
 
+    static def PERFORMANCE_RECORD = []
+
+    def stopWatch = new StopWatch()
+
+    def cleanupSpec() {
+        println('#############################################################################')
+        println('##             P E R F O R M A N C E   T E S T   R E S U L T S             ##')
+        println('#############################################################################')
+        PERFORMANCE_RECORD.sort().each { println(it) }
+        PERFORMANCE_RECORD.clear()
+    }
+
     def createLineage(cpsDataPersistenceService, numberOfChildren, numberOfGrandChildren, createLists) {
         xpathsToAllGrandChildren = []
         (1..numberOfChildren).each {
@@ -71,4 +84,16 @@ class CpsPersistencePerfSpecBase extends CpsPersistenceSpecBase {
         }
         return nodeCount
     }
+
+    def recordAndAssertPerformance(String shortTitle, thresholdInMs, recordedTimeInMs) {
+        def pass = recordedTimeInMs <= thresholdInMs
+        if (shortTitle.length()>40) {
+            shortTitle = shortTitle.substring(0,40)
+        }
+        def record = String.format('%2d.%-40s limit%,7d took %,7d ms ', PERFORMANCE_RECORD.size()+1, shortTitle, thresholdInMs, recordedTimeInMs)
+        record += pass?'PASS':'FAIL'
+        PERFORMANCE_RECORD.add(record)
+        assert recordedTimeInMs <= thresholdInMs
+        return true
+    }
 }
diff --git a/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServiceDeletePerfTest.groovy b/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServiceDeletePerfTest.groovy
index 4dd4823c95..91da53d2ea 100644
--- a/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServiceDeletePerfTest.groovy
+++ b/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServiceDeletePerfTest.groovy
@@ -25,6 +25,7 @@ import org.onap.cps.spi.impl.CpsPersistencePerfSpecBase
 import org.springframework.beans.factory.annotation.Autowired
 import org.springframework.test.context.jdbc.Sql
 import org.springframework.util.StopWatch
+import spock.lang.Shared
 
 import java.util.concurrent.TimeUnit
 
@@ -43,13 +44,13 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
 
     @Sql([CLEAR_DATA, PERF_TEST_DATA])
     def 'Create a node with many descendants (please note, subsequent tests depend on this running first).'() {
-        given: 'a node with a large number of descendants is created'
+        when: 'a node with a large number of descendants is created'
             stopWatch.start()
             createLineage(objectUnderTest, NUMBER_OF_CHILDREN, NUMBER_OF_GRAND_CHILDREN, false)
             stopWatch.stop()
             def setupDurationInMillis = stopWatch.getTotalTimeMillis()
-        and: 'setup duration is under #ALLOWED_SETUP_TIME_MS milliseconds'
-            assert setupDurationInMillis < ALLOWED_SETUP_TIME_MS
+        then: 'setup duration is under #ALLOWED_SETUP_TIME_MS milliseconds'
+            recordAndAssertPerformance('Setup',ALLOWED_SETUP_TIME_MS, setupDurationInMillis)
     }
 
     def 'Delete 5 children with grandchildren'() {
@@ -62,7 +63,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def deleteDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'delete duration is under 300 milliseconds'
-            assert deleteDurationInMillis < 300
+            recordAndAssertPerformance('Delete 5 children', 300, deleteDurationInMillis)
     }
 
     def 'Delete 50 grandchildren (that have no descendants)'() {
@@ -75,7 +76,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def deleteDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'delete duration is under 350 milliseconds'
-            assert deleteDurationInMillis < 350
+            recordAndAssertPerformance('Delete 50 grandchildren', 350, deleteDurationInMillis)
     }
 
     def 'Delete 1 large data node with many descendants'() {
@@ -85,7 +86,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def deleteDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'delete duration is under 250 milliseconds'
-            assert deleteDurationInMillis < 250
+            recordAndAssertPerformance('Delete one large node', 250, deleteDurationInMillis)
     }
 
     @Sql([CLEAR_DATA, PERF_TEST_DATA])
@@ -96,7 +97,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def setupDurationInMillis = stopWatch.getTotalTimeMillis()
         and: 'setup duration is under #ALLOWED_SETUP_TIME_MS milliseconds'
-            assert setupDurationInMillis < ALLOWED_SETUP_TIME_MS
+            recordAndAssertPerformance('Create node with many list elements', ALLOWED_SETUP_TIME_MS, setupDurationInMillis)
     }
 
     def 'Delete 5 whole lists with many elements'() {
@@ -109,7 +110,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def deleteDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'delete duration is under 1000 milliseconds'
-            assert deleteDurationInMillis < 1000
+            recordAndAssertPerformance('Delete 5 whole lists', 1500, deleteDurationInMillis)
     }
 
     def 'Delete 10 list elements with keys'() {
@@ -123,7 +124,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def deleteDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'delete duration is under 1200 milliseconds'
-            assert deleteDurationInMillis < 1200
+            recordAndAssertPerformance('Delete 10 lists elements', 1500, deleteDurationInMillis)
     }
 
     @Sql([CLEAR_DATA, PERF_TEST_DATA])
@@ -136,7 +137,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def deleteDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'delete duration is under 250 milliseconds'
-            assert deleteDurationInMillis < 250
+            recordAndAssertPerformance('Delete root node', 250, deleteDurationInMillis)
     }
 
     @Sql([CLEAR_DATA, PERF_TEST_DATA])
@@ -149,6 +150,7 @@ class CpsDataPersistenceServiceDeletePerfTest extends CpsPersistencePerfSpecBase
             stopWatch.stop()
             def deleteDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'delete duration is under 250 milliseconds'
-            assert deleteDurationInMillis < 250
+            recordAndAssertPerformance('Delete data nodes for anchor', 250, deleteDurationInMillis)
     }
+
 }
diff --git a/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServicePerfTest.groovy b/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServicePerfTest.groovy
index 0407490274..0c4f5ec41e 100644
--- a/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServicePerfTest.groovy
+++ b/cps-ri/src/test/groovy/org/onap/cps/spi/performance/CpsDataPersistenceServicePerfTest.groovy
@@ -50,9 +50,6 @@ class CpsDataPersistenceServicePerfTest extends CpsPersistencePerfSpecBase {
     static def NUMBER_OF_GRAND_CHILDREN = 50
     static def TOTAL_NUMBER_OF_NODES = 1 + NUMBER_OF_CHILDREN + (NUMBER_OF_CHILDREN * NUMBER_OF_GRAND_CHILDREN)  //  Parent + Children +  Grand-children
 
-    def stopWatch = new StopWatch()
-    def readStopWatch = new StopWatch()
-
     @Sql([CLEAR_DATA, PERF_TEST_DATA])
     def 'Create a node with many descendants (please note, subsequent tests depend on this running first).'() {
         given: 'a node with a large number of descendants is created'
@@ -61,7 +58,7 @@ class CpsDataPersistenceServicePerfTest extends CpsPersistencePerfSpecBase {
             stopWatch.stop()
             def setupDurationInMillis = stopWatch.getTotalTimeMillis()
         and: 'setup duration is under 10 seconds'
-            assert setupDurationInMillis < 10000
+            recordAndAssertPerformance('Setup', 10000, setupDurationInMillis)
     }
 
     def 'Get data node with many descendants by xpath #scenario'() {
@@ -71,7 +68,7 @@ class CpsDataPersistenceServicePerfTest extends CpsPersistencePerfSpecBase {
             stopWatch.stop()
             def readDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'read duration is under 500 milliseconds'
-            assert readDurationInMillis < 500
+            recordAndAssertPerformance("Get ${scenario}", 500, readDurationInMillis)
         and: 'data node is returned with all the descendants populated'
             assert countDataNodes(result) == TOTAL_NUMBER_OF_NODES
         where: 'the following xPaths are used'
@@ -87,7 +84,7 @@ class CpsDataPersistenceServicePerfTest extends CpsPersistencePerfSpecBase {
             stopWatch.stop()
             def readDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'read duration is under 500 milliseconds'
-            assert readDurationInMillis < 500
+            recordAndAssertPerformance('Query with many descendants', 500, readDurationInMillis)
         and: 'data node is returned with all the descendants populated'
             assert countDataNodes(result) == TOTAL_NUMBER_OF_NODES
     }
@@ -95,14 +92,14 @@ class CpsDataPersistenceServicePerfTest extends CpsPersistencePerfSpecBase {
     def 'Performance of finding multiple xpaths'() {
         when: 'we query for all grandchildren (except 1 for fun) with the new native method'
             xpathsToAllGrandChildren.remove(0)
-            readStopWatch.start()
+            stopWatch.start()
             def result = objectUnderTest.getDataNodes(PERF_DATASPACE, PERF_ANCHOR, xpathsToAllGrandChildren, INCLUDE_ALL_DESCENDANTS)
-            readStopWatch.stop()
-            def readDurationInMillis = readStopWatch.getTotalTimeMillis()
+            stopWatch.stop()
+            def readDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'the returned number of entities equal to the number of children * number of grandchildren'
             assert result.size() == xpathsToAllGrandChildren.size()
         and: 'it took less then 4000ms'
-            assert readDurationInMillis < 4000
+            recordAndAssertPerformance('Find multiple xpaths', 4000, readDurationInMillis)
     }
 
     def 'Query many descendants by cps-path with #scenario'() {
@@ -113,6 +110,7 @@ class CpsDataPersistenceServicePerfTest extends CpsPersistencePerfSpecBase {
             def readDurationInMillis = stopWatch.getTotalTimeMillis()
         then: 'read duration is under #allowedDuration milliseconds'
             assert readDurationInMillis < allowedDuration
+            recordAndAssertPerformance("Query many descendants by cpspath (${scenario})", allowedDuration, readDurationInMillis)
         and: 'data node is returned with all the descendants populated'
             assert result.size() == NUMBER_OF_CHILDREN
         where: 'the following options are used'