Soci (Soczó Zsolt) szakmai blogja

2017.09.04.

IIS lassulás probléma – help needed

Filed under: Szakmai élet — Soczó Zsolt @ 20:44

Kivételesen nem megoldást írok le, hanem kérdést teszek fel.

Egyik ügyfelemnél vagy egy eset, amit egyelőre nem sikerült visszafejteni. Adott 3 IIS publikus web láb NLBS-sel összenyalábolva, és 3 belső IIS alatt futó WS szintén NLBS mögött, ezeket hívják a külső webappok. A Windowsok VmWare alatt vannak virtualizálva.

A hiba az, hogy random időpontban belassulnak a webszerverek webszervizek irányába mutató hívásai. Normál esetben egy gyors ws metódus hívása 2-5ms, amikor beáll ez az állapotváltás a webszerver worker process belsejében, akkor felmegy kb. 200 ms-re.

Azért írok állapotváltást, mert nem azért lassulnak be a dolgok, mert nap közben nagyobb a terhelés, hanem egyszer csak “elborul” a webapp, és belassul. Dynatrace alapján a ws hívások mélyén a recv windows hívás válaszol lassan. Ilyenkor a ws iis logjában is lassú a hívás, vélhetően mert a webapp mint kliens lassan viszi el az adatot.
Hamarosan lesz DotTrace lenyomat és FREB log is, illetve System.NET trace is (csak ez nagyon sok adatot termel).

IIS App reset megoldja a problémát egy ideig. Ha egy app beteg, akkor egy console appból ugyanaz a ws hívás ugyanezen a gépről a wsek felé gyors, tehát nem valószínű, hogy a wsek lassulnak be.

Nehézkes megfogni az estet, mert pl. egy config módosítás a trace-ek kedvéért azonnal appol resetet csinál, így elillan a hiba, aztán lehet megint egy napot várni rá.

A .NET perf counterek nem mutatnak kiugró értékeket, minden normálisnak tűnik. A web processben kb. 500 szál fut 1-3 kérés/sec esetén, ez mondjuk kicsit soknak tűnik, de a procmon nem mutatta meg a managed stacket (debug symbolokkal se), majd csak dottrace-ből látszik, mit csinálnak. A procik 10%-ig vannak kiterhelve. A diszk terhelés minimális, paging nincs, van 0.5G szabad memória, más proceszek nem eszik el az erőforrásokat. A resource monitorban a wsek irányába futó kérések jelentős része 200ms körüli latency-t mutat, ez egybevág más megfigyelésekkel.

Látott már ilyet valaki? Mit lehetne még mérni, amire nem gondoltam?

10 Comments »

  1. És amikor beáll a lassulás, akkor az képes magától helyre jönni, vagy onnantól az az állapot van?

    Az ugrás szerintem túl kicsi ahhoz, hogy infrastrukturális baja legyen, de azért kíváncsi lennék a VM-ek specifikációjára [0.5 GiB memóriát én keveslem, mint szabad], illetve a w3wp-k memóriafoglalására. Ami még érdekes lehet, hogy nem-e a load balancer-ek játszanak valamit a socket-ekkel, illetve kérdés még, hogy egyáltalán a service-eket min keresztül lehet elérni, HTTP(1.0, 1.1), más?

    Ha a web service log-jában is látszik a lassú hívás, akkor gondolom, nem szabad kapcsolatra vagy hasonlóra vár a web app, nem tudom, visszairányban ki lehet-e ilyenkor még éheztetni az app-ot vagy sem hasonló módon.

    A 200ms plusz egyébként nekem nagyon annak tűnik, mikor a service hívásban a request sok időt tölt el az “AcquireRequestState” fázisban, olyan, mintha a shared session-re várna, hogy tudja lock-olni. Ilyet látok minden nap “nálunk”, még nem sikerült kijavíttatni…

    Én mindenképpen ilyen shared state-eket keresnék.

    Amit még ki lehetne próbálni, az egy New Relic vagy hasonló megoldás, ami meg tudná mutatni összefüggésében is a dolgokat.

    Comment by Peter — 2017.09.05. @ 07:11

  2. Csak app recycling segit.

    Comment by Soczó Zsolt — 2017.09.05. @ 07:18

  3. Szerintem nézd meg, hogy nincs-e valami a Nagle algorithm-mel (még TCP NoDelay néven is ismert, ez az, amikor ki van kapcsolva a Nagle algorithm).

    https://msdn.microsoft.com/hu-hu/library/system.net.sockets.socket.nodelay(v=vs.85).aspx

    Azért jutott eszembe, mert az pont 200 msec defaultból.

    Comment by Rici — 2017.09.05. @ 08:36

  4. Rici: igen, Nagle képbe került, de nem kapcsoltuk ki, mivel azt valószínűleg nem oldaná meg az IIS reset. Mindenesetre egy mérést megér.

    Comment by Soczó Zsolt — 2017.09.05. @ 18:40

  5. Peter: Dynatrace fut, a szerint a WebClient mélyén a windows api recv-jére vár a hívó webapp.

    Comment by Soczó Zsolt — 2017.09.05. @ 19:22

  6. Megnézném egy Wireshark-kal vagy hasonló network capture programmal a pontos időzítést, pontosabban összevetném a Dynatrace eredménnyel. A kérdés, hogy a recv hívás kezdete és befejezése hogyan viszonyul a hálózati csomag beérkezéséhez.

    Ha a recv kezdete környékén már ott van a csomag, akkor a fogadó gépen és a kliens processzben kell tovább nézegetni, pl. nem lehetséges-e, hogy a sok szál miatt van valami gond.

    Ha csak a recv hívás befejeződése környékén érkezik meg a csomag, akkor úgymond jogosan várakozik a recv hívás. Ez utóbbi esetben az egy elég érdekes kérdés, hogyan tudja rávenni a szervert egy adott kliens processz, hogy csak és kizárólag neki késleltetve küldje a válaszokat.

    Még egy tipp, hogy esetleg a hálózati kártya driverében van valami bug. Főleg, ha TCP offload be van kapcsolva, amikor is a TCP logika egy részét a hálózati kártya és a driver implementálja.

    Comment by Rici — 2017.09.06. @ 09:34

  7. Sikerült kideríteni valami izgalmasat?

    Comment by Peter — 2017.09.15. @ 15:56

  8. A virtualizált környezetben dedikált cpu magokon fut a windows?
    Egy ügyfelünknél többszáz millis várakozásokat okozott a webcontainer
    szálaknak, hogy az oprendszer elemi műveleteire vártak. Minél több virtuális magot
    rendeltek a guesthez annál gyakrabban fordult elő a probléma.
    Egyetlen dedikált mag megoldotta a problémájukat, az alkalmazás végig
    hibátlan volt.

    Comment by Robert — 2017.09.19. @ 20:58

  9. Rici, ez jó ötlet, köszönöm, ha lesz rá mód, összevetem.

    Comment by Soczó Zsolt — 2017.09.22. @ 15:49

  10. Robert: ez bizarr, de elvileg dedikált magon futnak.

    Comment by Soczó Zsolt — 2017.09.27. @ 22:55

RSS feed for comments on this post. TrackBack URL

Leave a comment

Powered by WordPress