AuditLog: Check performance of updates and deletes

auditlog/src/test/java/org/genesys/blocks/auditlog/model/ExampleAuditedEntity.java

@@ -45,11 +45,11 @@ public class ExampleAuditedEntity extends BasicModel {
 
 	private static final long serialVersionUID = 1L;
 
-	@Column(length = 10)
+	@Column(length = 50)
 	private String name;
 
 	@NotAudited
-	@Column(length = 20)
+	@Column(length = 200)
 	private String title;
 
 	@HideAuditValue

auditlog/src/test/java/org/genesys/blocks/auditlog/service/AuditTrailServiceTest.java

@@ -17,10 +17,16 @@ package org.genesys.blocks.auditlog.service;
 
 import static org.hamcrest.MatcherAssert.*;
 import static org.hamcrest.Matchers.*;
+import static org.junit.Assert.assertThrows;
 
+import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
+import java.util.stream.Collectors;
 
+import org.apache.commons.lang3.RandomUtils;
+import org.apache.commons.lang3.time.StopWatch;
 import org.genesys.blocks.auditlog.model.AuditAction;
 import org.genesys.blocks.auditlog.model.AuditLog;
 import org.genesys.blocks.auditlog.model.ExampleAuditedEntity;
@@ -146,6 +152,7 @@ public class AuditTrailServiceTest extends ServiceTest {
 
 		entity = exampleAuditedEntityService.delete(entity);
 		assertThat(entity.getName(), is("Test 3"));
+		printAuditLogs(entity);
 		AuditLog lastLog = lastAuditLog(entity);
 		assertThat(lastLog.getAction(), is(AuditAction.DELETE));
 		assertThat(lastLog.getPropertyName(), is("name"));
@@ -165,16 +172,17 @@ public class AuditTrailServiceTest extends ServiceTest {
 		entity = exampleAuditedEntityService.save(entity);
 		assertThat(listAuditLogs(entity), hasSize(1));
 
-		try {
-			entity.setName("Test 1. This is too long and should fail.");
-			entity = exampleAuditedEntityService.save(entity);
-		} catch (DataIntegrityViolationException e) {
-			// Name is too long
-			assertThat(listAuditLogs(entity), hasSize(1));
-		} finally {
-			exampleAuditedEntityRepository.delete(entity);
-			assertThat(listAuditLogs(entity), hasSize(2));
-		}
+		var toFail = entity;
+		assertThrows(DataIntegrityViolationException.class, () -> {
+			toFail.setName("Test 1. This is too long and should fail.This is too long and should fail. This is too long and should fail.");
+			exampleAuditedEntityService.save(toFail);
+		});
+		// Name is too long
+		assertThat(listAuditLogs(entity), hasSize(1));
+
+		exampleAuditedEntityRepository.delete(entity);
+		printAuditLogs(entity);
+		assertThat(listAuditLogs(entity), hasSize(2));
 	}
 
 	/**
@@ -228,6 +236,7 @@ public class AuditTrailServiceTest extends ServiceTest {
 
 		entity.setPassword("pass2");
 		entity = exampleAuditedEntityService.save(entity);
+		printAuditLogs(entity);
 		AuditLog lastLog = lastAuditLog(entity);
 		assertThat(lastLog, not(nullValue()));
 		assertThat(lastLog.getAction(), is(AuditAction.UPDATE));
@@ -312,7 +321,7 @@ public class AuditTrailServiceTest extends ServiceTest {
 		entity.getSet().clear();
 		entity.getSet().add("c++");
 		entity = exampleAuditedEntityService.save(entity);
-		// printAuditLogs(entity);
+		printAuditLogs(entity);
 		assertThat(listAuditLogs(entity), hasSize(3));
 		lastLog = lastAuditLog(entity);
 		assertThat(lastLog.getAction(), is(AuditAction.UPDATE));
@@ -356,6 +365,7 @@ public class AuditTrailServiceTest extends ServiceTest {
 		entity.getOthers().add(other2);
 		entity.getOthers().add(other1);
 		entity = exampleAuditedEntityService.save(entity);
+		printAuditLogs(entity);
 		assertThat(listAuditLogs(entity), hasSize(2));
 		assertThat(listAuditLogs(entity).get(0).getNewState(), is(Arrays.toString(new Long[] { other1.getId(), other2.getId() })));
 
@@ -369,11 +379,112 @@ public class AuditTrailServiceTest extends ServiceTest {
 		entity.getOthers().clear();
 		entity.getOthers().add(other2);
 		entity = exampleAuditedEntityService.save(entity);
-//		printAuditLogs(entity);
-//		System.out.println("\n\n\n");
+		// printAuditLogs(entity);
+		// System.out.println("\n\n\n");
 		assertThat(listAuditLogs(entity), hasSize(3));
 		assertThat(listAuditLogs(entity).get(0).getNewState(), is(Arrays.toString(new Long[] { other2.getId() })));
 
 	}
 
+	@Test
+	public void testAuditTrailInterceptorPerformance() {
+		var stopWatch = StopWatch.create();
+
+		stopWatch.reset();
+		stopWatch.start();
+		List<ExampleAuditedEntity> entities = new ArrayList<ExampleAuditedEntity>(1000);
+		for (int i = 0; i < 1000; i++) {
+			ExampleAuditedEntity entity = new ExampleAuditedEntity();
+			entity.setName("Loop A " + i);
+			entity.setPassword("this-is-not-a");
+			entities.add(exampleAuditedEntityService.save(entity));
+		}
+		stopWatch.stop();
+		LOG.warn("Adding 1000 1by1 took {}ms", stopWatch.getTime(TimeUnit.MILLISECONDS));
+
+		var toSave = new ArrayList<ExampleAuditedEntity>(1000);
+		for (int i = 0; i < 1000; i++) {
+			ExampleAuditedEntity entity = new ExampleAuditedEntity();
+			entity.setName("Loop B " + i);
+			entity.setPassword("this-is-not-a");
+			toSave.add(entity);
+		}
+		stopWatch.reset();
+		stopWatch.start();
+		entities.addAll(exampleAuditedEntityService.save(toSave));
+		stopWatch.stop();
+		LOG.warn("Adding 1000 in a batch took {}ms", stopWatch.getTime(TimeUnit.MILLISECONDS));
+		assertThat(entities, hasSize(2000));
+		assertThat(auditLogRepository.count(), is(0L));
+
+		// Update 1000 1 by 1
+		entities = exampleAuditedEntityRepository.findAll();
+		stopWatch.reset();
+		stopWatch.start();
+		for (int i = 0; i < 1000; i++) {
+			var entity = entities.get(i);
+			entity.setName("Updated A " + i);
+			entity.setPassword("this-is-not-a-password");
+			entity = exampleAuditedEntityService.save(entity);
+		}
+		stopWatch.stop();
+		LOG.warn("Updating 1000 1by1 took {}ms", stopWatch.getTime(TimeUnit.MILLISECONDS));
+		assertThat(auditLogRepository.count(), is(2000L));
+		assertThat(exampleAuditedEntityRepository.count(), is(2000L));
+
+		// Update 100
+		entities = exampleAuditedEntityRepository.findAll();
+		toSave.clear();
+		for (int i = 1000; i < 1100; i++) {
+			var entity = entities.get(i);
+			entity.setName("Updated B " + i);
+			entity.setPassword("this-is-not-a-password");
+			toSave.add(entity);
+		}
+		stopWatch.reset();
+		stopWatch.start();
+		exampleAuditedEntityService.save(toSave);
+		stopWatch.stop();
+		LOG.warn("Updating 100 in a batch took {}ms", stopWatch.getTime(TimeUnit.MILLISECONDS));
+		assertThat(auditLogRepository.count(), is(2200L));
+		assertThat(exampleAuditedEntityRepository.count(), is(2000L));
+
+		// Update 1000
+		entities = exampleAuditedEntityRepository.findAll();
+		toSave.clear();
+		for (int i = 1000; i < 2000; i++) {
+			var entity = entities.get(i);
+			entity.setName("Updated C " + i);
+			entity.setPassword("this-is-not-a-password");
+			toSave.add(entity);
+		}
+		stopWatch.reset();
+		stopWatch.start();
+		exampleAuditedEntityService.save(toSave);
+		stopWatch.stop();
+		LOG.warn("Updating 1000 in a batch took {}ms", stopWatch.getTime(TimeUnit.MILLISECONDS));
+		assertThat(auditLogRepository.count(), is(4100L));
+		assertThat(exampleAuditedEntityRepository.count(), is(2000L));
+
+		// Delete 1000
+		entities = exampleAuditedEntityRepository.findAll().stream().filter((entity) -> RandomUtils.nextBoolean()).collect(Collectors.toList());
+		stopWatch.reset();
+		stopWatch.start();
+		exampleAuditedEntityService.delete(entities);
+		stopWatch.stop();
+		LOG.warn("Deleting {} in a batch took {}ms", entities.size(), stopWatch.getTime(TimeUnit.MILLISECONDS));
+		assertThat(auditLogRepository.count(), is(4100L + 2 * entities.size()));
+		assertThat(exampleAuditedEntityRepository.count(), is(2000L - entities.size()));
+
+		entities = exampleAuditedEntityRepository.findAll();
+		stopWatch.reset();
+		stopWatch.start();
+		for (var entity : entities) {
+			exampleAuditedEntityService.delete(entity);
+		}
+		stopWatch.stop();
+		LOG.warn("Deleting {} 1by1 took {}ms", entities.size(), stopWatch.getTime(TimeUnit.MILLISECONDS));
+		assertThat(auditLogRepository.count(), is(8100L));
+		assertThat(exampleAuditedEntityRepository.count(), is(0L));
+	}
 }

auditlog/src/test/java/org/genesys/blocks/auditlog/service/ExampleAuditedEntityService.java

 /*
- * Copyright 2018 Global Crop Diversity Trust
+ * Copyright 2021 Global Crop Diversity Trust
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
  * you may not use this file except in compliance with the License.
@@ -16,6 +16,8 @@
 
 package org.genesys.blocks.auditlog.service;
 
+import java.util.Collection;
+
 import org.genesys.blocks.auditlog.model.ExampleAuditedEntity;
 
 /**
@@ -53,4 +55,19 @@ public interface ExampleAuditedEntityService {
 	 * @return the example audited entity
 	 */
 	ExampleAuditedEntity testList();
+
+	/**
+	 * Save many
+	 *
+	 * @param toSave the to save
+	 * @return the collection<? extends example audited entity>
+	 */
+	Collection<? extends ExampleAuditedEntity> save(Collection<ExampleAuditedEntity> toSave);
+
+	/**
+	 * Delete the entities.
+	 *
+	 * @param toDelete the to delete
+	 */
+	void delete(Collection<? extends ExampleAuditedEntity> toDelete);
 }

auditlog/src/test/java/org/genesys/blocks/auditlog/service/impl/ExampleAuditedEntityServiceImpl.java

@@ -16,6 +16,8 @@
 
 package org.genesys.blocks.auditlog.service.impl;
 
+import java.util.Collection;
+
 import org.genesys.blocks.auditlog.model.ExampleAuditedEntity;
 import org.genesys.blocks.auditlog.persistence.ExampleAuditedEntityRepository;
 import org.genesys.blocks.auditlog.service.ExampleAuditedEntityService;
@@ -39,6 +41,12 @@ public class ExampleAuditedEntityServiceImpl implements ExampleAuditedEntityServ
 		return exampleAuditedEntityRepository.save(entity);
 	}
 	
+	@Override
+	@Transactional
+	public Collection<? extends ExampleAuditedEntity> save(Collection<ExampleAuditedEntity> toSave) {
+		return exampleAuditedEntityRepository.saveAll(toSave);
+	}
+
 	@Override
 	@Transactional
 	public ExampleAuditedEntity delete(ExampleAuditedEntity entity) {
@@ -46,6 +54,12 @@ public class ExampleAuditedEntityServiceImpl implements ExampleAuditedEntityServ
 		return entity;
 	}
 
+	@Override
+	@Transactional
+	public void delete(Collection<? extends ExampleAuditedEntity> toDelete) {
+		exampleAuditedEntityRepository.deleteAll(toDelete);
+	}
+
 	@Override
 	@Transactional
 	public ExampleAuditedEntity testList() {

auditlog/src/test/resources/log4j.properties

@@ -27,6 +27,7 @@ log4j.rootLogger=error, stdout
 
 #log4j.category.org.genesys.blocks=debug
 #log4j.category.org.genesys.blocks.auditlog=trace
+log4j.category.org.genesys.blocks.auditlog.service.AuditTrailServiceTest=info
 
 ## Shut up hsql
 log4j.category.org.hibernate.tool.hbm2ddl.SchemaExport=fatal