Medición de tiempo de ejecución con StopWatch

StopWatch es un simple cronómetro que permite medir el tiempo de las tareas. Expone el tiempo total de ejecución y el tiempo de ejecución de cada tarea nombrada.

Documentación Oficial – StopWatch

A continuación, se exponen una serie de formas de utilizarlo con Spring-Boot:

Medición tests configurando el StopWatch en las fases ( @AferAll, … )

@SpringBootTest
class StopwatchApplicationTests {

	static StopWatch stopWatch = new StopWatch();
	
	@BeforeAll
	static void setUp() {
		stopWatch =  new StopWatch();
	}
	
	@BeforeEach
	void timeSetUp(TestInfo testInfo) {
		stopWatch.start( testInfo.getTestMethod().get().getName());
	}
	
	@AfterAll
	static void setDown() {
		System.out.print( stopWatch.prettyPrint() );
	}
	
	@AfterEach
	void timeSetDown() {
		stopWatch.stop();
	}

	@Test
	void test_one() throws InterruptedException {
		Thread.sleep(2000);
	}
	...
}

Resultado obtenido

StopWatch '': running time = 6011364520 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
2008182259  033 %  test_one
2001327545  033 %  test_two
2001854716  033 %  test_three

Medición de los test utilizando un TestExecutionListener
Es necesario crear un listener que extienda de AbstractTestExecutionListener, el cuál nos permitirá sobreescribir los métodos beforeTestClass, afterTestClass, afterTestMethod,…

public class ExecutionTimeTestListener extends AbstractTestExecutionListener {
    private StopWatch stopWatch;

    @Override
    public void beforeTestClass(TestContext testContext) throws Exception {
        super.beforeTestClass(testContext);
        stopWatch = new StopWatch(testContext.getTestClass().getSimpleName());
    }

    @Override
    public void beforeTestMethod(TestContext testContext) throws Exception {
        super.beforeTestMethod(testContext);
        stopWatch.start(testContext.getTestMethod().getName());
    }

    @Override
    public void afterTestMethod(TestContext testContext) throws Exception {
        if (stopWatch.isRunning()) {
            stopWatch.stop();
        }
        super.afterTestMethod(testContext);
    }

    @Override
    public void afterTestClass(TestContext testContext) throws Exception {
        System.out.println(stopWatch.prettyPrint());
        super.afterTestClass(testContext);
    }
}

Forma de utilización:

@ExtendWith(SpringExtension.class)
@TestExecutionListeners({DependencyInjectionTestExecutionListener.class, 
	ExecutionTimeTestListener.class})
class StopwatchWithListenerApplicationTest {
	@Test
	void test_one() throws InterruptedException {
		Thread.sleep(2000);
	}
	...
}

Resultado obtenido

StopWatch 'StopwatchWithListenerApplicationTest': running time = 6017421650 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
2013933526  033 %  test_one
2001191940  033 %  test_two
2002296184  033 %  test_three

Configuración utilizando Aspectj
Se crea un aspecto para que capture todas las ejecuciones del paquete service. Ademas se le pone el @Around para que envuelva el método que captura. Así podemos poner el StopWatch para que medir el tiempo que tarda en ejecutarlo.

Requiere añadir la dependencia spring-boot-starter-aop.

	    
	        org.springframework.boot
	        spring-boot-starter-aop
	    

@Aspect
@Component  
public class StopWatchAOP {
	
    @Around("execution(* es.com.disastercode.examplesspringboot.stopwatch.service.*.*(..))")
    public Object measureMethod(ProceedingJoinPoint pjp) throws Throwable
    {
        StopWatch sw = new StopWatch();
        Object retVal;
        try {
            sw.start(pjp.getTarget()+"."+pjp.getSignature());
            retVal = pjp.proceed();
        } catch (Throwable e) {
            throw e;
        } finally {
            sw.stop();
            System.out.println(sw.prettyPrint());
        }
        return retVal;
    }
}

Ejemplo de test.

@SpringBootTest
class StopwatchWithAopApplicationTests {
	@Autowired
	private ProductService productService;
	@Test
	void test_one() throws InterruptedException {
		assertEquals("name 2", this.productService.findNameProductById(2));
	}
}

Resultado obtenido

StopWatch '': running time = 2050920963 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
2050920963  100 %  es.com.disastercode.examplesspringboot.stopwatch.service.ProductServiceImpl@3d20e575.String es.com.disastercode.examplesspringboot.stopwatch.service.ProductServiceImpl.findNameProductById(Integer)

Github con los ejemplos.