Editing Timeplot (section)

===Usage example on made-up data===

Suppose we've got a log of the following format:
 ...
 [2009-10-23 04:43:28,669] DEBUG 186.76.115.174 GET /product.php?id=46 200 24 Cache hit!
 [2009-10-23 04:43:29,175] DEBUG 178.188.73.231 GET /product.php?id=39 200 443 Cache miss!
 [2009-10-23 04:43:29,210] DEBUG 135.78.12.242 GET /basket.php 200 410 Cache miss!
 ...
 [2009-10-23 06:11:32,460] INFO Reloading product data started...
 ...
 [2009-10-23 10:54:22,610] INFO Reloading product data finished
 ...

And we're interested in the influence that product data reloading (a very lengthy process that reads data from a big file into memory) has on response time and on cache hit rate. We also think that the influence on response time might be different for different pages.

Let us decompose this log into the following tracks and events:
* One event track for index reloading
* One numeric track for each page type: response time
* One global discrete track for cache events: hit/miss
* One discrete track per page type for cache events: hit/miss

The following awk script will generate an input for timeplot:

 $ cat <<END >log.awk
 function t(){return $1 " " $2} 
 function p(){sub(/\?.*/,"",$6); return $6} 
 /GET/{print t() " =GET" p() " " $8; print t() "=PAGE `" p()} 
 /Cache hit/{print t() " =Cache `Hit"; print t() " =Cache" p() " `Hit"} 
 /Cache miss/{print t() " =Cache `Miss"; print t() " =Cache" p() " `Miss"} 
 /Reload.*start/{print t() " >Reload"} 
 /Reload.*finish/{print t() " <Reload"}
 END 

 $ awk -f log.awk /var/log/program.log > program.trace
 $ head program.trace
 [2009-10-23 04:43:28,669] =GET/product.php 24
 [2009-10-23 04:43:28,669] =Page `/product.php
 [2009-10-23 04:43:28,669] =Cache `Hit
 [2009-10-23 04:43:28,669] =Cache/product.php `Hit
 [2009-10-23 04:43:29,175] =GET/product.php 443
 [2009-10-23 04:43:29,175] =Page `/product.php
 [2009-10-23 04:43:29,175] =Cache `Miss
 [2009-10-23 04:43:29,175] =Cache/product.php `Miss
 [2009-10-23 04:43:29,210] =GET/basket.php 410
 [2009-10-23 04:43:29,210] =Page `/basket.php
 $ time tplot -o biglog.png -or 960x960 -k 'GET.*' 'quantile 300 0.25,0.5,0.75' -k 'Cache/.*' 'freq 300 stacked' \
   -k Cache 'freq 300 stacked' -k Reload event -k Page 'freq 300 stacked' \
   -if program.trace -tf 'date [%Y-%m-%d %H:%M:%OS]'
 real	0m2.631s
 user	0m2.500s
 sys	0m0.124s

Here is the [[:Image:Program.log.gz|log file]] and the [[:Image:Program.trace.gz|trace file]].

And here is what we get:

[[Image:Biglog.png|800px]]

We can make the following observations:
* Reloading product data seems to gradually take up memory and decrease efficiency of the cache
* Cache efficiency changes only for product.php
* Response time for product.php depends crucially on cache efficiency
* Quantiles of response time for product.php change sharply, not smoothly, at certain thresholds of cache hit rate.

(remember that the data is made up, and probably does not fairly represent the typical behavior of a web application)

All in all, this analysis leads to a thought that the first thing to fix in this program is memory efficiency and duration of data reloading, since it has a great impact on overall program performance.