Introduzione a LogParser
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:
Input Formats | |
---|---|
ADS | Restituisce proprietà relative ad oggetti contenuti in Active Directory |
BIN | IIS logs in formato Centralized Binary Log File |
COM | Fornisce un’interfaccia per Custom Input Format COM Plugins |
CSV | Log in formato testo separato da virgole |
ETW | Formato per Enterprise Tracing for Windows (file .etl) e trace di sessioni live ETW |
EVT | Usato per leggere gli eventi dal Windows Event Log (sia dalla macchina locale che da una remota) e file .evt |
FS | Informazioni riguardo gli oggetti del File System (file e cartelle) |
HTTPERR | Log creati dal driver Http.sys (HTTP Error logs) |
IIS | Log di IIS nel formato nativo Microsoft (IIS Log File Format) |
IISODBC | Restituisce le informazioni dalle tabelle utilizzare quando IIS è configurato per salvare i log nel formato ODBC Log |
IISW3C | Usato per i log di IIS nel formato W3C Extended Log File Format (questa è la modalità di logging di default di IIS) |
NCSA | Usato per file in formato NCSA (nelle tre modalità Common, Combined ed Extended). Il formato NCSA è basato su campi a lunghezza fissa separati da spazi |
NETMON | Permette l’analisi di trace di rete (file .cap) prodotte con Network Monitor |
REG | Usato per fare query sul registro di sistema |
TEXTLINE | Restituisce righe di testo da file di testo generici |
TEXTWORD | Restituisce parole (words) da file di testo generici |
TSV | Gestisce file con valori separati da tab o da spazi |
URLSCAN | Usato per fare query su file generati da URLScan |
W3C | Gestisce file in formato W3C Extended Log File Format |
XML | Usato per gestire file in formato XML |
Output Formats | |
CHART | Usato per creare grafici; è necessario installare gli Office Web Components |
CSV | Log in formato testo separato da virgole |
DATAGRID | Mostra i record in una finestra grafica con una griglia tipo GridView |
IIS | Log di IIS nel formato nativo Microsoft (IIS Log File Format) |
NAT | Scrive i record in un formato separato da tab rispettando l’allineamento delle colonne per una comoda leggibilità |
SQL | Scrive l’output in una tabella di Sql Server |
SYSLOG | Può essere usato per mandare messaggi ad un Syslog server, per creare file di testo contenenti messaggi di tipo Syslog e per mandare messaggi di tipo Syslog agli utenti |
TPL | Scrive l’output formattandolo in base ad un template definito dall’utente |
TSV | Scrive l’output in record separati da tab o da spazi |
W3C | Scrive file in formato W3C Extended Log File Format |
XML | Scrive l’output in un file XML |
Qualche esempio pratico
IIS
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.aspx
57452 98531 3 /content/page2.aspx
44000 44000 2 /testapp/embed.aspx
43781 43781 1 /testapp/testapphandler.aspx
41953 41953 2 /testapp/sample.aspx
36046 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 55984
htm 0 4640 247 928
mpeg 312 14453 8877 13
gif 0 792171 246 25881
ico 0 96734 691 2178
jpg 0 280859 1982 2694
pdf 0 1653156 6731 8752
css 0 63453 357 10284
js 0 73125 308 4719
html 0 32734 1214 2144
axd 0 88718 1324 1197
png 0 17593 794 458
[...]
Event Viewer
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.
Senior Support Engineer
EMEA IIS and Web Developer Support