|| @iamidly
-- a blog about sham, unix and software design. also i rant.

analysing the traffic data from a webserver with atools

my webserver collected a log with all accepted connections. here i will pick the log apart with the help of atools to figure out how the webserver can be made better while serving this very article.

this is the log format we have:

#!/usr/bin/env sham
let file? weblog = data/10147_metrics
atools aslize 1..5 < $weblog
  | ./into-html-table

echo $weblog contains $((acount < $weblog)) entries
echo its size is $((wc -c < $weblog)) bytes
@iamidly> sham /tmp/EXAMPLE_CODE_0_
#client#port#method#route#user-agent#time
83.252.199.9632957GETblew-my-mind.htmlMozilla0x6156ee4b
83.252.199.9632961GETindexMozilla0x6156eed0
83.252.199.9632961GETcracks-in-nix-philosophy.htmlMozilla0x6156eed1
83.252.199.9632964GETbasics-of-sham.htmlMozilla0x6156eedf
83.252.199.9632967GETbreak.htmlMozilla0x6156eeeb
data/10147_metrics contains 9195 entries its size is 544889 bytes

firstly we check which resources clients requested and how many times.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics
atools //- agroup :route .
                  :route count
                   .. first
           asv[route,count,..]
           acut :route,:count
           asort :count num rev
      -// < $weblog
  | ./into-html-table
@iamidly> sham /tmp/EXAMPLE_CODE_1_
#route#count
blew-my-mind.html5897
favicon.ico2843
index102
basics-of-sham.html48
apple-touch-icon.png36
apple-touch-icon-precomposed.png35
robots.txt34
none33
cracks-in-nix-philosophy.html31
million-glazed-eyes.html12
sham_atools.tar.gz12
read.html10
break.html9
write.html9
repeat.html8
exit.html8
apple-touch-icon-120x120.png8
apple-touch-icon-120x120-precomposed.png8
fn.html7
let.html6
continue.html5
null5
setpgid.html4
blew-my-mind.h…3
apple-touch-icon-152x152.png2
blew-my-mind.html/favicon.ico2
feed2
feeds2
apple-touch-icon-152x152-precomposed.png2
rss2
azenv.php1
rss/1
ArticleBookmark@2x.png1
favicon.png1
case.html1
error.html1
index/sham_atools.tar.gz1
blew-my-mind.html/trackback1
1111/feed/1
index.html1

favicon.ico is a mightily requested resource, one can conclude. 12 people found and clicked my download button. also some decided to continue reading.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics
let int? uniq = $((atools //- auniq :client
                              acount
                         -// < $weblog))

echo we had $uniq unique visitors
echo total number of requests $((acount < $weblog))
@iamidly> sham /tmp/EXAMPLE_CODE_2_
we had 4303 unique visitors
total number of requests 9195

most request from webclients seem to set persistent connections with the keep-alive. my webserver has a keep-alive window of 6 seconds; set high to lure out bugs quickly. i shall now use the logs to find a reasonably sized keep-alive window.
first we need to find out how many times the keep-alive window was in fact used by a follow-up request on the same connection.
we know that a keep-alive connection will have the same :client and :port on multiple requests, because the connection is persistent. we need simply filter on that.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics
let file? reused = $((mktemp))

atools //- acut :client,:port
           agroup :client,:port .
                  :client,:port count
           asv[..,count]
           afilter :count ne? 1
      -// < $weblog
          > $reused

echo total number of connections: $((atools auniq :client,:port acount < $weblog))
echo number of reused keep-alive connections: $((atools acount < $reused))

echo these are the routes that was included in a keep-alive connection:

atools //- ajoin :client,:port intersect ${{weblog}}
           acut :route
           agroup :route .
                  :route count
           asv[..,count]
           asort :count num rev
      -// < $reused
  | ./into-html-table

rm $reused
@iamidly> sham /tmp/EXAMPLE_CODE_3_
total number of connections: 7111
number of reused keep-alive connections: 1834
these are the routes that was included in a keep-alive connection:
#route#count
favicon.ico2082
blew-my-mind.html1674
index42
basics-of-sham.html21
apple-touch-icon.png16
cracks-in-nix-philosophy.html15
apple-touch-icon-precomposed.png14
apple-touch-icon-120x120.png8
apple-touch-icon-120x120-precomposed.png8
million-glazed-eyes.html6
robots.txt4
fn.html3
break.html3
let.html2
setpgid.html2
read.html2
write.html2
repeat.html2
apple-touch-icon-152x152.png2
blew-my-mind.html/favicon.ico2
apple-touch-icon-152x152-precomposed.png2
exit.html2
continue.html2
sham_atools.tar.gz1
error.html1

the majority of the requests on a keep-alive connection are requests for favicon.ico. the site didn't even have one, yet many clients asked insistently. some asked no less than 30 times/real request. so now i have added a favicon.ico, let's see if those clients become less unruly should i serve them one.

we try to alter our keep-alive time, to see when we hit a sweet spot between keep-alive and number of requests that fall within this window. we assume that a client will always use a keep-alive connection if it is open. this program will calculate the number of requests that could have belonged in a keep-alive window. we ignore :port but bundle all requests from the same :client, then we join this set onto itself where the :time difference is less than the keep-alive window.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics

let file? idips = $((mktemp))

//assign a uniq id to each ip so that we can join
//on :ip and :time. also give a :seq number to all entries
//in weblog so that we can filter off duplicates.
atools //- let all        { aparse - }
           let seqno      { aseq 1..(rows #all) asv[seq] apaste #all }
           let clients    { #all acut :client auniq :client }
           let idxclients { aseq 1..(rows #clients) asv[id] apaste #clients }

           #idxclients ajoin :client intersect #seqno
                       acut :id,:seq,:time,:client,:port,:method,:route,:user-agent,:time
                       asort :id num :port :seq num
      -// < $weblog
          > $idips

//we test how many keep-alive connections we could maximally
//have hoped for when we vary keep-alive-time between 1..16s
//and assume that clients make optimal use of the keep-alive
//feature.
{ write #keep-alive-time #max-connections
  atools //- aseq 1..8 afilter ${{'[ :a % 2 ]'}} asv[keep-alive-time] -//
    | foreach :keep-alive-time {

        let max-connections = $((atools //-
            let set { aparse - asort :id,:time num }
            #set ajoin ${{"[ :id == #id
                          && :seq != #seq
                          && :time - ${{keep-alive-time}} <= #time
                          && :time >= #time ]"}} intersect #set
            auniq :seq
            acount
       -// < $idips))

        write $keep-alive-time $max-connections
      }
} | ./into-html-table

rm $idips
@iamidly> sham /tmp/EXAMPLE_CODE_4_
#keep-alive-time#max-connections
14308
34457
54536
74584

it looks like a reasonable keep-alive window for this site may be as short as 1 second. note how slowly we increase in requests captured by the keep-alive window when keep-alive is greater than 1s. 6 seconds is most likely needlessly long and wasteful because every persistent connection block some other connection:

echo timing a single request:
time wget -O - http://orion.feralhosting.com:8888/blew-my-mind.html 2>&1 >/dev/null
//use the average of 80ms per request -> response from server
echo number of requests in 6 seconds: $((calc 'exact 6 / 0.080'))
@iamidly> sham /tmp/EXAMPLE_CODE_5_
timing a single request:
Connecting to orion.feralhosting.com:8888 (185.21.217.81:8888)

-                    100% |*******************************| 14500   0:00:00 ETA
real	0m 0.41s
user	0m 0.00s
sys	0m 0.00s
number of requests in 6 seconds: 75.

for each connection hogged by keep-alive we could have served ~70 sequential requests without persistency.

we simulate a 1 second keep-alive window, and see how many of our current keep-alive requests that are captured by this window. basically a join between our theoretical set and the actual set above. we hope for a big overlap. this happens if the requests on a persistent connection follows each other in rapid succession.

#!/usr/bin/env sham
let int? keep-alive = 1
let file? weblog = data/10147_metrics

let file? idips = $((mktemp))
let file? reused = $((mktemp))
let file? theoretical-keep-alive = $((mktemp))

//assign a uniq id to each ip so that we can join
//on :ip and :time
atools //- let all        { aparse - }
           let seqno      { aseq 1..(rows #all) asv[seq] apaste #all }
           let clients    { #all acut :client auniq :client }
           let idxclients { aseq 1..(rows #clients) asv[id] apaste #clients }

           #idxclients ajoin :client intersect #seqno
                       acut :id,:seq,:time,:client,:port,:method,:route,:user-agent,:time
                       asort :id num :port :seq num
      -// < $weblog
          > $idips

atools //- let all  { aparse - }
           let idps { #all acut :client,:port
                           agroup :client,:port .
                                  :client,:port count
                           asv[..,count]
                           afilter :count ne? 1
                    }
           #idps ajoin :client,:port intersect #all
     -// < $idips
         > $reused

atools //-
    let set { aparse - }
    #set ajoin ${{"[ :id == #id
                  && :seq != #seq
                  && :time - ${{keep-alive}} <= #time
                  && :time >= #time ]"}} intersect #set
         auniq :seq
-// > $theoretical-keep-alive
    < $idips


echo theoretical maximum: $((acount < $theoretical-keep-alive))

echo number requests on kept alive connection: $((acount < $reused))

echo overlap with theoretical set: $((atools //- ajoin :seq intersect ${{theoretical-keep-alive}}
                                                 acount
                                            -// < $reused))

echo ratio for ${{keep-alive}}s keep-alive window is: $(( calc "$((
atools //- ajoin :seq intersect ${{theoretical-keep-alive}}
           acount
 -// < $reused)) / $((acount < $reused)) * 100"))%

rm $idips $theoretical-keep-alive $reused
@iamidly> sham /tmp/EXAMPLE_CODE_6_
theoretical maximum: 4308
number requests on kept alive connection: 3918
overlap with theoretical set: 3032
ratio for 1s keep-alive window is: 77%

now we have concluded that the keep-alive can indeed be reduced with just a slight increase in new connections.

what about plots then?

plots are fun. let's create a plot. we will plot the number of connections over time and see if something pops out.
the log is nearly 24 hours long, so we will have to estimate a resolution for the plot.

#!/usr/bin/env sham
calc 'int 60 * 24'
calc 'int 60 * 24 / 2'
calc 'int 60 * 24 / 4'
@iamidly> sham /tmp/EXAMPLE_CODE_7_
1440
720
360

if we create a bucket every two minutes we will get 720 data points to use for our plot. we generate a list for every second in 24 hours.

#!/usr/bin/env sham
//we generate a list with all the seconds in 24 hours
aseq 0..$((calc '60 * 60 * 24')) aslize 1..10
  | ./into-html-table

echo truncated data
@iamidly> sham /tmp/EXAMPLE_CODE_8_
#a
0
1
2
3
4
5
6
7
8
9
truncated data

we keep only the numbers evenly divisible by 120. that is the start of every second minute.

#!/usr/bin/env sham
//keep all the numbers that are a multiple of 120
atools //- aseq 0..$((calc '60 * 60 * 24'))
           afilter ${{'[ :a % 120 == 0 ]'}}
           aslize 1..10
      -//
  | ./into-html-table

echo truncated data
@iamidly> sham /tmp/EXAMPLE_CODE_9_
#a
0
120
240
360
480
600
720
840
960
1080
truncated data

now we need to find the first timestamp in the log so that we can offset the buckets to the correct timestamp.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics

read start < <((atools aslize 1..1 acut :time anohead < $weblog))
read end < <((atools aslize 0..0 acut :time anohead < $weblog))

echo start is: $start
echo end is: $end
@iamidly> sham /tmp/EXAMPLE_CODE_10_
start is: 0x6156ee4b
end is: 0x615834dd

we add this timestamp to our bucket, and also an end time for our bucket, and then we are finished. we keep the original second around, because it will be easier to plot than the hexadecimal timestamp.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics

read start < <((atools aslize 1..1 acut :time anohead < $weblog))

atools //- aseq 0..$((calc '60 * 60 * 24'))
           afilter ${{'[ :a % 120 == 0 ]'}}
      -// < $weblog
  | atools //- acalc ${{"asv[startt,endt,x] = [ hex :a + ${{start}}
                                              , hex #startt + 119
                                              , :a / 60 ]"}}
               aslize 1..10
          -//
  | ./into-html-table

echo truncated data
@iamidly> sham /tmp/EXAMPLE_CODE_11_
#startt#endt#x
0x000000006156ee4b0x000000006156eec20
0x000000006156eec30x000000006156ef3a2
0x000000006156ef3b0x000000006156efb24
0x000000006156efb30x000000006156f02a6
0x000000006156f02b0x000000006156f0a28
0x000000006156f0a30x000000006156f11a10
0x000000006156f11b0x000000006156f19212
0x000000006156f1930x000000006156f20a14
0x000000006156f20b0x000000006156f28216
0x000000006156f2830x000000006156f2fa18
truncated data

now this is our bucket set. now we simply need to join the buckets with $weblog where :time >= :startt and :time < :endt.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics
let file? buckets = $((mktemp))

read start < <((atools aslize 1..1 acut :time anohead < $weblog))

atools //- aseq 0..$((calc '60 * 60 * 24'))
           afilter ${{'[ :a % 120 == 0 ]'}}
      -// < $weblog
  | acalc ${{"asv[startt,endt,x] = [ hex :a + ${{start}}
                                   , hex #startt + 119
                                   , :a / 60 ]"}}
  > $buckets


atools //- ajoin ${{'[ :startt <= #time && :endt > #time ]'}} intersect ${{weblog}}
           aslize 1..12
      -// < $buckets
  | ./into-html-table

echo truncated data
rm $buckets
@iamidly> sham /tmp/EXAMPLE_CODE_12_
#startt#endt#x#client#port#method#route#user-agent#time
0x000000006156ee4b0x000000006156eec2083.252.199.9632957GETblew-my-mind.htmlMozilla0x6156ee4b
0x000000006156eec30x000000006156ef3a283.252.199.9632961GETindexMozilla0x6156eed0
0x000000006156eec30x000000006156ef3a283.252.199.9632961GETcracks-in-nix-philosophy.htmlMozilla0x6156eed1
0x000000006156eec30x000000006156ef3a283.252.199.9632964GETbasics-of-sham.htmlMozilla0x6156eedf
0x000000006156eec30x000000006156ef3a283.252.199.9632967GETbreak.htmlMozilla0x6156eeeb
0x000000006156eec30x000000006156ef3a283.252.199.9632967GETfn.htmlMozilla0x6156eeef
0x000000006156eec30x000000006156ef3a283.252.199.9632968GETexit.htmlMozilla0x6156ef08
0x000000006156eec30x000000006156ef3a283.252.199.9632969GETblew-my-mind.htmlMozilla0x6156ef11
0x000000006156ef3b0x000000006156efb2483.252.199.9632972GETblew-my-mind.htmlMozilla0x6156ef63
0x000000006156ef3b0x000000006156efb2449.204.187.24010752GETblew-my-mind.htmlMozilla0x6156ef66
0x000000006156ef3b0x000000006156efb2449.204.187.24010752GETfavicon.icoMozilla0x6156ef66
0x000000006156ef3b0x000000006156efb24172.58.171.16257029GETblew-my-mind.htmlMozilla0x6156ef66
truncated data

now we group the set on :startt to get the connection count in the bucket.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics
let file? buckets = $((mktemp))

read start < <((atools aslize 1..1 acut :time anohead < $weblog))

atools //- aseq 0..$((calc '60 * 60 * 24'))
           afilter ${{'[ :a % 120 == 0 ]'}}
      -// < $weblog
  | acalc ${{"asv[startt,endt,x] = [ hex :a + ${{start}}
                                   , hex #startt + 119
                                   , :a / 60 ]"}}
  > $buckets

atools //- ajoin ${{'[ :startt <= #time && :endt > #time ]'}} intersect ${{weblog}}
           acut :startt
           agroup :startt .
                  :startt count
           asv[..,count]
           aslize 1..32
      -// < $buckets
  | ./into-html-table

echo truncated data

rm $buckets
@iamidly> sham /tmp/EXAMPLE_CODE_13_
#startt#count
0x000000006156ee4b1
0x000000006156eec37
0x000000006156ef3b12
0x000000006156efb313
0x000000006156f02b5
0x000000006156f0a315
0x000000006156f11b18
0x000000006156f1938
0x000000006156f20b13
0x000000006156f28312
0x000000006156f2fb12
0x000000006156f37316
0x000000006156f3eb4
0x000000006156f4635
0x000000006156f4db7
0x000000006156f55311
0x000000006156f5cb8
0x000000006156f6433
0x000000006156f6bb6
0x000000006156f733139
0x000000006156f7ab198
0x000000006156f823493
0x000000006156f89b253
0x000000006156f913186
0x000000006156f98b381
0x000000006156fa03243
0x000000006156fa7b210
0x000000006156faf3159
0x000000006156fb6b165
0x000000006156fbe3201
0x000000006156fc5b67
0x000000006156fcd3122
truncated data

lastly we implement into-html-plot that compiles data into javascript and html to draw a fancy plot. if you are interested the highlight points to the file.

#!/usr/bin/env sham
let file? weblog = data/10147_metrics
let file? buckets = $((mktemp))

read start < <((atools aslize 1..1 acut :time anohead < $weblog))

atools //- aseq 0..$((calc '60 * 60 * 24'))
           afilter ${{'[ :a % 120 == 0 ]'}}
      -// < $weblog
  | acalc ${{"asv[startt,endt,x] = [ hex :a + ${{start}}
                                   , hex #startt + 119
                                   , :a / 60 ]"}}
  > $buckets

atools //- ajoin ${{'[ :startt <= #time && :endt > #time ]'}} intersect ${{weblog}}
           acut :x
           agroup :x .
                  :x count
           asort :x num
           asv[..,count]
      -// < $buckets
  | ./into-html-plot -x :x -y :count

rm $buckets
@iamidly> sham /tmp/EXAMPLE_CODE_14_



unfortunately this did not tell me much except for that the window to fame on hackernews is short and steep. but now i have a tool to generate shitty plots.

|| come join me at #sham on irc.snoonet.net
</post>