Hibajavítás a Claroline távoktatási rendszerben

D-val azt a feladatot kaptuk, hogy a Claroline nyílt forrású PHP/MySQL alapokra támaszkodó távoktatás keretrendszerben az ügyfél által észlelt problémát orvosoljuk. A hiba tárgya, hogy egy adott funkció elérésre (gyak. oldal betöltődése) az éles környezetben az adatbázis- és webkiszolgáló leállását, jobb esetben is 10–15 másodperces reakció időt produkált, amely az egyidejűleg a rendszerben tevékenykedő felhasználók számával csak romlott.

Az alábbiakban kronológiai sorrendben, időnk függvényében közöljük a nyomkövetés egyes fázisait, sejtéseinket, tapasztalatainkat, folyamatosan frissülő formában, míg el nem érjük a végső megoldást. A felhalmozódott tudást patch formájában az ügyfél kérésére a Claroline felé is visszajuttatjuk. A hibafelderítés, -javítás során visszajelzéseket szívesen veszünk, twit us.

Claroline minősége fejlesztői szemmel

Mielőtt a tényleges probléma feltárást megkezdenénk, elidőztünk a Claroline kódja felett egy keveset. A forráskód minősége, a szoftver topológiája leginkább a SugarCRM még open source ágából derivált vTiger CRM-et juttatta eszembe. Ha mostanában a DZone-os hype szerint MVC kialakítás szerint világítanánk át a keretrendszert, alig találnánk olyan ismérvet a programban, ami a legcsekélyebb módon is eleget tenne a modell követelményeinek. A programlogikát amúgy a zúzmókat majmolva szervesen egybegyúrták a HTML sablonokkal, de a bátortalanabbja már örülne annak is, ha templatingről beszélhetnénk ott, ahol az index.php felénél egy echo '<div style="text-align:center">'; fölött dermedt meg a kurzorom. Ha mindenáron MVC-ben akarunk gondolkodni, akkor a Claroline-nál a distributed controller megoldást választották a tervezők; nuke-os mintára minden funkcióhoz külön PHP szkript tartozik, ahol is minden fájl elején azzal megy a pöcsölés, hogy még mit lehet include-olni, mi van már betöltve satöbbi. Nevetséges.

Az átadott adatbázis dump visszatöltése előtt lekértem a böngészőben az alkalmazás címlapját, hogy szükséges-e bárminemű további beállítás alkalmazás szinten, mire az adatbázis megléte, ill. annak üressége következtében néhány oldalnyi hibaüzenet adta a tudomásomra, hogy dump nélkül ő bizony egy tapottat sem. Míg az első kivédhetetlen hibánál el nem hasalt az interpreter, át lehetett tekinteni mindazon hiányosságokat, amelyek az elvárt, ideális állapot feltételezésére engedtek következtetni a fejlesztők részéről, pedig még a foreach sem biztos, hogy mindig iterálható objektumot kap argumentumként.

Claroline teljesítmény mérése top, apachetop és mytop eszközökkel

Végül – egylőre – utolsó pontként a konfiguráció kapcsán volt rendkívül zavaró, hogy hol megkövetelte, hol pedig az útvonalak (path) záró perjelének mellőzésére kértek, nem értem, miért nem lehetett egységesen állást foglalni ebben a kérdésben.

Szoftver telepítése, tesztadatok betöltése

Az átadott konfigurációs állományokban speciális beállítást nem tapasztaltunk.

Az átadott Claroline instancia helyi telepítése közben feltűntek:

  • A csatolmányok fájlneveiben ékezetek találhatók, ez számos probléma forrása lehet a jövőben (vagy akár most is)
  • Adatbázis táblák latin1 ábrázolásúak, noha a bennük tárolt adatok latin2 kódolásúak

A hiba tárgyát képező problémát tapasztaltuk – a tesztkörnyezetünkön az adott funkció elérése 5-7 másodpercig, az éles rendszeren ez nagyjából 12-15 mp. A jelentősen reszponzívabb működés várhatóan abból fakad, hogy a tesztkörnyezetünkhöz kétmagos architektúra áll a rendelkezésünkre. Nem zárjuk ki, hogy megfelelő konfigurációval jobban közelíthető a két válaszidő egymáshoz.

A betöltődés során folyamatosan monitoroztuk az oldalt külöböző nyomkövető és terhelésmérő eszközökkel (apachetop, top, mytop, XDebug). A webszerverre és PHP feldolgozóra gyakorlatilag nem esett terhelés a funkció betöltődése során. Az adatbázis kiszolgálón észleltünk mérhető terhelést, egy “Beadandó feladat” oldal betöltése összesen 12 db lekérdezést intézett az RDBMS felé. Megfigyeltük, hogyha egyidejűleg több oldal betöltődését kezdeményezzük, az adatbázis kiszolgáló egyszerre csak az említett 12 lekérdezéssel foglalkozik, és amikor ezeket teljesítette, akkor kezdi el kielégíteni a következő “Beadandó feladat”-hoz tartozó adatkiszolgálásokat. Sejtésünk szerint olyan műveletet kér a Claroline az adatlekérdezés során, amely implicit vagy explicit zárolja (LOCK) az adatbázist további műveletek végzése elől.

Az alábbi két lekérdezés költsége volt jelentős a mysql-slow.log tanulsága szerint.

# Time: 080322 19:35:20
# Query_time: 7  Lock_time: 0  Rows_sent: 8  Rows_examined: 1923517
SELECT SQL_CALC_FOUND_ROWS `U`.`user_id`                        AS `authId`,
                   CONCAT(`U`.`nom`, ' ', `U`.`prenom`) AS `name`,
                   `S`.`title`,
                   COUNT(`S`.`id`)                      AS `submissionCount`,
                   COUNT(`FB`.`id`)                     AS `feedbackCount`,
                   max(`FB`.`score`)   AS `maxScore`

            #GET USER LIST
            FROM  `claroline`.`cl_user` AS `U`

            #ONLY FROM COURSE
            INNER JOIN  `claroline`.`cl_cours_user` AS `CU`
                    ON  `U`.`user_id` = `CU`.`user_id`
                   AND `CU`.`code_cours` = 'PED56'

            # SEARCH ON SUBMISSIONS
            LEFT JOIN `c_PED56_wrk_submission` AS `S`
                   ON ( `S`.`assignment_id` = 13 OR `S`.`assignment_id` IS NULL)
                  AND `S`.`user_id` = `U`.`user_id`
                  AND `S`.`original_id` IS NULL


             # SEARCH ON FEEDBACKS
            LEFT JOIN `c_PED56_wrk_submission` as `FB`
                   ON `FB`.`parent_id` = `S`.`id`


			GROUP BY `U`.`user_id`,
                     `S`.`original_id`
	ORDER BY submissionCount DESC, S.last_edit_date DESC, FB.last_edit_date DESC, CU.isCourseManager ASC, CU.tutor DESC, U.nom ASC, U.prenom ASC
	 LIMIT 380, 20;

# Time: 080322 19:35:22
# Query_time: 2  Lock_time: 0  Rows_sent: 131  Rows_examined: 429940
SELECT `S`.`user_id` as `authId`, `S`.`title`
    			FROM `c_PED56_wrk_submission` AS `S`
            LEFT JOIN `c_PED56_wrk_submission` AS `S2`
            	ON `S`.`user_id` = `S2`.`user_id`
            	AND `S2`.`assignment_id` = 13
            	AND `S`.`last_edit_date` < `S2`.`last_edit_date`
            WHERE `S2`.`user_id` IS NULL
                AND `S`.`original_id` IS NULL
                AND `S`.`assignment_id` = 13;

A probléma forrását a workList.php-ben kiindulva kell keresni és a jelek szerint adatbázis szinten lesz.

Valamennyi bizonytalan tényező kizárása érdekében a kritikus oldallekérést az Xdebuggal is monitoroztuk. Az eredmény értékeléséhez a KCacheGrindot használtuk. Kiválóan megfigyelhető, hogy a felhasznált időegység gyakorlatilag teljes egészét a mysql_query, ill. közvetve az azt meghívó wrapper függvények viszik el. Kétség immáron nem férhet hozzá, hogy elemeznünk, majd lehetőségekhez képest optimalizálnunk kell az SQL kifejezéseket.

More to come!