This is an automated email from the ASF dual-hosted git repository. jdaugherty pushed a commit to branch database-cleanup-feature in repository https://gitbox.apache.org/repos/asf/grails-core.git
commit 730122d25270500f8f316443a49bf9565cd1548a Author: Test <[email protected]> AuthorDate: Sat Feb 21 23:31:25 2026 -0500 Add detailed timing to debug stats --- .../cleanup/core/DatabaseCleanupInterceptor.groovy | 45 ++++++- .../cleanup/core/DatabaseCleanupStats.groovy | 75 ++++++++++++ .../core/DatabaseCleanupInterceptorSpec.groovy | 10 +- .../cleanup/core/DatabaseCleanupStatsSpec.groovy | 130 +++++++++++++++++++++ .../testing/cleanup/h2/H2DatabaseCleaner.groovy | 3 + .../postgresql/PostgresDatabaseCleaner.groovy | 6 +- 6 files changed, 261 insertions(+), 8 deletions(-) diff --git a/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptor.groovy b/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptor.groovy index e9616913e5..0b30d2ac8f 100644 --- a/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptor.groovy +++ b/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptor.groovy @@ -27,6 +27,8 @@ import org.spockframework.runtime.extension.IMethodInvocation import org.springframework.context.ApplicationContext +import java.text.SimpleDateFormat + /** * Spock method interceptor that performs database cleanup after tests annotated * with {@link DatabaseCleanup}. Supports both class-level and method-level annotations. @@ -70,16 +72,18 @@ class DatabaseCleanupInterceptor extends AbstractMethodInterceptor { ensureApplicationContext(invocation) log.debug('Performing database cleanup after test method: {}', invocation.feature?.name ?: 'unknown') + long startTime = System.currentTimeMillis() List<DatabaseCleanupStats> stats = context.performCleanup(mapping) - logStats(stats) + logStats(stats, startTime) } else if (isCurrentFeatureAnnotated(invocation)) { ensureApplicationContext(invocation) DatasourceCleanupMapping methodMapping = getMethodMapping(invocation) log.debug('Performing database cleanup after test method: {}', invocation.feature?.name ?: 'unknown') + long startTime = System.currentTimeMillis() List<DatabaseCleanupStats> stats = context.performCleanup(methodMapping) - logStats(stats) + logStats(stats, startTime) } } } @@ -93,8 +97,9 @@ class DatabaseCleanupInterceptor extends AbstractMethodInterceptor { if (classLevelCleanup) { ensureApplicationContext(invocation) log.debug('Performing database cleanup after spec: {}', invocation.spec?.name ?: 'unknown') + long startTime = System.currentTimeMillis() List<DatabaseCleanupStats> stats = context.performCleanup(mapping) - logStats(stats) + logStats(stats, startTime) } } } @@ -135,8 +140,28 @@ class DatabaseCleanupInterceptor extends AbstractMethodInterceptor { } } - private static void logStats(List<DatabaseCleanupStats> statsList) { + /** + * Logs cleanup statistics and overall timing information for the cleanup operation. + * + * @param statsList the list of cleanup statistics from individual datasources + * @param overallStartTime the overall start time of the cleanup operation + */ + private static void logStats(List<DatabaseCleanupStats> statsList, long overallStartTime) { if (DatabaseCleanupStats.debugEnabled) { + long overallEndTime = System.currentTimeMillis() + long overallDuration = overallEndTime - overallStartTime + + String separator = '==========================================================' + String startTimeFormatted = formatTime(overallStartTime) + String endTimeFormatted = formatTime(overallEndTime) + + System.out.println(separator) + System.out.println('Overall Cleanup Timing') + System.out.println("Start Time: ${startTimeFormatted}") + System.out.println("End Time: ${endTimeFormatted}") + System.out.println("Duration: ${overallDuration} ms") + System.out.println(separator) + for (DatabaseCleanupStats stats : statsList) { if (stats.tableRowCounts) { System.out.println(stats.toFormattedReport()) @@ -144,4 +169,16 @@ class DatabaseCleanupInterceptor extends AbstractMethodInterceptor { } } } + + /** + * Formats a timestamp in milliseconds as an ISO 8601 string. + * + * @param timeMillis the timestamp in milliseconds since epoch + * @return the formatted time string + */ + private static String formatTime(long timeMillis) { + SimpleDateFormat sdf = new SimpleDateFormat('yyyy-MM-dd\'T\'HH:mm:ss.SSS\'Z\'') + sdf.setTimeZone(TimeZone.getTimeZone('UTC')) + sdf.format(new Date(timeMillis)) + } } diff --git a/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStats.groovy b/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStats.groovy index e00f020f48..bcbb17f52b 100644 --- a/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStats.groovy +++ b/grails-testing-support-cleanup-core/src/main/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStats.groovy @@ -20,6 +20,7 @@ package org.apache.grails.testing.cleanup.core import groovy.transform.CompileStatic +import java.text.SimpleDateFormat /** * Captures statistics from a single datasource cleanup operation, including which @@ -29,6 +30,9 @@ import groovy.transform.CompileStatic * The {@link #tableRowCounts} map tracks per-table row counts using a default of {@code 0L} * for unknown keys, enabling convenient {@code +=} accumulation.</p> * + * <p>Individual cleanup timing can be tracked using the {@link #start()} and {@link #stop()} + * methods. These capture the start and end times for schema/datasource purging.</p> + * * <p>When debug output is enabled via the {@code grails.testing.cleanup.debug} system property, * the {@link #toFormattedReport()} method produces a human-readable summary suitable for * printing to the console.</p> @@ -54,6 +58,34 @@ class DatabaseCleanupStats { */ Map<String, Long> tableRowCounts = [:].withDefault { 0L } + /** + * The start time of the cleanup operation in milliseconds since epoch. + * Set by calling {@link #start()} before cleaning begins. + */ + long startTimeMillis = 0L + + /** + * The end time of the cleanup operation in milliseconds since epoch. + * Set by calling {@link #stop()} after cleaning completes. + */ + long endTimeMillis = 0L + + /** + * Starts the timer for individual schema/datasource cleanup. + * Records the current time as the start time. + */ + void start() { + this.startTimeMillis = System.currentTimeMillis() + } + + /** + * Stops the timer for individual schema/datasource cleanup. + * Records the current time as the end time. + */ + void stop() { + this.endTimeMillis = System.currentTimeMillis() + } + /** * Returns {@code true} if the {@code grails.testing.cleanup.debug} system property * is set to {@code "true"}. @@ -62,6 +94,20 @@ class DatabaseCleanupStats { Boolean.getBoolean(DEBUG_PROPERTY) } + /** + * Calculates the duration of the cleanup operation in milliseconds. + * + * @return the duration in milliseconds, or 0 if times were not set + */ + long getDurationMillis() { + if (startTimeMillis > 0L && endTimeMillis > 0L) { + endTimeMillis - startTimeMillis + } + else { + 0L + } + } + /** * Returns a human-readable formatted report of the cleanup statistics. * @@ -69,6 +115,9 @@ class DatabaseCleanupStats { * <pre> * ========================================================== * Database Cleanup Stats (datasource: dataSource) + * Start Time: 2024-02-21T12:34:56.789Z + * End Time: 2024-02-21T12:34:57.123Z + * Duration: 334 ms * ========================================================== * Table Name | Row Count * ---------------------------------------------------------- @@ -91,6 +140,20 @@ class DatabaseCleanupStats { else { sb.append('Database Cleanup Stats').append('\n') } + + // Add timing information if available + if (startTimeMillis > 0L || endTimeMillis > 0L) { + if (startTimeMillis > 0L) { + sb.append("Start Time: ${formatTime(startTimeMillis)}").append('\n') + } + if (endTimeMillis > 0L) { + sb.append("End Time: ${formatTime(endTimeMillis)}").append('\n') + } + if (startTimeMillis > 0L && endTimeMillis > 0L) { + sb.append("Duration: ${durationMillis} ms").append('\n') + } + } + sb.append(separator).append('\n') if (tableRowCounts.isEmpty()) { @@ -107,4 +170,16 @@ class DatabaseCleanupStats { sb.append(separator).append('\n') sb.toString() } + + /** + * Formats a timestamp in milliseconds as an ISO 8601 string. + * + * @param timeMillis the timestamp in milliseconds since epoch + * @return the formatted time string + */ + private static String formatTime(long timeMillis) { + SimpleDateFormat sdf = new SimpleDateFormat('yyyy-MM-dd\'T\'HH:mm:ss.SSS\'Z\'') + sdf.setTimeZone(TimeZone.getTimeZone('UTC')) + sdf.format(new Date(timeMillis)) + } } diff --git a/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptorSpec.groovy b/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptorSpec.groovy index 6341e81c17..aec065d7e1 100644 --- a/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptorSpec.groovy +++ b/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupInterceptorSpec.groovy @@ -346,7 +346,7 @@ class DatabaseCleanupInterceptorSpec extends Specification { ex.message.contains('Could not resolve ApplicationContext') } - def "interceptCleanupMethod prints formatted stats when debug property is set"() { + def "interceptCleanupMethod prints formatted stats when debug property is set"() { given: System.setProperty(DatabaseCleanupStats.DEBUG_PROPERTY, 'true') @@ -387,8 +387,14 @@ class DatabaseCleanupInterceptorSpec extends Specification { 1 * invocation.proceed() 1 * cleaner.cleanup(appCtx, dataSource) >> stats - and: + and: 'overall timing information is printed' String output = baos.toString() + output.contains('Overall Cleanup Timing') + output.contains('Start Time:') + output.contains('End Time:') + output.contains('Duration:') + + and: 'individual datasource stats are printed' output.contains('Database Cleanup Stats (datasource: dataSource)') output.contains('BOOK') output.contains('AUTHOR') diff --git a/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStatsSpec.groovy b/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStatsSpec.groovy index fbe85496c9..58da954a4b 100644 --- a/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStatsSpec.groovy +++ b/grails-testing-support-cleanup-core/src/test/groovy/org/apache/grails/testing/cleanup/core/DatabaseCleanupStatsSpec.groovy @@ -169,4 +169,134 @@ class DatabaseCleanupStatsSpec extends Specification { lines[0] == '==========================================================' lines.last() == '==========================================================' } + + def "startTimeMillis defaults to 0L"() { + when: + def stats = new DatabaseCleanupStats() + + then: + stats.startTimeMillis == 0L + } + + def "endTimeMillis defaults to 0L"() { + when: + def stats = new DatabaseCleanupStats() + + then: + stats.endTimeMillis == 0L + } + + def "start() records current time"() { + given: + def stats = new DatabaseCleanupStats() + def beforeStart = System.currentTimeMillis() + + when: + stats.start() + def afterStart = System.currentTimeMillis() + + then: + stats.startTimeMillis >= beforeStart + stats.startTimeMillis <= afterStart + } + + def "stop() records current time"() { + given: + def stats = new DatabaseCleanupStats() + def beforeStop = System.currentTimeMillis() + + when: + stats.stop() + def afterStop = System.currentTimeMillis() + + then: + stats.endTimeMillis >= beforeStop + stats.endTimeMillis <= afterStop + } + + def "durationMillis returns 0 when times are not set"() { + when: + def stats = new DatabaseCleanupStats() + + then: + stats.durationMillis == 0L + } + + def "durationMillis calculates difference when both times are set"() { + given: + def stats = new DatabaseCleanupStats() + stats.startTimeMillis = 1000L + stats.endTimeMillis = 1500L + + when: + long duration = stats.durationMillis + + then: + duration == 500L + } + + def "toFormattedReport includes timing information when times are set"() { + given: + def stats = new DatabaseCleanupStats() + stats.datasourceName = 'dataSource' + stats.tableRowCounts['BOOK'] += 1L + stats.startTimeMillis = 1708516496789L // Some timestamp + stats.endTimeMillis = 1708516496999L // 210ms later + + when: + String report = stats.toFormattedReport() + + then: + report.contains('Start Time:') + report.contains('End Time:') + report.contains('Duration:') + report.contains('210 ms') // Duration should be 210ms + } + + def "toFormattedReport omits timing when times are not set"() { + given: + def stats = new DatabaseCleanupStats() + stats.datasourceName = 'dataSource' + stats.tableRowCounts['BOOK'] += 1L + + when: + String report = stats.toFormattedReport() + + then: + !report.contains('Start Time:') + !report.contains('End Time:') + !report.contains('Duration:') + } + + def "toFormattedReport includes only start time if only startTimeMillis is set"() { + given: + def stats = new DatabaseCleanupStats() + stats.datasourceName = 'dataSource' + stats.startTimeMillis = 1708516496789L + stats.endTimeMillis = 0L + + when: + String report = stats.toFormattedReport() + + then: + report.contains('Start Time:') + !report.contains('End Time:') + !report.contains('Duration:') + } + + def "toFormattedReport includes only end time if only endTimeMillis is set"() { + given: + def stats = new DatabaseCleanupStats() + stats.datasourceName = 'dataSource' + stats.startTimeMillis = 0L + stats.endTimeMillis = 1708516496999L + + when: + String report = stats.toFormattedReport() + + then: + !report.contains('Start Time:') + report.contains('End Time:') + !report.contains('Duration:') + } } diff --git a/grails-testing-support-cleanup-h2/src/main/groovy/org/apache/grails/testing/cleanup/h2/H2DatabaseCleaner.groovy b/grails-testing-support-cleanup-h2/src/main/groovy/org/apache/grails/testing/cleanup/h2/H2DatabaseCleaner.groovy index a9c74ac820..a23a1cb80f 100644 --- a/grails-testing-support-cleanup-h2/src/main/groovy/org/apache/grails/testing/cleanup/h2/H2DatabaseCleaner.groovy +++ b/grails-testing-support-cleanup-h2/src/main/groovy/org/apache/grails/testing/cleanup/h2/H2DatabaseCleaner.groovy @@ -84,10 +84,12 @@ class H2DatabaseCleaner implements DatabaseCleaner { @Override DatabaseCleanupStats cleanup(ApplicationContext applicationContext, DataSource dataSource) { DatabaseCleanupStats stats = new DatabaseCleanupStats() + stats.start() String schemaName = H2DatabaseCleanupHelper.resolveSchemaName(dataSource) if (!schemaName) { log.warn('Could not resolve schema name for datasource, skipping cleanup') + stats.stop() return stats } @@ -112,6 +114,7 @@ class H2DatabaseCleaner implements DatabaseCleaner { catch (e) { log.error('Error cleaning up after cleaning up database', e) } + stats.stop() } stats diff --git a/grails-testing-support-cleanup-postgresql/src/main/groovy/org/apache/grails/testing/cleanup/postgresql/PostgresDatabaseCleaner.groovy b/grails-testing-support-cleanup-postgresql/src/main/groovy/org/apache/grails/testing/cleanup/postgresql/PostgresDatabaseCleaner.groovy index 51d456223e..88ed9a0ca7 100644 --- a/grails-testing-support-cleanup-postgresql/src/main/groovy/org/apache/grails/testing/cleanup/postgresql/PostgresDatabaseCleaner.groovy +++ b/grails-testing-support-cleanup-postgresql/src/main/groovy/org/apache/grails/testing/cleanup/postgresql/PostgresDatabaseCleaner.groovy @@ -93,15 +93,16 @@ class PostgresDatabaseCleaner implements DatabaseCleaner { @Override DatabaseCleanupStats cleanup(ApplicationContext applicationContext, DataSource dataSource) { DatabaseCleanupStats stats = new DatabaseCleanupStats() + stats.start() Sql sql = null try { sql = new Sql(dataSource) - + // Disable all triggers and referential integrity checks for this session // This is more efficient than using CASCADE on each truncate sql.execute('SET session_replication_role = replica') - + String currentSchema = PostgresDatabaseCleanupHelper.resolveCurrentSchema(dataSource) if (currentSchema) { @@ -129,6 +130,7 @@ class PostgresDatabaseCleaner implements DatabaseCleaner { log.error('Error closing SQL connection after cleanup', e) } } + stats.stop() } stats
