Raportowanie czasów - ten sam czas na różnych etapach

Mam 2 timery:

• timerIn (do raportowania czasu przed startem metody accept())
• timerOut (do raportowania czasu po wykonaniu mnetody accept())

@Aspect
@Component
public class SummaryMsgHandlerMetrics {

    public static final String TIMER_IN_NAME = "cstream_sse_provider_summary_in";
    public static final String TIMER_OUT_NAME = "cstream_sse_provider_summary_out";

    private final MeterRegistry meterRegistry;
    private final Clock clock;
    private final Timer timerIn;
    private final Timer timerOut;

    private static final double[] PERCENTILES = new double[]{.5, .95, .99};

    @Autowired
    public SummaryMsgHandlerMetrics(MeterRegistry meterRegistry, Clock clock) {
        this.meterRegistry = meterRegistry;
        this.clock = clock;
        this.timerIn = Timer.builder(TIMER_IN_NAME)
                .publishPercentiles(PERCENTILES)
                .register(meterRegistry);
        this.timerOut = Timer.builder(TIMER_OUT_NAME)
                .publishPercentiles(PERCENTILES)
                .register(meterRegistry);
    }

    @Around("execution(* *.SummaryMsgHandler.accept(..))")
    public void measureTimeAroundAccept(ProceedingJoinPoint joinPoint) throws Throwable {
        long before = clock.millis();

        var summaryTrade = (SummaryTrade) joinPoint.getArgs()[0];

        joinPoint.proceed();

        timerIn.record(before - summaryTrade.getBirthTimestamp(), TimeUnit.MILLISECONDS);
        timerOut.record(clock.millis() - summaryTrade.getBirthTimestamp(), TimeUnit.MILLISECONDS);
    }
}

Wynik tych timerów jest taki, że mają identyczne czasy co do 1 ms.

Zwróćcie uwagę na 2 ostatnie linie.
Dodałem 100 sekund opóźnienia między raportowaniem timerIn i timerOut:

        timerIn.record(before - summaryTrade.getBirthTimestamp(), TimeUnit.MILLISECONDS);
        TimeUnit.SECONDS.sleep(100);
        timerOut.record(clock.millis() - summaryTrade.getBirthTimestamp(), TimeUnit.MILLISECONDS);

czasy podskoczyły, ale są dalej identyczne!

Jvm coś optymalizuje i odpala clock.millis() tylko raz?

Sprawdź jeszcze raz czy nie zrobiłeś złego zapytania sprawdzając metryki. Wszystko wygląda OK na pierwszy rzut oka.

Tutaj przykład ze źródeł https://github.com/micrometer-metrics/micrometer/blob/0981381dc5d311d117af96bc98b5a1cd1379e2eb/micrometer-core/src/main/java/io/micrometer/core/instrument/internal/TimedRunnable.java#L42

Możesz wysłać wartości na "sztywno" tak żeby sprawdzić czy metryki się poprawnie odsyłają:

 timerIn.record(100, TimeUnit.MILLISECONDS);
timerOut.record(666, TimeUnit.MILLISECONDS);

A ile instancji SummaryMsgHandlerMetrics działa na twoim kodzie?

jarekr000000 napisał(a):

A ile instancji SummaryMsgHandlerMetrics działa na twoim kodzie?

1 instancja

0xmarcin napisał(a):

Sprawdź jeszcze raz czy nie zrobiłeś złego zapytania sprawdzając metryki. Wszystko wygląda OK na pierwszy rzut oka.

tak, poprawnie je czytam pa:

# HELP cstream_sse_provider_mean_out_seconds  
# TYPE cstream_sse_provider_mean_out_seconds summary
cstream_sse_provider_mean_out_seconds{quantile="0.5",} 22.414360576
cstream_sse_provider_mean_out_seconds{quantile="0.95",} 38.520487936
cstream_sse_provider_mean_out_seconds{quantile="0.99",} 38.520487936
cstream_sse_provider_mean_out_seconds_count 969.0
cstream_sse_provider_mean_out_seconds_sum 17779.999
# HELP cstream_sse_provider_mean_out_seconds_max  
# TYPE cstream_sse_provider_mean_out_seconds_max gauge
cstream_sse_provider_mean_out_seconds_max 37.631

# HELP cstream_sse_provider_mean_in_seconds  
# TYPE cstream_sse_provider_mean_in_seconds summary
cstream_sse_provider_mean_in_seconds{quantile="0.5",} 22.414360576
cstream_sse_provider_mean_in_seconds{quantile="0.95",} 38.520487936
cstream_sse_provider_mean_in_seconds{quantile="0.99",} 38.520487936
cstream_sse_provider_mean_in_seconds_count 969.0
cstream_sse_provider_mean_in_seconds_sum 17779.747
# HELP cstream_sse_provider_mean_in_seconds_max  
# TYPE cstream_sse_provider_mean_in_seconds_max gauge
cstream_sse_provider_mean_in_seconds_max 37.63

Możesz wysłać wartości na "sztywno" tak żeby sprawdzić czy metryki się poprawnie odsyłają:

 timerIn.record(100, TimeUnit.MILLISECONDS);
timerOut.record(666, TimeUnit.MILLISECONDS);

Wtedy jest poprawnie.

A patrzcie na to:

    @Around("execution(* *.SummaryMsgHandler.accept(..))")
    public void measureTimeAroundAccept(ProceedingJoinPoint joinPoint) throws Throwable {
        var timerTmp = Timer.builder("tmp").publishPercentiles(PERCENTILES).register(meterRegistry);
        timerTmp.measure();

        joinPoint.proceed();
        TimeUnit.SECONDS.sleep(1);

        timerTmp.close();
    }

wynik:

# HELP tmp_seconds  
# TYPE tmp_seconds summary
tmp_seconds{quantile="0.5",} 0.0
tmp_seconds{quantile="0.95",} 0.0
tmp_seconds{quantile="0.99",} 0.0
tmp_seconds_count 0.0
tmp_seconds_sum 0.0
# HELP tmp_seconds_max  
# TYPE tmp_seconds_max gauge
tmp_seconds_max 0.0

OK jaki jest czas życia SummaryMsgHandlerMetrics? Być może timer rejestruje się per wywołanie. Osobiście zrobiłbym je statyczne.

hm, nie wiem jak statystyczne zrobić, bo on potrzebuje MeterRegistry, który jest beanem.
Z tego co sobie loguję to ta klasa tworzy się tylko raz i sobie żyje. Czy timer się resetuje? hm... w innym serwisie mam dokładnie tak samo i działa z tą różnicą, że rejestruję tylko 1 timer, a tu 2.

No to ciężko powiedzieć to tu jest nie halo, poza tym że proceed wykonuje się < 1milisekundy. Być może ten Clock co tam dostajesz jest zjbny typu Clock.fixed(instant, zoneId);...

No to ciężko powiedzieć to tu jest nie halo, poza tym że proceed wykonuje się < 1milisekundy.

Wtedy sleep by coś zmienił, a nic nie zmienia.

Zrobiłem jeszcze logowanie tego co tam wkłada to timerów, to loguje ok, różne czasy loguje tylko jakby te 2 osobne timery łączyły się w jedno. Jakby ten timerOut nadpisywał timerIn. Tylko, że jak zapodam mu z palca jakas wartość to jest dobrze.
Clock clock = Clock.systemDefaultZone()

@straznik-tagu:

1. Co to za klasa Timer?
2. Spróbuj dodać volatile przy deklaracji zmiennej recordsIn. Wtedy będziesz miał gwarancję, że JVM sobie nie poprzestawia tego.
3. Dodatkowo możesz jeszcze spojrzeć na bytecode

wartek01 napisał(a):

@straznik-tagu:

1. Co to za klasa Timer?

import io.micrometer.core.instrument.Timer;

Osobie, która rozwiąże ten problem milinijny do końca tygodnia (znajdzie przyczynę tak bym dał radę to naprawić) dostanie ode mnie darowiznę w postaci 0,1 monero.

ROZWIĄZANIE:

to nie jest błąd

do handlera trafia naraz po kilkadziesiąt wiadomości, a handler działa jednowątkowo. Z tego powodu zanim rozpocznie się kolejne handlowanie wiadomości, trzeba poczekać aż się zakończy poprzednie.
Zaraz po zakończeniu rozpoczyna się nowe, stąd czas startuN+1 ~= czas stopN

np.

--- 1 wiadomosc ---
start: 0 ms
stop: 50 ms
--- 2 wiadomosc ---
start: 50 ms
stop: 100 ms
--- 3 wiadomosc ---
start: 100 ms
stop: 150 ms
--- N wiadomosc ---
start: N * 50 - 50 ms
stop: N * 50

co daje:
start: {0, 50, 100, 150, ... N * 50 - 50 - 50, N * 50 - 50}
stop: {    50, 100, 150, ...,                           N * 50 - 50, N * 50}

dlatego percentyle i srednie są takie same dla start i stop