Tra gli strumenti che mi capita di usare più spesso nel mio lavoro c’è sicuramente LogParser, un tool alla riga di comando (per il quale però esistono alcune GUI che facilitano l’uso tramite un’interfaccia grafica) che tramite un linguaggio molto simile al T-SQL permette di analizzare log in formato testuale ma non solo; io lo trovo particolarmente utile per analizzare log di IIS ed i log dell’Event Viewer, ma l’utilizzo è in realtà più ampio e molto flessibile.
LogParser supporta un numero piuttosto ampio di formati di file sia in input che in output, ecco l’elenco completo per la versione 2.2:
Per fare un esempio pratico vorrei usare il campo time-taken che troviamo nei log di IIS: nelle versioni fino alle 6 era necessario abilitare esplicitamente questo valore nel log, fortunatamente dalla versione 7 in poi è invece abilitato di default:
Il campo time-taken misura il tempo necessario per l’esecuzione di una richiesta http: il timestamp viene inizializzato quando il server (meglio, il driver http.sys, il responsabile del logging in IIS) riceve il primo byte della richiesta proveniente dal client e comprende il tempo per completare l’elaborazione e spedire il risultato (la pagina richiesta). A partire da IIS 6 questo valore tiene conto anche del tempo di trasmissione sulla rete, questo perchè http.sys ferma il timer quando riceve conferma che il client ha ricevuto anche l’ultimo byte spedito. Usando questo valore (in combinazione con gli altri dati contenuti nei log di IIS) è possibile creare report, grafici e statistiche circa i tempi di esecuzione delle richieste http, aggregarli e manipolarli come più ci piace e ci serve.
Ad esempio per conoscere il tempo medio di esecuzione delle nostre pagine .aspx possiamo eseguire una query simile a questa:
logparser "SELECT AVG(time-taken) As AverageTimeTaken, MAX(time-taken) As MaxTimeTaken, COUNT(*) As Hits, TO_LOWERCASE(cs-uri-stem) As Uri INTO average_uri_execution_time.txt FROM ex*.log WHERE EXTRACT_EXTENSION(TO_LOWERCASE(cs-uri-stem)) = 'aspx' GROUP BY TO_LOWERCASE(cs-uri-stem) ORDER BY AverageTimeTaken DESC" -i:IISW3C -o:NAT -RTP:-1
Nota: il comando deve essere scritto ed eseguito in una riga singola, io l’ho diviso su più righe solo per migliorarne la leggibilità
Il risultato sarà qualcosa simile a questo:
AverageTimeTaken MaxTimeTaken Hits Uri ---------------- ------------ ---- -------------------------------65382 130359 2 /testapp/post.aspx57452 98531 3 /content/page2.aspx44000 44000 2 /testapp/embed.aspx43781 43781 1 /testapp/testapphandler.aspx41953 41953 2 /testapp/sample.aspx36046 36046 2 /testapp/connect.aspx[...]
Se avete i log organizzati in sotto cartelle (o se avete più siti sullo stesso server, ognuno dei quali con i log raggruppati in una cartella separata), usando il formato di input IISW3C è possibile elaborarli tutti in una volta sola aggiungendo il parametro “-recurse:-1” al comando qui sopra.
E se volessimo sapere quali sono le 10 pagine più lente del nostro sito?
logparser "SELECT TOP 10 time-taken, cs-uri-stem INTO top_time_taken.txt FROM ex*.log WHERE EXTRACT_EXTENSION(TO_LOWERCASE(cs-uri-stem))='aspx' ORDER BY time-taken DESC" -i:IISW3C -o:NAT -RTP:-1
Se invece fossimo interessati ad una specifica finestra temporale (ad esempio per capire cosa è stato loggato quando si è verificato un particolare problema sul server):
logparser "SELECT AVG(time-taken) As AverageTimeTaken, MAX(time-taken) As MaxTimeTaken, COUNT(*) As Hits, TO_LOWERCASE(cs-uri-stem) As Uri INTO date_range.txt FROM *.log WHERE TO_TIMESTAMP(date,time) BETWEEN TIMESTAMP('2009/05/27 10:11:00', 'yyyy/MM/dd hh:mm:ss') AND TIMESTAMP('2009/05/27 11:20:00', 'yyyy/MM/dd hh:mm:ss') GROUP BY TO_LOWERCASE(cs-uri-stem)" -i:IISW3C -RECURSE:-1 -o:NAT -RTP:-1
Infine, per sapere quali tipi di risorse (tipi di file) vengono serviti dal nostro IIS, quali sono i tempi di esecuzione e quanti file per ogni tipo (per ogni estensione) sono stati richiesti, possiamo eseguire questo:
logparser "SELECT TO_LOWERCASE(EXTRACT_EXTENSION(cs-uri-stem)) as ResourceType, MIN(time-taken) as MinTimeTaken, MAX(time-taken) as MaxTimeTaken, AVG(time-taken) as AvgTimeTaken, COUNT(*) as Hits INTO timers.txt FROM ex*.log GROUP BY ResourceType" -i:IISW3C -o:NAT -RTP:-1
Ed otterremo questo:
ResourceType MinTimeTaken MaxTimeTaken AvgTimeTaken Hits ------------- ------------ ------------ ------------ -----aspx 0 338750 673 55984htm 0 4640 247 928mpeg 312 14453 8877 13gif 0 792171 246 25881ico 0 96734 691 2178jpg 0 280859 1982 2694pdf 0 1653156 6731 8752css 0 63453 357 10284js 0 73125 308 4719html 0 32734 1214 2144axd 0 88718 1324 1197png 0 17593 794 458[...]
Cambiamo tipo di file in input. Capita spesso di aver bisogno di estrarre tutti i log per un particolare EventID dall’Event Viewer:
logparser "SELECT TimeWritten, SourceName, EventID, Message INTO eventid.txt FROM *.evt WHERE EventID = '1011'" -i:EVT -o:NAT -RTP:-1
Oppure possiamo convertire facilmente un file .evt in un file .csv ad esempio per poi filtrarlo con Excel (strano, ma so che c’è chi lo preferisce ):
logparser "SELECT * INTO System.csv FROM System.evt" -i:EVT -o:CSV
Nota: su Vista, Windows 2008 e Windows 7 prima di poter leggere da LogParser un file in formato .evt è necessario convertirlo nel nuovo formato .evtx con questo comando:
wevtutil epl application.evt application.evtx /lf:true
Spero di aver stuzzicato un po’ l’interesse per questo strumento potente e flessibile, in un prossimo post mostrerò altri query d’esempio e come creare grafici.
Carlo Cardella Senior Support Engineer EMEA IIS and Web Developer Support