Merge pull request #8 from adessoAG/structure_timestamps

Structure timestamps

.gitignore

@@ -1,6 +1,7 @@
 .gradle
 /build/
 !gradle/wrapper/gradle-wrapper.jar
+*.csv
 
 ### Java ###
 .class

build.gradle

@@ -10,15 +10,23 @@ buildscript {
         classpath("org.springframework.boot:spring-boot-gradle-plugin:${springBootVersion}")
         classpath("org.jetbrains.kotlin:kotlin-gradle-plugin:${kotlinVersion}")
         classpath("org.jetbrains.kotlin:kotlin-allopen:${kotlinVersion}")
+        classpath "org.jetbrains.kotlin:kotlin-noarg:${kotlinVersion}"
     }
 }
 
+ext.junit4Version        = '4.12'
+ext.junitVintageVersion  = '4.12.0'
+ext.junitPlatformVersion = '1.1.0'
+ext.junitJupiterVersion  = '5.1.0'
+ext.log4jVersion         = '2.6.2'
+
 apply plugin: 'kotlin'
 apply plugin: 'kotlin-spring'
 apply plugin: 'eclipse'
 apply plugin: 'org.springframework.boot'
 apply plugin: 'io.spring.dependency-management'
 apply plugin: 'maven-publish'
+apply plugin: "kotlin-jpa"
 
 publishing {
     publications {
@@ -69,13 +77,22 @@ dependencies {
     compile('com.fasterxml.jackson.module:jackson-module-kotlin')
     compile('org.jetbrains.kotlin:kotlin-stdlib-jdk8')
     compile('org.jetbrains.kotlin:kotlin-reflect')
-    compile('org.springframework.boot:spring-boot-starter-test') {
-        exclude group: 'junit', module: 'junit'
-    }
-    compile('org.junit.jupiter:junit-jupiter-api')
-    runtime('org.springframework.boot:spring-boot-devtools')
-    testCompile('org.springframework.boot:spring-boot-starter-test') {
-        exclude group: 'junit', module: 'junit'
-    }
-    testCompile('org.junit.jupiter:junit-jupiter-api')
+
+    compile('org.springframework.boot:spring-boot-starter-test') { exclude group: 'junit', module: 'junit' }
+    testCompile('org.springframework.boot:spring-boot-starter-test') { exclude group: 'junit', module: 'junit' }
+
+    // JUnit Jupiter API and TestEngine implementation
+    compile("org.junit.jupiter:junit-jupiter-api:${junitJupiterVersion}")
+    testCompile("org.junit.jupiter:junit-jupiter-api:${junitJupiterVersion}")
+    testRuntime("org.junit.jupiter:junit-jupiter-engine:${junitJupiterVersion}")
+
+    // If you also want to support JUnit 3 and JUnit 4 tests
+    //testCompile("junit:junit:${junit4Version}")
+    //testRuntime("org.junit.vintage:junit-vintage-engine:${junitVintageVersion}")
+
+    testRuntime("org.apache.logging.log4j:log4j-core:${log4jVersion}")
+    testRuntime("org.apache.logging.log4j:log4j-jul:${log4jVersion}")
+
+    // Only needed to run tests in an IDE that bundles an older version (e.g. IntelliJ)
+    testRuntime("org.junit.platform:junit-platform-launcher:${junitPlatformVersion}")
 }

readme.md

@@ -16,4 +16,10 @@ For the user of the test classes, it looks like some tests take a long time to e
 To make this behavior transparent, a report is created.
 
 # How to use
-ToDo
+
+Add the dependency to your project.
+
+`//TODO`
+
+Add @JUnitInsights to the test-classes you want to benchmark.
+Be aware that ExtendsWith(SpringExtension::class) needs to be used as Runner-class.

src/main/kotlin/de/adesso/junitinsights/JunitInsightsApplication.kt

@@ -4,7 +4,7 @@ import org.springframework.boot.autoconfigure.SpringBootApplication
 import org.springframework.boot.runApplication
 
 @SpringBootApplication
-open class JunitInsightsApplication
+class JunitInsightsApplication
 
 fun main(args: Array<String>) {
     runApplication<JunitInsightsApplication>(*args)

src/main/kotlin/de/adesso/junitinsights/annotations/JUnitInsights.kt

@@ -0,0 +1,12 @@
+package de.adesso.junitinsights.annotations
+
+import de.adesso.junitinsights.tests.TestBenchmarkExtension
+import org.junit.jupiter.api.extension.ExtendWith
+
+/**
+ * Annotate your test classes with this method to activate JUnit-insights.
+ */
+@Target(AnnotationTarget.TYPE, AnnotationTarget.CLASS)
+@Retention(value = AnnotationRetention.RUNTIME)
+@ExtendWith(TestBenchmarkExtension::class)
+annotation class JUnitInsights

src/main/kotlin/de/adesso/junitinsights/annotations/NoJUnitInsights.kt

@@ -0,0 +1,8 @@
+package de.adesso.junitinsights.annotations
+
+/**
+ * Annotate the functions you don't want to have insights about with this and they won't be benchmarked.
+ */
+@Target(AnnotationTarget.FUNCTION)
+@Retention(value = AnnotationRetention.RUNTIME)
+annotation class NoJUnitInsights

src/main/kotlin/de/adesso/junitinsights/HelloController.kt → src/main/kotlin/de/adesso/junitinsights/example/HelloController.kt

@@ -1,4 +1,4 @@
-package de.adesso.junitinsights
+package de.adesso.junitinsights.example
 
 import org.springframework.web.bind.annotation.RequestMapping
 import org.springframework.web.bind.annotation.RestController
@@ -7,7 +7,7 @@ import org.springframework.web.bind.annotation.RestController
 class HelloController {
 
     @RequestMapping("/")
-    fun index() : String {
+    fun index(): String {
         return "Greetings from Spring Boot!"
     }
 }

src/main/kotlin/de/adesso/junitinsights/listener/SpringContextListener.kt

@@ -0,0 +1,38 @@
+package de.adesso.junitinsights.listener
+
+import de.adesso.junitinsights.tools.TimestampWriter
+import org.slf4j.Logger
+import org.slf4j.LoggerFactory
+import org.springframework.context.event.ContextClosedEvent
+import org.springframework.context.event.ContextRefreshedEvent
+import org.springframework.context.event.EventListener
+import org.springframework.stereotype.Component
+
+@Component
+class SpringContextListener {
+
+    companion object {
+        val log: Logger = LoggerFactory.getLogger(this::class.java)
+    }
+
+    private val timestampWriter = TimestampWriter
+
+    @EventListener(ContextRefreshedEvent::class)
+    fun catchContextStart(event: ContextRefreshedEvent) {
+        //log.info("### AppContextId: ${event.applicationContext.id}")
+        //TODO Check if first init before closing initial, so that its not a refresh
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "context refreshed",
+                "", "")
+    }
+
+    @EventListener(ContextClosedEvent::class)
+    fun catchContextEnd(event: ContextClosedEvent) {
+        //log.info("### AppContextId: ${event.applicationContext.id}")
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "context closed",
+                "", "")
+        //TODO: Is this method really called only once at the end?
+        timestampWriter.flush()
+    }
+}

src/main/kotlin/de/adesso/junitinsights/tests/TestBenchmarkExtension.kt

@@ -0,0 +1,97 @@
+package de.adesso.junitinsights.tests
+
+import de.adesso.junitinsights.annotations.NoJUnitInsights
+import de.adesso.junitinsights.tools.TimestampWriter
+import org.junit.jupiter.api.extension.*
+import org.junit.platform.commons.support.AnnotationSupport.isAnnotated
+
+
+/**
+ * Extension that measures the execution time of each test class and method
+ *
+ */
+class TestBenchmarkExtension :
+        BeforeAllCallback, AfterAllCallback,
+        BeforeEachCallback, AfterEachCallback,
+        BeforeTestExecutionCallback, AfterTestExecutionCallback {
+
+    private val timestampWriter = TimestampWriter
+
+    override fun beforeAll(context: ExtensionContext) {
+        if (shouldNotBeBenchmarked(context)) {
+            return
+        }
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "before all",
+                trimClassName(context),
+                trimMethodName(context))
+    }
+
+    override fun afterAll(context: ExtensionContext) {
+        if (shouldNotBeBenchmarked(context)) {
+            return
+        }
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "after all",
+                trimClassName(context),
+                trimMethodName(context))
+        timestampWriter.flush()
+    }
+
+    override fun beforeEach(context: ExtensionContext) {
+        if (shouldNotBeBenchmarked(context)) {
+            return
+        }
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "before each",
+                trimClassName(context),
+                trimMethodName(context))
+    }
+
+    override fun afterEach(context: ExtensionContext) {
+        if (shouldNotBeBenchmarked(context)) {
+            return
+        }
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "after each",
+                trimClassName(context),
+                trimMethodName(context))
+    }
+
+    @Throws(Exception::class)
+    override fun beforeTestExecution(context: ExtensionContext) {
+        if (shouldNotBeBenchmarked(context)) {
+            return
+        }
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "before test execution",
+                trimClassName(context),
+                trimMethodName(context))
+    }
+
+    @Throws(Exception::class)
+    override fun afterTestExecution(context: ExtensionContext) {
+        if (shouldNotBeBenchmarked(context)) {
+            return
+        }
+        timestampWriter.writeTimestamp(System.currentTimeMillis(),
+                "after test execution",
+                trimClassName(context),
+                trimMethodName(context))
+    }
+
+    private fun shouldNotBeBenchmarked(context: ExtensionContext): Boolean {
+        return context.element
+                .map<Boolean> { el -> isAnnotated(el, NoJUnitInsights::class.java) }
+                .orElse(false)
+    }
+
+    private fun trimClassName(testContext: ExtensionContext): String {
+        return testContext.testClass.toString().replace("class", "")
+    }
+
+    private fun trimMethodName(testContext: ExtensionContext): String {
+        val splitName = testContext.testMethod.toString().split(".")
+        return if (splitName.isEmpty()) "" else splitName.last()
+    }
+}

src/main/kotlin/de/adesso/junitinsights/tools/TimestampWriter.kt

@@ -0,0 +1,47 @@
+package de.adesso.junitinsights.tools
+
+import org.slf4j.Logger
+import org.slf4j.LoggerFactory
+import java.io.File
+
+var deltaMode = false
+var logOutput = false
+
+object TimestampWriter {
+    private var file = File("timestamps.csv").bufferedWriter()
+    private var lastTimestamp: Long = 0
+
+    private var logger: Logger = LoggerFactory.getLogger(this::class.java)
+
+    init {
+        file.write("timestamp;event;test class;test function")
+        file.newLine()
+    }
+
+    fun writeTimestamp(timestamp: Long, event: String, testClass: String, testFunction: String) {
+        var tstamp: Long = timestamp
+        if (deltaMode) {
+            if (lastTimestamp == 0.toLong()) {
+                lastTimestamp = timestamp
+            } else {
+                tstamp = timestamp - lastTimestamp
+                lastTimestamp = timestamp
+            }
+        }
+        file.write(tstamp.toString() + ";" + event + ";" + trimObjectString(testClass) + ";" + trimObjectString(testFunction))
+        file.newLine()
+        if (logOutput)
+            logger.info("########" + tstamp.toString() + ";" + event + ";" + trimObjectString(testClass) + ";" + trimObjectString(testFunction) + "\n")
+    }
+
+    fun flush() {
+        file.flush()
+    }
+
+    private fun trimObjectString(string: String): String {
+        return string.replace("Optional.empty", "")
+                .replace("Optional", "")
+                .replace("[", "")
+                .replace("]", "")
+    }
+}