@ExpectMaxQueryExecutionTime alert message always displays "0 ms" as max about quickperf HOT 8 CLOSED

Hello Fabrice,

Thanks a lot for this report.

Indeed, there is an issue in the error report when the threshold is expressed with TimeUnit.MICROSECONDS or TimeUnit.NANOSECONDS.

In SqlQueryMaxExecutionTimeVerifier class:

    @Override
	public PerfIssue verifyPerfIssue(ExpectMaxQueryExecutionTime annotation, ExecutionTime measure) {
		
		ExecutionTime maxExpectedSqlExecutionTime = new ExecutionTime(annotation.value(), annotation.unit());
		
		if(measure.isGreaterThan(maxExpectedSqlExecutionTime)) {

			String message = "At least one request exceeds the max expected query execution time <" + maxExpectedSqlExecutionTime + ">.";
			

If we look at the toString() implementation of ExecutionTime:

	@Override
	public String toString() {
		return this.unit.toMillis(value) + " ms";
	}

If unit value is TimeUnit.MICROSECONDS or TimeUnit.NANOSECONDS then unit.toMillis(value) value can be zero.

QuickPerf uses ttddyy to intercept the SQL queries. In ttddy, the execution time is given in milliseconds.

In QuickPerf, I think that a threshold less than to the millisecond does not make sense.

I would prefer to have an API like this:

public @interface ExpectMaxQueryExecutionTime {

	int thresholdInMilliSeconds();
	

I will be glad to have your opinion.

You are very welcome if you would like to work on developing this new API.

I would also like to remove value and unit annotation elements. QuickPerf is in release candidate version (hoping not for a long time), so it's still the moment to do it.

Kind regards,

Jean

from quickperf.

Hi Jean,

Thanks again for the clarifications (especially on ttddyy).

Your idea of removing the time unit from the interface is appealing (always having an int value representing milliseconds). I can make a draft to see where this will lead me, I'm sure I will ask you more questions later :).

I will give you an update soon.

Kind regards,
Fabrice

from quickperf.

Hi Jean,

Sorry for the delay, I made a draft starting from your idea (don't consider the two previous commits, I forgot Git reports everything even when cautiously working on a separate branch).
The "good" commit is here.

Notice I tweaked the alert message from SqlQueryMaxExecutionTimeVerifier.
When testing and setting the annotation on several tests I was confused as I had no idea of the query execution time that happened effectively (plus the effective execution time can vary from time to time). I played for a time with the @MeasureExecutionTime annotation until I realised it wasn't relevant.

So, even though the [SQL Executions] message displays the execution time for each query, I modified the alert to display both reality and expectation as following :

[PERF] At least one request exceeds the max expected query execution time:
    Effective execution time <1 ms>
    Expected execution time <0 ms>

I'd be happy to have your feedback.

P.S. : there is still no test that tests the alert message itself (which is I feel the origin of the issue in a way), I simply updated the SqlQueryMaxExecutionTimeVerifier). Let me know if you want me to set a new test class.

Kind regards,
Fabrice

from quickperf.

Hi Fabrice,

Many thanks for your work. Don't worry about the delay. You are welcome.

So, even though the [SQL Executions] message displays the execution time for each query, I modified the alert to display both reality and expectation as following

Good idea Fabrice.

"Effective" may seem ambiguous.

Perhaps, we could propose something looking like

[PERF] Query execution time expected to be less than  <1 ms>.  
       At least one query has a greater execution time. The greater query execution time is <2ms>.

With several queries, the user can find the query taking a long time by looking at the console:

[SQL EXECUTIONS]
	Time:1, Success:True, Type:Prepared, Batch:False, QuerySize:1, BatchSize:0, Query:["
    select
        book0_.id as id1_0_,
        book0_.isbn as isbn2_0_,
        book0_.title as title3_0_ 
    from
        Book book0_"], Params:[()]

Time:1 means that the query takes 1 ms. We could update the documentation.

P.S. : there is still no test that tests the alert message itself (which is I feel the origin of the issue in a way), I simply updated the SqlQueryMaxExecutionTimeVerifier). Let me know if you want me to set a new test class.

You are right. The message content is not automatically checked. I put a comment in your Github repo.

Thanks a lot for your relevant remarks Fabrice.

Kind regards,

Jean

from quickperf.

Hi Jean,

Happy to help ! Here is an updated commit based on your feedbacks. To sum up:

• added assertj assertions as discussed,
• refactored (presentation) to match existing BDD style of other tests,
• added assertion testing for the message itself.
  If ok I'll rebase and squash to do a proper PR on the master branch. I'll update the documentation and push to the doc repo in parallel.

UPDATE: here is the update on the wiki. There is also stuff to do on the quickperf examples (Quarkus example among others) but since they user the actual version of Quickperf which does not include the modifications of this issue I guess they are fine for now.

Kind regards,
Fabrice

from quickperf.

Hi Fabrice,

It's perfect!

I will update the wiki from your proposal just after the next release, together with quickperf examples.

Many thanks for your contributions Fabrice!

Kind regards,

Jean

from quickperf.

It's been a pleasure !

from quickperf.

Fixed with bbb561b

from quickperf.