Katselin vähän tuon viimeisen jumin requesteja ja responseja. Filtteröin requestit/responset posts.json nimellä (että pysyy yhtään kärryillä logista) ja tuossa jumin kohdalla yhdestä requestista tulee logiin n. kpl responseja, eli tod.näk. tuossa kohdassa joku discoursen palikka huomaa, että samaan aikaan onkin tullut enemmänkin uusia viestejä.
Eka response jumiin liittyen on tullut ajassa 17:42:52 GMT ja vika 17:43:38 GMT. Eli koska kaikki performance metriikat ovat ihan normaaleja niin voiko nuo responset sitten jäädä jonnekin pendaamaan?
Edit: Kun katsoo tuon jumin requesteja niin siinä haetaan ryöppyä samanaikaisia viestejä ja keskellä noiden uusien viestien hakua poll-request palauttaa 429:n ja sen jälkeen seuraava response tulee vasta 14 sekunnin kuluttua.
Mutta ei kyllä pysty sanomaan tuohon mitään kun ei Discoursen toteutusta tunne.
Viimeksi kun tähän liittyen Discoursen koodia luin, sieltä tulee 429 jälkeen frontille käsky odottaa satunnainen aika 5-10s väliltä. Eli tuo @a1r6 havaitsema 5s voisi olla juurikin tämä.
Edit: Ja tuo taisi triggeröityä siitä, että viestijonojen viive kasvoi arvoon x. Tämä vähän sellaista muistelua ja voi olla jo muuttunutkin.
No tämä taas saattaisi selittää tuon vikan vähän tarkemmin tutkimani casen, kun poll palauttaa 429, sen jälkeen tulee tauko ja sitten kun sen jälkeen jatketaan viestiryöpyn uusien viestien hakemista niin ne responset tulevat aina useamman sekunnin välein vaikka kaikki performance-metriikat ovat ihan normaalit?
Edit: Ja tuon jumin luonne selaimen puolella vs. request/response-logi vaikuttaisi siltä, että kun haetaan avoimeen ketjuun uusi viesti niin sitten joku palikka Discoursessa yrittää luupissa hakea kerralla kaikki uudet viestit ja selain päivitetään vasta sitten kun kaikki uudet on saatu, mutta 429:n aiheuttamat viiveet tekevät tämän sitten hitaaksi eli jumiksi.
Disclaimer: Mitään en Discoursen toteutuksesta tiedä, mutta omat ja @ozzi havainnot ehkä tukevat tätä teoriaa.
Jumin syy kun on edelleen auki, niin tuli mieleen että saisiko sen 429:n jotenkin disabloitua?
Kaikki nuo request/response-logista tutkimani jumit sisälsivät 429:n ja kaikki muut metriikat olivat ihan minimaalisia (redis, runtime ja sql olivat max. 0.1s, queue taisi olla max. 0.3s).
Jos 429:n saisi disabloitua ja seurailisi taas logia niin voisi saada jotain lisäinfoa.
Web rate limiterin saa pois, mutta sitten ylikuormittuu serveri. Discourse suojelee aika agressiivisesti palvelinta pitääkseen sen toimintakykyisenämä.
Normaalitempoisessa keskustelussahan tämä ei ole ongelma, vaan erittäin järkeväää, koska 45 sek viiveellä ei ole merkitystä. Eri selaimet taitavat vielä reagoida 429:iin eri tavalla.
Inspectorin tallennetta eiliseltä illalta juuri katsoin ja kaikissa niissä 429:ssä missä mitään performance-infoa tuli mukana, oli queue time yli 0.1. Sen verran sähläsin tallenteen ottoa että sinne ei jäänyt kuin 429-vastaukset, niin tuosta ei nyt näe osviittaa millaisia infoja olisi ollut juuri ennen 429:ää. Mutta olisiko tuossa sitten se avuksi että Unicornien määrää kasvattaa.
Kuormat oli eilen etummaosella palvelimella aika ihanteenlliset, eli hetkittäin maalipiikeissä load kävi 4.00 yläpuolella.
Tässä tulee taas UpCloudin hinnoittelupaketit vastaan, eli seuraava plani tarjoaan vain +2 corea, vaikka hinta tuplaantuu. 6x3=18 unicornia sillä saisi, nykysäädöillä.
Illalla pelataan, joten taas uusi kokeilu kokoonpanoon.
Webbiä pyörittää nyt 6 vCore / 16GB purkki
Unicornien määrä nousi samassa suhteessa 12 → 18
Eli käytössä on nyt enemmän tehoja ja resursseja kuin koskaan. Kaiken järjen mukaan tämän pitäisi parantaa tilannetta merkittävästi, koska muutos yhteisössä viime maaliskuun KooKoo-ottelusta (ilman yleisöä) ei kuitenkaan ole niin suurta.
Mutta olen edelleen pessimistinen, sillä olen alusta alkaen epäillyt jotain muutosta versioissa 2.4…2.5, joka heikentää suorituskykyä meidän käyttötapauksessa. Onko se sitten nuo rate limiter -toiminnot, tai joku muu.
Nyt heti näkee jo kuinka webin kasvattaminen kuormittaa myös tietokantapalvelinta enemmän. Näyttää korreloivan suoraan Unicornien määrään. Mielenkiinoista alkaako se vuorostaan yskähdellä kun verkko heiluu?
Tutkin tuota Discoursen koodia vähän tarkemmin. Siellä tuli jossain kohtaa tuo aiemmin mainitsemani fiksi 429-tilanteisiin. Discourse-Background headerillä varustetut kyselyt saavat olla jonossa korkeintaan 0.5s, muuten clientille heitetään 429 ja pyyntö odottaa 5-10s.
Headeri on käytössä vain uusien viestien lataamisessa (triggerNewPostsInStream).
The only request we shed at the moment is the request to load up a new post
when someone posts to a topic.
We can extend this as we go with a more general pattern on the client.
Siispä mutuilua mahdollisista tilanteista:
Discourse-Background ei ole (vielä) mukana kaikkialla missä sen pitäisi olla? Eli jotkin kutsut räjäyttävät asioita?
Meillä jono kasvaa yli tuon 0.5s joka triggeröi noita odotteluita. Tilanteen pitäisi siis palautua 5-10s kuluttua, jos kuorma on silloin laskenut eikä tule uutta 429:iä.
Raja-arvoa voi säätää background_requests_max_queue_length muuttujalla, tähän voisi kokeilla pitempää odotusta? Tämä toiminnallisuus on ymmärtääkseni täysin erillään aiemmin säädetyistä 429:hin liittyvistä toiminnallisuuksista.
Miksi jono venyy niin pitkäksi?
Illan pelin aikana olisi hyvä siis seurata seuraavia asioita:
x-queue-time headerin arvoja, kasvaako tämä yli 0.5s? Tätä ei harmillisesti lähetetä poll/timings kyselyissä joten seuraaminen on hankalaa seurannassa. Onko Discoursessa yhteinen jono kaikille viesteille? Arvot kiinnostavat etenkin maalitilanteissa (tai muissa viestiryöpyissä).
Kun seuranta pysähtyy, palautuuko tilanne odottelun jälkeen itsestään? Näkyykö 429-vastauksia useampia ja minkälaisille väleillä? Kauanko palautumiseen menee?
Jonkun verran tulee 429:ä, mutta jotenkin satunnaisesti, eivät liity aina edes maaleihin. Nyt tuli erätauolla:
Request URL: xhttps://tappara.co/message-bus/2f05976d29864c99b6e30eb8ca894e20/poll
Request Method: POST
date: Tue, 29 Dec 2020 18:00:57 GMT
Response: You’ve performed this action too many times. Please wait 2 minutes before trying again.
Edellinen onnistut poll oli:
date: Tue, 29 Dec 2020 18:00:31 GMT
429:n jälkeinen seuraava poll:
date: Tue, 29 Dec 2020 18:03:04 GMT
Eli tuossa tuli pitkä tauko, mutta toipui itsekseen, kun jaksoi odottaa.
Ei ole kyllä mitään arvausta. Kaikki x-*-time-headerit esim. tuon tapauksen ympärillä näyttävät ihan normaaleilta, mutta mitään requesteja ei liiku tuon failanneen pollin ja sen tauon jälkeen onnistuneen välissä.
Mites nämä kaikki limiterit oikein toimii, kun otin U20 pelin mainoskatkolla koko rate limiterin pois, mutta sain sen jälkeenkin 3x 429:ia tuosta poll:sta ja ilmeisesti @iceman ainakin yhden myös.
DISCOURSE_MAX_REQS_PER_IP_MODE` : none
x-queue-time: 0.221929
x-runtime: 0.000411
Oletin siis, ettei throttlausta tapahtuisi tuolla asetuksella enää lainkaan.