Egy nyomozás története következik.
Mint azt jónéhányan már látták (és sajnos néhányan önhibájukon kívül jól meg is járták 🙁 ) az IE224 labor teljesen új Ubuntu alapú rendszert kapott. Erről majd ha nagyon ráérek (famous last words…) írok egy részletesebb leírást is. Ez a rendszer most egy kellemes kis rejtvényfeladványt csinált nekem. Lássuk röviden a szereplőket:
- Labpc17. Róla annyit kell tudni, hogy rossz helyen volt rossz időben, rajta volt egy virtuális gép, amit szét kellett volna dobni az összes többi laborgépre.
- Shelob. Gonosz fekete pók, ami majdnem megette Frodót és most behálózta az összes laborgépet. Gyakorlatilag minden hálózati szolgáltatás a laborban erről jön. A mostani eset szempontjából annyi érdekes, hogy innen lehet lokálisan tárolt fájlokat szétmásolni a gépekre. CentOS fut rajta.
- Aragorn. A hibatűrő kutatócsoport “mindentvívő” gépe. Tényleg minden lényeges virtuális gépet ez visz a hátán, ez ugyanis egy ESX server. A Shelobot is hátán viszi… mert ugyanis az virtuális. (Ezt így szó szerint vizualizálni csak horror rajongóknak javaslom 🙂 )
- Idril. Ez adja iSCSI-n a tárhelyet az Aragorn (és még egy rakás másik) gép alá, az éles virtuális gépeink minden tárhelye fizikailag itt helyezkedik el. Egy raid-5 tömb van LVM-mel kötetekre bontva, ezt szolgálja ki az iscsi enterprise target. Mindez CentOS felett.
Egy szép komplikált rendszer kezd körvonalazódni. Igazából egy nagy IT infrastruktúra is jellemzően pont ennyi rétegből, hasonló struktúrával épül fel, csak minden elemből sokkal több darab van. Meg persze az egyes elemek kicsit nagyobbak és többe is kerülnek.
De bevezetőből ennyi elég is most. Nem akartam semmi különösen bonyolultat ettől a rendszertől, egyszerűen egy pár fájlt scp-vel felmásolni a labpc17-ről a Shelobra. Gigabites a hálózat végig, erős a gép a kapcsolat mindkét végen, 30-40 MB/s-et szokott tudni scp-vel másolva. Na ebből most nekem lett 200-300 kB/s. Ennél még az ADSL is gyorsabb. Mivel nem akartam az ítéletnapig tartó másolás közben unatkozni (jó pár óra lett volna ezzel a tempóval), ezért inkább azzal töltöttem az időt, hogy megpróbáltam rájönni, hogy mégis miért csinálja ezt és hogy lehet megjavítani.
laboradmin@labpc17:/media/vmware-images/oktatas$ scp -r TestImage/ xmi@shelob:/srv/nfs/imagestore/oktatas/ xmi@shelob's password: Windows XP Professional SP3-cl1-000001-cl1.vmdk 100% 766 0.8KB/s 00:00 Windows XP Professional SP3-cl1-000001-cl1-000002-s003.vmdk 100% 320KB 320.0KB/s 00:00 vmware.log 100% 76KB 75.5KB/s 00:00 LaborXP.vmx 100% 1554 1.5KB/s 00:00 Windows XP Professional SP3-cl1-000001-cl1-000002.vmdk 100% 644 0.6KB/s 00:00 LaborXP-Snapshot5.vmsn 100% 26KB 26.4KB/s 00:00 vmware-1.log 100% 58KB 58.1KB/s 00:00 Windows XP Professional SP3-cl1-000001-cl1-s001.vmdk 70% 1338MB 307.9KB/s 31:34 ETA
Azt hiszem elég egyértelmű, nem kell ehhez sok magyarázat. Elsőre mit próbál ki a tanácstalan ember? Nézzük meg top-pal a gépeket. A kliens labpc kimenetét külön nem másoltam be ide, de azt hiszen nem nehéz elhinni, hogy ott semmi terhelés nem látszott. 300kB/s-el scp-zni egy 486-osnak is megy, nem hogy egy Core2 E6400-nak. Nézzük inkább a másik végét, a Shelobot, kizárásos alapon ott kell lennie a bajnak:
top - 16:20:58 up 12 days, 21:09, 2 users, load average: 1.57, 1.08, 0.52 Tasks: 150 total, 2 running, 148 sleeping, 0 stopped, 0 zombie Cpu(s): 0.8%us, 0.7%sy, 0.0%ni, 96.2%id, 1.8%wa, 0.1%hi, 0.3%si, 0.0%st Mem: 3115860k total, 2616856k used, 499004k free, 418524k buffers Swap: 0k total, 0k used, 0k free, 2011980k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 20097 xmi 25 0 6496 1436 1124 R 6.0 0.0 4:35.69 scp 20096 xmi 15 0 14180 5944 1108 S 1.0 0.2 0:49.87 sshd 354 root 17 -5 0 0 0 S 0.1 0.0 5:58.81 kjournald 1 root 15 0 2064 624 536 S 0.0 0.0 0:02.27 init 2 root RT -5 0 0 0 S 0.0 0.0 0:00.00 migration/0 3 root 34 19 0 0 0 S 0.0 0.0 0:00.03 ksoftirqd/0
Kiemeltem a lényeget, így máris rögtön látható, hogy… nem látható semmi. Gyakorlatilag üresjáratban van a gép. Némi gyanakvással töltött el azért a magas load average. Mégis mitől? Ha egyszer még az iowait is csak 1,8%. Pedig a diszk I/O-ra gyanakodtam. Biztos, ami biztos lássunk egy iostat kimenetet, ha többféle mérési eredmény van az sosem árt:
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 6.67 0.00 26.67 0.00 8.00 0.01 2.00 2.00 1.33 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 200.00 0.00 800.00 8.00 0.22 1.11 0.06 1.11 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 [...] sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 40046.15 0.00 461.54 0.00 162030.77 702.13 1.12 2.42 0.48 22.31 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
Szép sorminta, felülről lefelé minden sor egy 2 másodpercenkénti mintavétel. Annyit még elárulok, hogy kicsit csaltam, hogy ilyen szép legyen a kiírás, a következő parancsot adtam ki:
iostat -d -x -k 2 | grep 'sdb'
Az sdb az a diszk, amire másolok scp-vel, tehát itt sok írás műveletet kellene látni. Ehhez képest elég ritkásan történik bármi is. Persze jogos, hiszen a lassan csordogáló adat a write bufferben állomásozik, míg össze nem gyűlik elég (vagy le nem telik a beállított maximális idő) ahhoz, hogy érdemes legyen kiírni. Miket mutat az iostat:
- rrqm/s, wrqm/s – összevont olvasás és írás műveletek száma (átlagolva a legutóbbi 2 sec-es intervallumban)
- r/s, w/s – nyers olvasás és írás műveletek száma átlagolva
- rkB/s, wkB/s – na vajon mi lehet… adat áteresztő képesség olvasás és írás esetén
- avgrq-sz – egy művelet során átlagosan megmozgatott adatmennyiség
- avgqu-sz – a várakozási sor átlagos hossza
- await – átlagos várakozási ideje egy műveletnek, beleértve a sorban állási időt is
- svctm – a kérések kiszolgálási ideje az eszközben, sorban állási időt nem számítva
- %util – az idő mekkora részében végzett az eszköz valami feladatot.
Az %util értékek alacsonyak, tehát bőven van üresjárati ideje. Viszont akkor miért nem csinálja gyorsabban? Mi az amire várni kell? És ha már itt tartunk az a 162MB/s-es írás 2 másodpercre vett átlagként teljesen hihetetlen. Az is érezhető, hogy a gép lassan válaszol, mintha erősen terhelve lenne, annak ellenére, hogy látszólag minden szempontból üresjáratban van.
Mivel itt nem igazán jutottam közelebb a probléma természetének megértéshez, csak annyit sikerült megállapítani, hogy – finoman szólva – inkonzisztensek az eredmények, ezért most egy kicsit lejjebb kell ásni. Mit mond az ESX szerver a virtuális gépről, kívülről nézve? Ezt a service console-on az esxtop segítségével nézhetjük meg. Az esxtop csak root felhasználóval működik. Nézzük rögtön a ‘d’ lenyomásával a diszk statisztikát:
4:24:16pm up 67 days 5:43, 109 worlds; CPU load average: 0.35, 0.35, 0.35ADAPTR CID TID LID WID NCHNS NTGTS NLUNS NVMS AQLEN LQLEN WQLEN ACTV QUED %USD LOAD CMDS/s READS/s WRITES/s MBREAD/s MBWRTN/s vmhba0 - - - - 1 3 3 23 512 0 0 - - - - 1.91 0.00 1.91 0.00 0.01 vmhba1 - - - - 1 0 0 0 512 0 0 - - - - 0.00 0.00 0.00 0.00 0.00 vmhba32 - - - - 1 2 2 50 4096 0 0 - - - - 90.71 82.65 8.05 0.32 0.06
Na itt most nem fogok teljes jelmagyarázatot adni, akit érdekel itt elolvashatja a teljes leírást az esxtop által mért értékekről. A lényeg, hogy a vmhba32 a mi eszközünk, ez a szoftveres iscsi initiatior. A sor végére figyelve láthatjuk, hogy kiadott parancsok túlnyomó többsége olvasás. Persze nem egyedül terheli a Shelob a gépet, fut még egy rakás másik virtuális gép is. A tisztánlátás végett tekintsük meg a virtuális gépre lebontott diszk IO-t a ‘v’ billentyű lenyomásával:
ID GID NAME DEVICE NWD NDV DQLEN WQLEN ACTV QUED %USD LOAD CMDS/s READS/s WRITES/s MBREAD/s MBWRTN/s
2 2 system - 3 - 0 0 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00
6 6 helper - 5 - 0 0 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00
9 9 console - 1 - 0 0 0 0 0 0.00 1.72 0.00 1.72 0.00 0.01
15 15 vmware-vmkauthd - 1 - 0 0 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00
20 20 Alnitak - 3 - 0 0 0 0 0 0.00 0.19 0.00 0.19 0.00 0.00
37 37 Gorbag - 3 - 0 0 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00
50 50 Shelob - 4 - 0 0 0 0 0 0.00 68.66 65.99 2.67 0.26 0.04
59 59 Uglug - 4 - 0 0 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00
67 67 TaddmImage - 3 - 0 0 0 0 0 0.00 1.14 0.00 1.14 0.00 0.02
78 78 PseudoSalvador - 3 - 0 0 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00
[...]
De bizony a Shelob csinálja az olvasást. A többi gép viszonylag nyugiban van, nem lehet rájuk fogni, hogy elzabrálnák az erőforrásokat. Ez roppant érdekes, mert a Shelobon belülről nézve a nem látszottak kiadott olvasás műveletek, ebben az elkapott mintavételben pedig kb. 30-szor annyi olvasás művelet látható, mint írás, de az adatmennyiségben is legalább hatszoros eltérés van. Nem a mintavételezés csal, ezek sajnos az átlagot teljesen jól reprezentáló értékek. Honnan jönnek azok olvasás kérések? A Shelob itt valójában nem egy atomi bejegyzés, hanem egy aggregált folyamat csoport a hypervisor felett, ami kibontható az ‘e’ billentyűvel és a megfelelő GID megadásával. Kibontva ezt látjuk:
ID GID NAME DEVICE NWD NDV DQLEN WQLEN ACTV QUED %USD LOAD CMDS/s READS/s WRITES/s MBREAD/s MBWRTN/s 1325 50 vmware-vmx - 4 1 0 32 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00 1326 50 vmm0:Shelob - 4 1 0 32 1 0 3 0.03 66.76 65.04 1.72 0.25 0.01 1328 50 mks:Shelob - 4 1 0 32 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00 1329 50 vcpu-0:Shelob - 4 1 0 32 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00
A vmm csinálja. Szerettem volna azt hinni, hogy közelebb kerültem a megoldáshoz, de más virtuális gépeket megnézve azt tapasztaltam, hogy minden diszk művelet csak és kizárólag a vmm alatt jelenik meg. Érdemes még megfigyelni WQLEN és ACTV értékeket, az előbbi a várakozási sor maximális hossza, az utóbbi a kihasznált hossza. A sorban nem várakoznak műveletek, mindig csak egy van benne. Hasonlóan, ahogy az iostat-nál láttuk, itt is van egy számított kihasználtsági százalékos érték: %USD. Itt is meglepően alacsony az érték, nem magyarázza meg, hogy miért nem gyorsabb a szerencsétlen guest gép.
A fentebbi diszk statisztika is kibontható folyamatokig, ekkor egy ilyen szép táblázat lesz az eredmény:
ADAPTR CID TID LID WID NCHNS NTGTS NLUNS NVMS CMDS/s READS/s WRITES/s MBREAD/s MBWRTN/s DAVG/cmd KAVG/cmd GAVG/cmd QAVG/cmd DAVG/rd KAVG/rd GAVG/rd QAVG/rd DAVG/wr KAVG/wr GAVG/wr QAVG/wr
vmhba0 - - - - 1 3 3 23 1.91 0.00 1.91 0.00 0.01 4.56 0.01 4.56 0.00 0.00 0.00 0.00 0.00 4.56 0.01 4.56 0.00
vmhba1 - - - - 1 0 0 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1024 0 0 0 1 0.76 0.00 0.76 0.00 0.00 0.18 0.01 0.20 0.00 0.00 0.00 0.00 0.00 0.18 0.01 0.20 0.00
vmhba32 0 0 0 1032 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1033 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1035 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1036 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1037 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1069 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1078 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1079 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1080 0 0 0 1 0.38 0.00 0.38 0.00 0.03 7.15 0.00 7.16 0.00 0.00 0.00 0.00 0.00 7.15 0.01 7.16 0.00
vmhba32 0 0 0 1083 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1116 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1228 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1229 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1232 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1303 0 0 0 1 0.19 0.00 0.19 0.00 0.00 0.93 0.02 0.94 0.01 0.00 0.00 0.00 0.00 0.93 0.02 0.94 0.01
vmhba32 0 0 0 1305 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1314 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1315 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1318 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1325 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1326 0 0 0 1 106.24 76.48 29.75 0.30 7.72 9.09 0.01 9.10 0.00 11.06 0.01 11.07 0.00 4.04 0.00 4.05 0.00
vmhba32 0 0 0 1328 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1329 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1390 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1391 0 0 0 1 0.57 0.00 0.57 0.00 0.00 0.30 0.01 0.32 0.00 0.00 0.00 0.00 0.00 0.30 0.01 0.32 0.00
vmhba32 0 0 0 1392 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1395 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1446 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1447 0 0 0 1 4.39 0.00 4.39 0.00 0.02 3.68 0.00 3.68 0.00 0.00 0.00 0.00 0.00 3.68 0.00 3.68 0.00
vmhba32 0 0 0 1450 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1451 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1452 0 0 0 1 0.76 0.38 0.38 0.00 0.02 20.46 0.01 20.47 0.00 10.62 0.01 10.63 0.00 30.30 0.01 30.31 0.01
vmhba32 0 0 0 1455 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1498 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1499 0 0 0 1 0.76 0.00 0.76 0.00 0.01 11.32 0.01 11.34 0.01 0.00 0.00 0.00 0.00 11.32 0.01 11.34 0.01
vmhba32 0 0 0 1502 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1513 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1514 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 0 0 1517 0 0 0 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
vmhba32 0 1 - - 1 1 1 10 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
Gyönyörű, a teljes vizuális élmény érdekében nem szedtem ki a történet szempontjából lényegtelen sorokat. 🙂 Most más oszlopokat kapcsoltam be (‘f’ billentyű), a kiszolgálási időket akartam szemügyre venni. A lényeges sort a World ID alapján találhatjuk meg (ez a process ID megfelelője a VMware terminológiájában), az előző táblázatból lenézhető, hogy az 1326-os a számunkra érdekes. A fizikai eszköz olvasási kiszolgálási idejére az átlag érték 11ms, ami teljesen normális, az írás ennél is rövidebb. Ez sem ad magyarázatot.
Nincs más hátra be kell nézni az iSCSI szerverre is, indításnak mondjuk egy iostat-tal. Ez most nem idősor, hanem csak egy mintavétel az idősorból az összes eszköz felsorolásával:
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sda1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sda2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdc 47.50 0.00 36.00 0.00 334.00 0.00 18.56 0.43 11.85 8.54 30.75 sdd 18.00 0.00 31.50 0.00 198.00 0.00 12.57 0.37 11.62 9.70 30.55 sde 8.50 0.00 19.00 0.00 110.00 0.00 11.58 0.19 9.97 9.74 18.50 sdf 15.50 0.00 30.00 0.00 182.00 0.00 12.13 0.27 8.90 8.53 25.60 md1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 md0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 md2 0.00 0.00 206.00 0.00 824.00 0.00 8.00 0.00 0.00 0.00 0.00 dm-2 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-3 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-4 0.00 0.00 206.00 0.00 824.00 0.00 8.00 2.04 9.90 4.60 94.85 dm-5 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-6 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 dm-7 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
Az sdc, sdd, sde, sdf fizikai merevlemezek adják az md2 raid tömböt, azt hiszem ez talán ki is található az eredményekből. A dm-4 az egyik logikai kötet, történetesen az, amin a Shelob virtuális diszkje is helyet kapott. Na itt már látni csúnya dolgokat. A jobb szélen a táblázatban a %util 94,8%, tehát gyakorlatilag telítésben van. Ehhez tartozik egy 824 kB/s-os olvasási áteresztőképesség, ami nagyon alacsony. Ez bizony trashel, nem is kicsit. Mindezt 2048-as readahead és bekapcsolt read és writeback cache mellett, deadline IO ütemezővel. Ezen már nem sok tuningolási lehetőség van… Itt egyértelműen az ESX szerver ad ki olyan kéréseket, amik kicsik, avqrq-sz mindössze 8.00 kB, tehát a readahead nem segít. Emellett rossz a lokalitásuk, tehát a cache nem segít. Ráadásul egyesével jönnek a kérések, mint ahogy azt már feljebb is láthattuk, itt is csak 2 körüli a várakozási sor hossza (avgqu-sz), tehát az IO ütemező teljesen tehetetlen, nem tud optimalizálni semmit. Másképpen nézve ugyanez toppal:
top - 17:47:03 up 67 days, 6:09, 1 user, load average: 0.89, 1.00, 0.99 Tasks: 156 total, 1 running, 155 sleeping, 0 stopped, 0 zombie Cpu0 : 0.0%us, 0.3%sy, 0.0%ni, 6.6%id, 93.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu1 : 0.0%us, 0.7%sy, 0.0%ni, 93.4%id, 5.3%wa, 0.0%hi, 0.7%si, 0.0%st Mem: 2059236k total, 2048616k used, 10620k free, 1812760k buffers Swap: 2097144k total, 144k used, 2097000k free, 97592k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1820 root 10 -5 0 0 0 S 0.3 0.0 102:36.12 md2_raid5 8063 root 10 -5 0 0 0 S 0.3 0.0 0:16.82 istd4 17288 root 15 0 12736 1116 816 R 0.3 0.1 0:00.13 top 1 root 15 0 10344 648 552 S 0.0 0.0 0:01.47 init
Az iscsi target daemon szálaiból csak egy aktív, pedig akár 8 szál is mehetne. Ez egybevág az 1-es sorhosszal kapcsolatos eddigi megfigyelésekkel. Borzasztó látvány a 93%-os IOWait CPU idő is. Próbálkoztam a több IO ütezővel, különösen az anticipatory schedulertől vártam javulást, amit pont ilyen esetekre találtak, hiszen megpróbálja előre becsülni a még be nem érkezett kéréseket is. Semmit nem javított, ami tovább erősítette a gyanút, hogy teljesen véletlenszerű helyekre érkeznek a kérések. Talán valami swappol? A Shelob belül nem swappolt, ez biztosan látszott volna. Ezen kívül a VI client VMware Tools: OK jelzést mutat, ami azt jelenti, hogy a memory ballooning meghajtó működik, memória kifogyásnál ennek elsőbbsége van a swappeléssel szemben.
Vissza az aragornra az esxtop-pal, ezúttal az memória statisztikára ‘m’ billentyűvel, majd ‘f’ és a SWAP oszlopcsoport beválasztásával:
4:37:31pm up 67 days 5:57, 109 worlds; MEM overcommit avg: 0.16, 0.16, 0.17 PMEM /MB: 20479 total: 272 cos, 299 vmk, 13469 other, 6438 free VMKMEM/MB: 19929 managed: 1195 minfree, 2467 rsvd, 17316 ursvd, high state COSMEM/MB: 9 free: 541 swap_t, 491 swap_f: 0.00 r/s, 0.00 w/s PSHARE/MB: 4154 shared, 714 common: 3440 saving SWAP /MB: 2156 curr, 8 target: 0.34 r/s, 0.00 w/s MEMCTL/MB: 168 curr, 168 target, 7955 max GID NAME MEMSZ SZTGT TCHD %ACTV %ACTVS %ACTVF %ACTVN SWCUR SWTGT SWR/s SWW/s 15 vmware-vmkauthd 5.58 5.58 1.93 0 0 0 0 0.00 0.00 0.00 0.00 16 Balrog 2048.00 1907.09 266.24 7 5 6 2 0.00 0.00 0.00 0.00 20 Alnitak 1536.00 1128.40 150.42 9 6 8 4 1.96 0.68 0.00 0.00 37 Gorbag 512.00 464.40 15.36 0 0 0 0 284.49 0.00 0.00 0.00 50 Shelob 3072.00 3006.20 1044.48 31 8 24 19 1116.38 0.00 0.34 0.00 59 Uglug 2048.00 1876.85 102.40 3 2 3 2 420.87 0.00 0.00 0.00 67 TaddmImage 3072.00 3020.48 829.44 25 23 24 9 0.00 0.00 0.00 0.00 68 ProjectWiki 512.00 509.26 10.24 2 1 2 2 223.01 7.84 0.00 0.00 78 PseudoSalvador 4096.00 2803.11 40.96 0 0 0 0 109.05 0.00 0.00 0.00 [...]
“Van különbség elmélet és gyakorlat között? Elméletileg nincs, de gyakorlatilag nagyon is van.” – tartja a bölcs mondás, a HUP-on egy ember aláírásából. Hát itt az élő példa rá. Az SWCUR bizony azt mutatja, hogy most éppen 1,1GB memória van swapra írva. A SWTGT, vagyis a megcélzott kilapozandó memória mérete viszont 0, vagyis korábban volt valami oka, de most már elmúlt. Az SWR/s, nos ez swap read-in rate, ez a rejtélyes folyamatos olvasás forrása. Nagyon lassacskán, kb 600kB/s-el csorog visszafelé swapról a memória tartalma. A szerencsétlen mit sem sejtő Shelob az scp-vel másolt adatokat a memóriban akarja cache-elni, ezáltal hozzáér a kilapozott memórialapokhoz. Ezeket egyesével szedi be az vmm, addig pedig felfüggeszti a guest gép futtatását, amíg nem tudja alárakni a hiányzó memórialapot. Mindezt meglepően szép egyenletes ütemben. Látható ugyanez másik ábrán is, a VI Clientből nézve:
Azt hiszem innentől kezdve ez lesz az demonstrációs példa előadáson a memory ballooning hasznosságának magyarázatához. Már csak egy a kérdés: miért csinálja ezt? Erre is fény derült, hamarabb, mint gondoltam:
[xmi@shelob:~ ] sudo service vmware-tools status Password: vmware-guestd is running
Aha, tényleg?!
[xmi@shelob:~ ] sudo service vmware-tools restart Stopping VMware Tools services in the virtual machine: Guest operating system daemon: [ OK ] Virtual Printing daemon: [ OK ] Guest memory manager: [ OK ] VM communication interface socket family: [ OK ] VM communication interface: [ OK ] VMware Tools is installed, but it has not been (correctly) configured for the running kernel. To (re-)configure it, invoke the following command: /usr/bin/vmware-config-tools.pl.
Végülis nem hazudik, a guestd tényleg fut, de kb ez az egyetlen része, ami működik. Én viszont hazudtam, amikor azt írtam, hogy a VMware Tools: OK bármit is jelent a ballooning meghajtó működőképsségét illetően, ha nem is szándékosan, ez ugyanis engem is megvezetett. A kernel moduloknak bizony nagy híja van, nyilván a legutóbbi kernel update után elmaradt a vmware-config-tools.pl újbóli futtatása. Azért jó tudni, hogy erről a problémáról semmi, de semmi értesítésre nem számíthatok. Azt hiszem kell erre egy saját ágenst írnom, mert nem ez lesz az egyetlen virtuális gép, aminél ilyen előfordul.
Szintén tanulságos volt látni, hogy a valós IO terhelési értékek mennyire nem látszódnak át egy iSCSI kapcsolaton keresztül, és hasonlóképpen a külső swappolás következményei is teljesen mérhetetlenek a guest gépen belülről nézve.