Wolne pierwsze wywołanie endpointu po dłuższej przerwie

Obserwuję problem w mikroserwisach: jeśli dany endpoint nie jest używany przez dłuższy czas ( np.15-30 min), jego pierwsze wywołanie po takiej przerwie jest znacznie wolniejsze (np. 2-5s vs 50-150ms).

Mikroserwisy napisane są w Kotlinie, a obrazy dockerowe bazują na OpenJDK 21. Korzystam ze Spring Boota 3.2 (WebFlux), a z bazą PostgreSQL łączę się za pomocą Spring R2DBC.

Podobny problem zauważam również w mikroserwisach, które nie korzystają z bazy danych, a jedynie łączą się z zewnętrznymi API. Podejrzewam, że zapytanie musi otworzyć nowe połączenie z bazą (connection pool z max-idle-time: 30m), ale i tak nie powinno to trwać aż tak długo.

Czy ktoś ma pomysł, jak rozwiązać ten problem lub chociaż zminimalizować trochę ten czas (inny niż regularne wywoływanie tego endpointu)?

Co to znaczy, że podejrzewasz, że zapytanie musi utworzyć nowe połączenie z bazą? Debugowałeś to jakoś?

Damian Śniatecki napisał(a):

Obserwuję problem w mikroserwisach: jeśli dany endpoint nie jest używany przez dłuższy czas ( np.15-30 min), jego pierwsze wywołanie po takiej przerwie jest znacznie wolniejsze (np. 2-5s vs 50-150ms).

Tzn. gdzie ten problem występuje? Na localhoście czy na docelowym hostingu?

Masz metryki, to zobacz ile jest otwartych polaczen do bazy i tyle. Inaczej, to bedzie zgadywanka.

Mój błąd. Zapomniałem dodać, a prawdopodobnie to właśnie gdzieś po stronie chmury jest główny problem. Mikroserwisy uruchomione są jako cluster Kubernetesa w chmurze Googla (GKE - standard, nie autopilot), a bazka to Cloud SQL. Problem obserwuje szczególnie w godzinach, w których system jest rzadko używany i robię do niego request jakiś ( lub np. odpalam aplikację mobilną, która korzysta z wystawionego API i odczuwalny jest nieprzyjemny lag), chociaż są tam wewnątrz różne cron joby, który np. co 5 min łączą się z różnymi mikroserwisami.

Generalnie, nawet jeśli request po prostu odbije się od walidacji/security wystawionego API (co nie wymaga żadnych zapytań do bazki), to właśnie ten pierwszy request zajmuje po dłuższej przerwie zazywczyj około 5-6 sekund, więc możemy wykluczyć na razie problemy z ustanawianiem połączenia z bazką). Więc flow połączenia jest następujące: Google Cloud DNS > Ingress (Nginx) > nginx wystawiący API > serwis postawiony na JDK 21 > ...

Ja bym dodał logi z timestampami gdzie tylko się da, łącznie z ingress controllerem (o ile jesteś w stanie na GKE to zrobić, tu się nie orientuję).

Drugi krok to sidecar z tcpdump (albo natywny odpowiednik googlowy) to powinno być widać, czy np. po sieci gdzieś ci nie laguje.

Zrobiłem request do API, który zajął 6.41s.

Następnie rzuciłem okiem na logi Nginx-a wystawiającego to API: 16/Aug/2024:20:28:50 +0000 | 401 | 0.004 s -> czyli 0.4 ms

Potem sprawdziłem, że sam DNS lookup dla tego połączenia zajął 6.28s ( swoją drogą trochę długo, ciekawe czy da się to jakoś przyspieszyć ).

TTL dla tych rekordów w Cloud DNSie był ustawiony na 5m i stąd wynika ten problem...

Czasami człowiek się zapętli w myśleniu i szuka problemów tam gdzie ich nie ma. Dzięki za pomoc

Ale czemu tak długo, bo nie zrozumiałem chyba? Co ma do tego ustawienie ttl?

Robią te cloudy, kto to widział :D

Ja bym zrobił log.info("dupa"); i sprawdzał logi ;D

PaulGilbert napisał(a):

Ale czemu tak długo, bo nie zrozumiałem chyba? Co ma do tego ustawienie ttl?

Ma tyle, że przy dłuższym TTL (np. 24h) ten DNS lookup będzie musiał znacznie rzadziej być robiony.

A dlaczego aż tyle zajmował to dobre pytanie. Spróbuję bardziej zbadać temat.

Pobieżnie sprawdziłem wątek, ale sprawdzałes ile startuje aplikacja? Miałem kiedyś podobny problem na cloud run i okazało się, że start aplikacji po prostu powodował dlugi czas oczekiwania na pierwszy request.

Pewnie obrazy są usypiane po kilku minutach od ostatniego wywołania operacji na mikro serwisie i przy następnym musi się na nowo cały serwis uruchomić

Aplikacje uruchomione są jako kontenery i nie są wygaszane. Startują w około 30 sekund. Są healthchecki, metryki i wiele innych takich.

Zwiększenie TTLa na DNSie z 5m do 24h w dużym stopniu pomogło pozbyć się przynajmniej tego problemu, ale ciężej to teraz testować przez to. Nadal jest to dosyć dziwne, DNS lookup nie powinien tyle trwać, ale według różnych testów jest już niby ok obecnie.

Skupiając się już na samym systemie i komunikacji wewnątrz klastra to czasy odpowiedzi endpointów po dłuższej przerwie (15-30 minut) od ostatniego użycia są przy pierwszym wywołaniu znacząco wyższe ( ~400-600ms vs ~5-20ms przy kolejnych wywołaniach według wewnętrznych logów na proxy). Te zapytania zazwyczaj przechodzą przez dwa serwisy, pierwszy: Spring Boot Webflux + WebClient (connection pool), drugi: Spring Boot Webflux + R2DBC (connection pool) łączące się z PostgreSQL.

Tutaj już muszę zbadać gdzie najwięcej czasu jest tracone. Dodać jakieś dodatkowe logi itp. Jest dużo elementów, które mogą być potencjalnym winowajcą.

Zależy mi na tym by system odpowiadał możliwie szybko nawet gdy od paru godzin dana jego część nie jest używana

Może zapytania do bazy są jakieś skomplikowane i potem są ewentualnie wykorzystywane wcześniejsze dane które są gdzieś cache-owane?

Obstawiałbyś że to gdzieś po stronie apki problem czy coś ta googlowska chmura niedomaga?

Osobiście obstawiam, że to coś związanego z charakterystyką Spring Boota (Webflux & Netty w moim przypadku).

To, że pierwsze wywołania endpointu po starcie serwisu są wolniejsze, w przypadku Javy i tego frameworka jest oczywiste, ale że kolejne po przerwie, to już nie bardzo.

O ile w przypadku jednego serwisu byłoby to raczej mało odczuwalne, o tyle z racji tego, że jest ich kilka, można odczuć po tej przerwie, że aplikacje korzystające z API tego systemu mają lekkiego początkowego laga (szczególnie jedna, która na starcie od razu zaciąga dużo danych)

@Damian Śniatecki jakie masz ustawienia dla pul połączeń? Zwłaszcza dla Keep Alive i Max Idle Time?

Czemu nie łączysz się bezpośrednio do private IP? Problem z DNSami najlepiej rozwiązać po prostu ich nie używając

Generalnie możesz też ustawić gdzieś jakiegoś crona co będzie strzelał co jakieś 10-15 minut do tej apki, żeby była cały czas "w gotowości".

slsy napisał(a):

Czemu nie łączysz się bezpośrednio do private IP? Problem z DNSami najlepiej rozwiązać po prostu ich nie używając

Nie chciałbym harcodować IP w aplikacji mobilnej np :)

Crona wolałbym nie ustawiać. Nie chcę sobie ruchu z zewnątrz (który monitoruję), tym zaśmiecać.

Flow jest takie:

Mikroserwis A -> Mikroserwis B

Ustawienia web-clienta w mikroserwsie A:

  web-client:
    max-in-memory-size: 50000000
    connection:
      max: 100
      max-idle-time: 30s
      max-life-time: 60s
      pending-acquire-timeout: 60s
      evict-in-background: 30s
      timeout: 5m

    private fun createWebClientConnectionProvider(): ConnectionProvider =
        ConnectionProvider.builder("webclient-connection-pool")
            .maxConnections(webClientMaxConnections)
            .maxIdleTime(webClientConnectionMaxIdleTime)
            .maxLifeTime(webClientConnectionMaxLifeTime)
            .pendingAcquireTimeout(webClientConnectionPendingAcquireTimeout)
            .evictInBackground(webClientConnectionEvictInBackground)
            .build()

Ustawienia poola r2dbc w mikroserwisie A:

  pool:
    enabled: true
    initial-size: 5
    max-size: 20
    max-idle-time: 30m
    max-validation-time: 5s

Dużo już z tym eksperymentowałem i różnice były marginalne.

Moim zdaniem to jest coś związanego z samym frameworkiem, serwerem aplikacji, czy jdk. Wskazuje na to, że nawet jeśli request odbije się od walidacji mikroserwisu A ( czyli nie łączy się nawet z mikroserwisem B), to po przerwie typu 15-30 minut te pierwsze wywołanie jest znacząco wolniejsze.

Z tym r2dbc:

pool:
    enabled: true
    initial-size: 5
    max-size: 20
    max-idle-time: 30m      
    max-validation-time: 5s

Po takiej konfiguracji oczekiwałbym, że pół godziny po ustaniu ruchu, pula zostanie wyczyszczona do 0 połączeń. Zmień sobie max-idle-time na 5min i zobacz, czy po przerwie 5min (a nie jak obecnie 15-30min), kolejny request jest znacząco wolniejszy. Jeśli tak, to może wypadałoby skonfigurować connecition keepalive dla puli.

yarel napisał(a):

Z tym r2dbc:

pool:
    enabled: true
    initial-size: 5
    max-size: 20
    max-idle-time: 30m      
    max-validation-time: 5s

Po takiej konfiguracji oczekiwałbym, że pół godziny po ustaniu ruchu, pula zostanie wyczyszczona do 0 połączeń. Zmień sobie max-idle-time na 5min i zobacz, czy po przerwie 5min (a nie jak obecnie 15-30min), kolejny request jest znacząco wolniejszy. Jeśli tak, to może wypadałoby skonfigurować connecition keepalive dla puli.

Zgadza się. Jednak w systemie są różne zadania, które co kilka minut odpytują bazę poprzez różne mikroserwisy, więc tam zawsze jakieś połączenia są otwarte.

Wydaje mi się, że tutaj jednak jest coś związanego z samym frameworkiem lub serwerem aplikacji (Netty). Może jakieś póle wątków zostają zwolnione, albo coś musi się inicjalizować na nowo po jakimś czasie. Dużo springów lata na produkcji i liczyłem, że ktoś może napotkał podobny problem.

Koniecznie zadnych metryk! Zgadujemy dalej!

Nie rozumiem jak ludzie moga tak pracowac. Sa metryki, pokazuje ile jest otwartych polaczen. Jak to jest jakas baza z Clouda to ma swoje metryki z polaczniami na konkretnego usera. A tutaj zgaduj-zgadula od 3 dni.

Mam niestety tylko podstawowe metryki, ale takie które pozwalają mi ocenić ile trwały dane zapytania do bazki i ile zajęła cała odpowiedź mikroserwisu.

Mikroserwis B (Spring Webflux, JDK 21 & ZGC, Netty, Spring R2DBC + PostgreSQL w cloudzie). Prosty endpoint, który jedynie zaciąga 50 ostatnich obiektów.

[Poprzednie zapytania]
[19:20 - ostatnie zapytanie] - Bazka odpowiada: 14.2 ms, a mikroserwis w 18.7 ms
[PRZERWA - zero zapytań do tego mikroserwisu]
[19:28 - pierwsze po przerwie] - Bazka odpowiada: 16 ms, a mikroserwis w 261 ms

Czasy metryk w cludzie dla bazy jeszcze niższe ( nie uwzględniają transferu), więc samą bazę możemy już raczej wykluczyć jako przyczynę.

CPU, GC, Wątki, Heap w normie.

Dane według metryk mikroserwisu ( nie uwzględniają transferu danych )

Liczyłem, że może jest to coś charakterystycznego dla Spring Boota i ktoś miał podobny problem.
Trochę niepotrzebnie o tej bazie wspominałem i pool-u. Zmyliłem jedynie. DNS dotyczył akurat problemu połączenia z zewnątrz.

Wrzucę debug/trace i spróbuję po logach ocenić co tam się dzieje

Po przeanalizowaniu logów okazało się, że to aplikacja sama w sobie jest wyraźnie wolniejsza ( walidacja, mapowanie i różne springowe magie ) przy pierwszym wywołaniu po dłuższej przerwie i potem się znowu się rozpędza.

Mikroserwisy mają mocno ograniczone zasoby, ale nie powinno być to wymówką dla takiego zachowania. Pobawiłem się trochę różnymi flagami JVMa, ale raczej bezskutecznie.

Co ciekawe, zastosowanie defaultowego GC zamiast ZGC (ZGC zużywa więcej CPU i agresywniej unload-uje klasy) pomogło w dużym stopniu ograniczyć to zjawisko, ale abym mógł wyciągnąć jakieś dokładniejsze wnioski musi to trochę polatać na prodzie. Niestety nie posiadam dogłębnej wiedzy na temat obecnych GC-ków by być w stanie to sensownie wytłumaczyć.