For lidt over et år siden skrev jeg et tip om den dynamiske statement cache i DB2, og hvordan du kan trække information ud af den. I dette tip vil jeg komme nærmere ind på, hvordan du kan bruge den til at måle på et specifikt SQL statement. Denne teknik bruger jeg til at finde ud af, om en tuning af et SQL statement rent faktisk har den ønskede effekt. Husk at statement cachen kun virker for dynamisk SQL, så dette tip virker altså kun for dynamisk SQL.

For at kunne måle CPU forbruget af et SQL statement er det vigtigt at huske på, at det præcis samme SQL statement højst sandsynligt bruger mere CPU første gang det eksekveres end det gør efterfølgende. Det skyldes, at første gang læses data ind i bufferpool'en, mens data sandsynligvis allerede findes i bufferpool'en de efterfølgende gange, lidt afhængig af, hvor lang tid, der går mellem hver eksekvering. Disse ekstra læs af data kaldes synchronous reads.

En anden meget vigtig detajle er, at hvis to SQL statements er tekstmæssigt ens, så opfatter statement cachen de to statements som det samme statement. Hvis du gerne vil have en ny række i statement cachen for netop dit statement, så tilføj eksempelvis en konstant forrest i select listen, som du så kan ændre hver gang du ønsker en ny række i statement cachen. Hvis det ikke er en SELECT, du vil måle på, så brug i stedet QUERYNO 999 til sidst i statementet.

Når jeg skal måle på et SELECT statement, benytter jeg følgende fremgangsmåde:

1. Jeg indsætter en konstant forrest i SELECT listen eksempelvis '1.TIME'.
2. Jeg eksekverer SELECT statementet.
3. Jeg ændrer konstanten til 'N.TIME'.
4. Jeg eksekverer SELECT statementet fem gange hurtigt efter hinanden.

Jeg har nu skabt to nye rækker i statement cachen, en for første eksekvering, som får læst data ind i bufferpool'en, og en for de næste fem eksekveringer. Jeg gør det fem gange for at få en rimelig fornuftig måling, da der kan være mange faktorer, der spiller ind på CPU forbruget, som vi ikke kan påvirke. Ti gange giver en endnu bedre måling, men det gør jeg kun, hvis mit statement i forvejen bruger meget lidt CPU, og der derfor kan være større usikkerhed på CPU målingen, også selv om der måles i mikrosekunder.

Næste spændende skridt er selvfølgelig at trække data ud af statement cachen. Her vil jeg henvise til mit tidligere tip for, hvordan det gøres. Når statement cachen er populeret i DSN_STATEMENT_CACHE_TABLE, vil jeg dog anbefale følgende SELECT:

SELECT CHAR(STMT_TEXT, 30) STMT, STAT_EXEC EXECS, DECIMAL(STAT_CPU,10,6) CPU
     , STAT_GPAG GETPAGE, STAT_SYNR SYNCREAD
     , DECIMAL(STAT_ELAP,10,6) ELAPSED
FROM DSN_STATEMENT_CACHE_TABLE
WHERE CACHED_TS > CURRENT TIMESTAMP - 15 MINUTES
ORDER BY CACHED_TS DESC

Da statement cachen kan indeholde mange af de gamle statements, jeg har eksekveret, så har jeg sat en tidsbegrænsning på, så jeg kun ser dem for de sidste 15 minutter. Jeg kan altid variere denne tidsbegrænsning. Den øverste række skulle gerne være den med konstanten N.TIME og den næstøverste 1.TIME. Her kan DELETE FROM DSN_STATEMENT_CACHE snige sig ind, hvis du har fulgt min vejledning fra det tidligere tip. Den første kolonne indeholder de første 30 tegn af det SQL statement, som er registreret i statement cachen. Her kan du selv udvide, hvis du synes 30 tegn ikke er nok, men den indsatte konstant er i hvert fald med. Hvis 1.TIME eller N.TIME rækken mangler, så skyldes det sandsynligvis, at jeg har eksekveret præcis det samme statement bare mere end 15 minutter siden.

STMT_TEXT er en LOB kolonne, og derfor kan udtrykket CHAR(STMT_TEXT, 30) volde problemer for eksempel i SPUFI. Prøv her i stedet med SUBSTR(STMT_TEXT, 1, 30). I QMF er det lige omvendt, her vil SUBSTR(STMT_TEXT, 1, 30) volde problemer, mens CHAR-udgaven virker fint. Det skyldes, at programmørerne bag disse to produkter ikke har helt styr på håndteringen af LOB-kolonner.

Kolonnen EXECS (STAT_EXEC) angiver, hvor mange gange statementet er blevet udført, mens det har været i statement cachen. Her vil der stå 1 ud for 1.TIME og 5 ud for N.TIME, ellers er der fumlet med eksekveringerne. Kolonnen CPU vil vise det samlede CPU forbrug for alle eksekveringerne. Du skal altså dividere dette tal med EXECS, hvis du vil vide, hvad een eksekvering koster. Kolonnen GETPAGE (STAT_GPAG) viser det samlede antal getpages for alle eksekveringerne. Getpages er det antal pages i bufferpool'en, som statementet har besøgt. Flere besøg til samme page tæller een for for hvert besøg. Kolonnen SYNCREAD (STAT_SYNR) viser det samlede antal synchronous reads. Dette tal skal helst være nul for N.TIME rækken, ellers kan du ikke sammenligne CPU forbruget for et statement med et andet med mindre de to statements har udført samme antal SYNCREAD (hvilket kan være forbandet svært at opnå). Det er netop for at få nul i SYNCREAD kolonnen, at du skal udføre en første gangs eksekvering. Kolonnen ELAPSED viser den samlede tid, DB2 har brugt på eksekveringen.

Når du har målt på forskellige SQL statements, vil du hurtigt opdage, at jo flere getpages et statement udfører, desto mere CPU bruger det. At reducere antallet af getpages for et statement er altså den sikre vej til at få det til at bruge mindre CPU. Du vil sandsynligvis også opdage, at både CPU og ELAPSED går i vejret, så snart SYNCREAD er større end nul. Her ser du med andre ord tydeligt effekten af bufferpool'en.

Måske sidder du nu og spekulerer på, om CPU forbrug med mere til at finde accessvejen er medregnet i tallene fra statement cachen. Det er de ikke. Det er kun CPU, GETPAGE og så videre for selve eksekveringen efter, at accessvejen er bestemt, der medtages.