Menu
How would I calculate time-based metrics (hourly average) based on log file data?
let me make this more clear, consider a log file that contains entries as follows: Each UIDs appears only twice in the log. they will be in embeded xml format. And they will likely appear OUT of sequence. And the log file will have data for only one day so only one day records will be there.
No of UIDs are 2 millions in log file.
I have to find out average hourly reponse time for these requests. Below has request and response in log file. UID is the key to relate b/w request and response.
2013-04-03 08:54:19,451 INFO [Logger] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><log-event><message-time>2013-04-03T08:54:19.448-04:00</message-time><caller>PCMC.common.manage.springUtil</caller><body><log-message-body><headers>&lt;FedDKPLoggingContext id="DKP_DumpDocumentProperties" type="context.generated.FedDKPLoggingContext"&gt;&lt;logFilter&gt;7&lt;/logFilter&gt;&lt;logSeverity&gt;255&lt;/logSeverity&gt;&lt;schemaType&gt;PCMC.MRP.DocumentMetaData&lt;/schemaType&gt;&lt;UID&gt;073104c-4e-4ce-bda-694344ee62&lt;/UID&gt;&lt;consumerSystemId&gt;JTR&lt;/consumerSystemId&gt;&lt;consumerLogin&gt;jbserviceid&lt;/consumerLogin&gt;&lt;logLocation&gt;Beginning of Service&lt;/logLocation&gt;&lt;/fedDKPLoggingContext&gt;</headers><payload>
&lt;ratedDocument&gt;
&lt;objectType&gt;OLB_BBrecords&lt;/objectType&gt;
&lt;provider&gt;JET&lt;/provider&gt;
&lt;metadata&gt;&amp;lt;BooleanQuery&amp;gt;&amp;lt;Clause occurs=&amp;quot;must&amp;quot;&amp;gt;&amp;lt;TermQuery fieldName=&amp;quot;RegistrationNumber&amp;quot;&amp;gt;44565153050735751&amp;lt;/TermQuery&amp;gt;&amp;lt;/Clause&amp;gt;&amp;lt;/BooleanQuery&amp;gt;&lt;/metadata&gt;
&lt;/ratedDocument&gt;
</payload></log-message-body></body></log-event>
2013-04-03 08:54:19,989 INFO [Logger] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><log-event><message-time>2013-04-03T08:54:19.987-04:00</message-time><caller>PCMC.common.manage.springUtil</caller><body><log-message-body><headers>&lt;fedDKPLoggingContext id="DKP_DumpDocumentProperties" type="context.generated.FedDKPLoggingContext"&gt;&lt;logFilter&gt;7&lt;/logFilter&gt;&lt;logSeverity&gt;255&lt;/logSeverity&gt;&lt;schemaType&gt;PCMC.MRP.DocumentMetaData&lt;/schemaType&gt;&lt;UID&gt;073104c-4e-4ce-bda-694344ee62&lt;/UID&gt;&lt;consumerSystemId&gt;JTR&lt;/consumerSystemId&gt;&lt;consumerLogin&gt;jbserviceid&lt;/consumerLogin&gt;&lt;logLocation&gt;Successful Completion of Service&lt;/logLocation&gt;&lt;/fedDKPLoggingContext&gt;</headers><payload>0</payload></log-message-body></body></log-event>
here is the bash script I wrote.
uids=cat $i|grep "Service" |awk 'BEGIN {FS="lt;";RS ="gt;"} {print $2;}'| sort -u
for uid in ${uids}; do
count=`grep "$uid" test.log|wc -l`
if [ "${count}" -ne "0" ]; then
unique_uids[counter]="$uid"
let counter=counter+1
fi
done
echo ${unique_uids[@]}
echo $counter
echo " Unique No:" ${#unique_uids[@]}
echo uid StartTime EndTime" > $log
for unique_uids in ${unique_uids[@]} ; do
responseTime=`cat $i|grep "${unique_uids}" |awk '{split($2,Arr,":|,"); print Arr[1]*3600000+Arr[2]*60000+Arr[3]*1000+Arr[4]}'|sort -n`
echo $unique_uids $responseTime >> $log
done
And the output should be like this Operation comes from id, Consumer comes from documentmetadata and hour is the time 08:54:XX So if we have more than one request and response then need to average of the response times for requests came at that hour.
Operation Consumer HOUR Avg-response-time(ms)
DKP_DumpDocumentProperties MRP 08 538
354
Given your posted input file:
$ cat file
2013-04-03 08:54:19,989 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;904c-be-4e-bbda-3e62&lt;/UId&gt;&lt;</body></event>
2013-04-03 08:54:39,389 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;904c-be-4e-bbda-3e62&lt;/UId&gt;&lt;</body></event>
2013-04-03 08:54:34,979 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;edfc-fr-5e-bced-3443&lt;/UId&gt;&lt;</body></event>
2013-04-03 08:55:19,569 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;edfc-fr-5e-bced-3443&lt;/UId&gt;&lt;</body></event>
This GNU awk script (you are using GNU awk since you set RS to a multi-character string in the script you posted in your question)
$ cat tst.awk
{
date = $1
time = $2
guid = gensub(/.*;gt;([^&]+).*/,"\\1","")
print guid, date, time
}
will pull out what I THINK is the information you care about:
$ gawk -f tst.awk file
904c-be-4e-bbda-3e62 2013-04-03 08:54:19,989
904c-be-4e-bbda-3e62 2013-04-03 08:54:39,389
edfc-fr-5e-bced-3443 2013-04-03 08:54:34,979
edfc-fr-5e-bced-3443 2013-04-03 08:55:19,569
The rest is simple math, right? And do it in this awk script - don't go piping the awk output to some goofy shell loop!
90
Extending Ed Morton's solution:
function parse_time (date, time, newtime) {
gsub(/-/, " ", date)
gsub(/:/, " ", time)
gsub(/,.*/, "", time)
newtime = date" "time
return newtime
}
(gensub(/.*;gt;([^&]+).*/,"\\1","") in starttime) {
etime = parse_time($1, $2)
endtime[gensub(/.*;gt;([^&]+).*/,"\\1","")] = etime
next
}
{
stime = parse_time($1, $2)
starttime[gensub(/.*;gt;([^&]+).*/,"\\1","")] = stime
}
END {
for (x in starttime) {
for (y in endtime) {
if (x==y) {
diff = mktime(endtime[x]) - mktime(starttime[y])
diff = sprintf("%dh:%dm:%ds",diff/(60*60),diff%(60*60)/60,diff%60)
print x, diff
delete starttime[x]
delete endtime[y]
}
}
}
}
$ cat log.file
2013-04-03 08:54:19,989 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;904c-be-4e-bbda-3e62&lt;/UId&gt;&lt;</body></event>
2013-04-03 08:54:34,979 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;edfc-fr-5e-bced-3443&lt;/UId&gt;&lt;</body></event>
2013-04-03 08:54:39,389 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;904c-be-4e-bbda-3e62&lt;/UId&gt;&lt;</body></event>
2013-04-03 08:55:19,569 INFO [LOGGER] <?xml version="1.0" encoding="UTF-8" standalone="yes"?><event><body>&lt;UId&gt;edfc-fr-5e-bced-3443&lt;/UId&gt;&lt;</body></event>
$ awk -f script.awk log.file
904c-be-4e-bbda-3e62 0h:0m:20s
edfc-fr-5e-bced-3443 0h:0m:45s
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With
