Idle Hacking

I did some testing on a really fast machine today. It's Dell PowerEdge 2900.
It has two:

• CPU:2x: Quad Core Intel® Xeon® E5410, 2x6MB Cache, 2.33GHz, 1333MHz FSB
• Memory:8GB 667MHz (8x1GB), Dual Ranked DIMMs
• Disk:146GB 15K RPM Serial-Attach SCSI 3Gbps

Running mongrel-esi 0.5.4, load testing a page with 9 esi fragments

4 unique fragment servers

• frag1 sends 1,024 bytes and delays 0.05 before sending and is requested 3 times.
• frag2 sends 4,096 bytes with no extra delay and is requested 2 times.
• frag3 sends "<p>Hello there user</p>" with no extra delay and is requested 2 times.
• frag4 sends 4,096 bytes with no extra delay and is requested 2 times.

The origin server sends 38,448 bytes with no extra delay and a max age of 10 seconds.

Fragments are given a max-age between 1 and 3 seconds.

Here are the performance charts from mongrel-esi 0.4 to 0.5.4, running 1000 requests:

Setting up SyslogLogger is a really good idea.

sudo gem install SyslogLogger

# edit /etc/rsyslog.conf

!logtarget
*.* <tab><tab> /var/log/logtarget/production.log

# edit config/environments/production.rb

config.logger = RAILS_DEFAULT_LOGGER = SyslogLogger.new('logtarget')

References:

• syslog overview


• Logging rails to syslog with sysloglogger


• SyslogLogger

I just released a new version of rbtagger that includes a little feature called suggest. After loading the rule tagger, you can pass it a chunk of text and have it suggest key words to use for tagging. Here's how it works:

  require 'rbtagger'
  tagger = Brill::Tagger.new( 'LEXICON', 'LEXICALRULEFILE', 'CONTEXTUALRULEFILE' )
  tagger.suggest( File.read('sample.txt') )
=> [['doctor', 'NN', 3],['treatment','NN',5]]

The array returned contains the original word of interest, the part of speech, and the frequency of the term within the corpus. All it does is a simple reduction based on a maximum default of 10 tags. In this case, rbtagger picks all the nouns in the text and reduces until within the threshold of 10. Still this could be pretty useful for gathering terms of interest from a body of text. If you have any questions about rbtagger feel free to ask in the group I created for it.

I've been busy doing a lot of profiling and toning. I know it can be better and now it is. The graph below shows 2000 requests making 10 concurrent requests at a time. I'm comparing the latest version 0.5.1 to my previous version 0.4.2.

  sudo gem install mongrel-esi

check out the samples folder in the gem install or browse the project page for details on how to configure it.

Well, I'm out in California this week visiting my brother and helping my parents with the house. Not having a whole lot to do while we got grounded in Minneapolis, I worked on cleaning up mongrel esi. This new release checks for Surrogate-Control: max-age=xx, where xx is the amount of time in seconds you want to cache the page, it will still run the cached page through the ESI parser before serving it so any include tags that have expired will be refreshed. I'm measuring about a 2x improvement for cached pages. My sample page is now handling about 50 requests/second, up from 20 request/second. When I get back to a real network connection, I'll post some more numbers. For now please let me know if you find any bugs in this new release.

After a little time to relax this weekend, I decided it was time to improve the parser, by being smarter about how it buffers output. This means less code executing in ruby. Here's the same benchmarks I ran before, this time against the new parser and the current stable 0.4 release. I think the reason the standard deviation increased is due to more time being spent by the parser in C. I plan to work on this by having it call rb_thread_schedule, at specific times to give other ruby threads a chance to run - this should help smooth out the standard deviation.

Raw request times

Average request times

Standard Deviation

After a few months away from mongrel-esi, I decided it was time to finish some long standing improvements. Here's the list:

• Correctly handle max-age attribute


• Ragel 6.x compatibility


• Pipeline ESI fragment requests.

Correctly handling max-age attribute

It used to be hard coded to 600 milliseconds. Now setting max-age attribute on <esi:include tag will set the cache ttl for that fragment correctly. This means it's easy to load test without caching or with caching.

Ragel 6.x compatibility

There was a change in how ragel handles EOF. The fix was minor and doesn't break compatibility with ragel 5.x.

Pipeline ESI Fragment Reqeusts

The pipeline work, that I started here - has increased the servers response time stability, but slightly reduced it's average response time under load. I'm still tweaking to figure out if I can increase the concurrency further to get an even faster average - under load. I should be making another gem release in the next week, with those improvements. For now, have a look at the numbers below - the standard deviation graph and the raw response time graph show the improved response stability.

Average Request time

Standard Deviation

The Raw Data

One explanation for the increased average is that more users are a getting partial bits of the page faster, but because more requests are getting equal response time the whole is slower. Where as the serial server favored a single request at a time - the pipelined favors all requests equally giving everyone some bits immediately, but taking longer to server them all out. I need to do some more thorough analysis to verify this idea. I could for example measure the amount of time it takes to get the first chunk from each server....

Next I plan on bringing the average request time down even further - the goal being to bring the pipelined average below the serial version. For now stay tuned, more to come...

I started to put together some benchmarks to validate my work on evdispatch. Here's what I have so far...

Curb as a pure C extension runs on the main ruby thread, meaning no ruby threads can be schedule while it's blocking. It uses the easy curl interface meaning it's all blocking. This makes it very easy to use and for single requests it's great. For multiple requests, it's as though all the requests are made one after the other in serial.

Net::HTTP + Thread is really good, it runs fast and really doesn't start to show performance issues until it starts to exceed 20 concurrent requests.

Evdispatch is good for when you start to pass the 50 concurrent requests. It suffers from some stability issues at the moment, as time permits I'll work on fixing them.

Net::HTTp vs Evdispatch vs Curb for 50 concurrent requests.

Net::HTTP vs Evdispatch for 50 concurrent requests

Net::HTTP vs Evdispatch for 400 concurrent requests

The x axis is number of requests and the y axis is time per request. My benchmark code is here.. For most uses Net::HTTP should be plenty fast when making concurrent requests. I would definitely keep an eye on the rev.rubyforge.org project.

I've been doing a little work on mongrel-esi to improve it's concurrency. Here's a little test script I wrote to verify some of my thinking. The tricky part, is keeping all the bytes in the correct order, while still requesting as much as possible in parallel. Here's my thinking at the moment.

# reading a file
# as we read and encounter <esi:include src="/foo"/>
# spawn a thread and simulate requesting, but continue parsing the file looking for more on the main thread
# tweak the sleep calls to get different behavior...
require 'thread'

# define a sample buffer here:
input_stream = %Q(
  hello there world

  <esi:include src='/foo/'/>

  some more bytes here
  
  <esi:include src='/bar/'/>

  and some more here
)

# lets read line by line

count = 0
output = []
back_buffer = []
lock = Mutex.new
in_request = false
requesting = []
last_out = 0

input_stream.split("\n").each do|line|
  if line.match(/<esi:/)
    lock.synchronize do
      in_request = true
      back_buffer[count] = nil # reserve a location in back_buffer
    end
    requesting << Thread.new(count) do|id|
      sleep 0.4 # some busy work
      lock.synchronize do
        back_buffer[id] = "#{id}: sample"
        in_request = false
      end
    end
  else
    sleep 0.1
    lock.synchronize do
      if in_request 
        puts "buffering lines..."
        back_buffer[count] = "#{count}: #{line}"
      else
        # roll up requests
        puts "roll up requests..."
        i = 0
        until i == count
          o = back_buffer.shift
          output << o unless o.nil?
          i += 1
        end
        output << "#{count}: #{line}"
        last_out = count # mark the last buffer in back_buffer to be sent
      end
    end
  end
  count += 1
end
requesting.each do|t|
  t.join
end
# roll up requests
while !back_buffer.empty?
  o = back_buffer.shift
  output << o unless o.nil?
end

puts back_buffer.inspect
puts output.join("\n")

One obvious issue with this implementation is the number of threads per request is bounded by the response document.
Update: I've checked the above into svn, with a few updates

While I was very disappointed to miss railsconf this year, I was very excited to hear about Aaron's talk covering ESI. It was especially awesome to hear mongrel-esi mentioned. My plans for mongrel-esi so far are to improve it's concurrency further once I get evdispatch stabilized.