Add instrumentation to the PR jobs

Measure how much time we spend in the groovy scripts versus how much
time is spent executing the test scripts for each component.

Signed-off-by: Bence Szépkúti <[email protected]>

src/org/mbed/tls/jenkins/JobTimestamps.groovy

@@ -0,0 +1,83 @@
+/*
+ *  Copyright (c) 2023, Arm Limited, All Rights Reserved
+ *  SPDX-License-Identifier: Apache-2.0
+ *
+ *  Licensed under the Apache License, Version 2.0 (the "License"); you may
+ *  not use this file except in compliance with the License.
+ *  You may obtain a copy of the License at
+ *
+ *  http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *  Unless required by applicable law or agreed to in writing, software
+ *  distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ *  WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *  See the License for the specific language governing permissions and
+ *  limitations under the License.
+ *
+ *  This file is part of Mbed TLS (https://www.trustedfirmware.org/projects/mbed-tls/)
+ */
+
+package org.mbed.tls.jenkins
+
+import java.util.concurrent.atomic.AtomicLong
+
+import com.cloudbees.groovy.cps.NonCPS
+
+class JobTimestamps {
+    private final AtomicLong start, end, innerStart, innerEnd
+
+    JobTimestamps() {
+        this.start      = new AtomicLong(-1)
+        this.end        = new AtomicLong(-1)
+        this.innerStart = new AtomicLong(-1)
+        this.innerEnd   = new AtomicLong(-1)
+    }
+
+    @NonCPS
+    long getStart() {
+        return this.@start.get()
+    }
+
+    @NonCPS
+    long getEnd() {
+        return this.@end.get()
+    }
+
+    @NonCPS
+    long getInnerStart() {
+        return this.@innerStart.get()
+    }
+
+    @NonCPS
+    long getInnerEnd() {
+        return this.@innerEnd.get()
+    }
+
+    private static void set(String name, AtomicLong var, long val) {
+        if (!var.compareAndSet(-1, val)) {
+            throw new IllegalAccessError("$name set twice")
+        }
+    }
+
+    void setStart(long val) {
+        set('start', start, val)
+    }
+
+    void setEnd(long val) {
+        set('end', end, val)
+    }
+
+    void setInnerStart(long val) {
+        set('innerStart', innerStart, val)
+    }
+
+    void setInnerEnd(long val) {
+        set('innerEnd', innerEnd, val)
+    }
+
+    @NonCPS
+    @Override
+    String toString() {
+        return "JobTimestamps(start:$start, end:$end, innerStart:$innerStart, innerEnd:$innerEnd)"
+    }
+}

vars/analysis.groovy

@@ -17,11 +17,83 @@
  *  This file is part of Mbed TLS (https://www.trustedfirmware.org/projects/mbed-tls/)
  */
 
+import java.util.concurrent.Callable
+import java.util.concurrent.ConcurrentHashMap
+import java.util.concurrent.ConcurrentMap
+import java.util.function.Function
+
 import groovy.transform.Field
 
+import com.cloudbees.groovy.cps.NonCPS
+import net.sf.json.JSONObject
+
+import org.mbed.tls.jenkins.JobTimestamps
+
 // A static field has its content preserved across stages.
 @Field static outcome_stashes = []
 
+@Field private static ConcurrentMap<String, ConcurrentMap<String, JobTimestamps>> timestamps =
+        new ConcurrentHashMap<String, ConcurrentMap<String, JobTimestamps>>();
+
+void record_timestamps(String group, String job_name, Callable<Void> body, String node_label = null) {
+    def ts = new JobTimestamps()
+    def group_map = timestamps.computeIfAbsent(group, new Function<String, ConcurrentMap<String, JobTimestamps>>() {
+        @Override
+        @NonCPS
+        ConcurrentMap<String, JobTimestamps> apply(String key) {
+            return new ConcurrentHashMap<String, JobTimestamps>()
+        }
+    })
+
+    if (group_map.putIfAbsent(job_name, ts) != null) {
+        throw new IllegalArgumentException("Group and job name pair '$group:$job_name' used multiple times.")
+    }
+
+    try {
+        def stamped_body = {
+            ts.start = System.currentTimeMillis()
+            body()
+        }
+        if (node_label != null) {
+            node(node_label, stamped_body)
+        } else {
+            stamped_body()
+        }
+    } finally {
+        ts.end = System.currentTimeMillis()
+    }
+}
+
+void node_record_timestamps(String node_label, String job_name, Callable<Void> body) {
+    record_timestamps(node_label, job_name, body, node_label)
+}
+
+void record_inner_timestamps(String group, String job_name, Callable<Void> body) {
+    def ts = timestamps[group][job_name]
+    if (ts == null) {
+        throw new NoSuchElementException(job_name)
+    }
+    ts.innerStart = System.currentTimeMillis()
+    try {
+        body()
+    } finally {
+        ts.innerEnd = System.currentTimeMillis()
+    }
+}
+
+void print_timestamps() {
+    writeFile(
+        file: 'timestamps.json',
+        text: JSONObject.fromObject([
+            job: currentBuild.fullProjectName,
+            build: currentBuild.number,
+            main: timestamps.remove('main'),
+            subtasks: timestamps
+        ]).toString()
+    )
+    archiveArtifacts(artifacts: 'timestamps.json')
+}
+
 def stash_outcomes(job_name) {
     def stash_name = job_name + '-outcome'
     if (findFiles(glob: '*-outcome.csv')) {
@@ -77,21 +149,22 @@ def gather_outcomes() {
     if (outcome_stashes.isEmpty()) {
         return
     }
-    node('helper-container-host') {
-        dir('outcomes') {
+    dir('outcomes') {
+        deleteDir()
+        try {
+            checkout_repo.checkout_repo()
+            process_outcomes()
+        } finally {
             deleteDir()
-            try {
-                checkout_repo.checkout_repo()
-                process_outcomes()
-            } finally {
-                deleteDir()
-            }
         }
     }
 }
 
 def analyze_results() {
-    gather_outcomes()
+    node('helper-container-host') {
+        gather_outcomes()
+        print_timestamps()
+    }
 }
 
 def analyze_results_and_notify_github() {