Monday, December 21, 2009

Configuring Common Access Log Format in GlassFish v2 and v3

For a long time Matthew and I had a dilemma about changing the non-standard access log format used by GlassFish v2 and v3, to the commonly used common or combined format used by Apache.

GlassFish does allow one to specify the access log format, but how this works is not obvious. If one tries to create a formatting string, which should result in one of the Apache access log formats, the resulting output does contain all the specified fields and in the right order, but the field delimiters are not preserved from the formatting string and instead all the fields are quoted and separated by spaces. That's not quite what we want, especially if you plan to feed the logs into a log analyzer that expect the usual Apache syntax.

While getting Confluence wiki to run on GlassFish v3, I fetched the GF source code and since I already had it, I thought that it should be trivial to find out how the Access log format gets processed in GF.

To my big surprise, I found out that there are classes with very suspicious names: CommonAccessLogFormatterImpl, CombinedAccessLogFormatterImpl and DefaultAccessLogFormatterImpl. A minute later I also found this piece of code "hidden" in PEAccessLogValve:
    // Predefined patterns
   private static final String COMMON_PATTERN = "common";
   private static final String COMBINED_PATTERN = "combined";


   ...
   ...


   /**
    * Set the format pattern, first translating any recognized alias.
    *
    * @param p The new pattern
    */
   public void setPattern(String p) {
       if (COMMON_PATTERN.equalsIgnoreCase(p)) {
           formatter = new CommonAccessLogFormatterImpl();
       } else if (COMBINED_PATTERN.equalsIgnoreCase(p)) {
           formatter = new CombinedAccessLogFormatterImpl();
       } else {
           formatter = new DefaultAccessLogFormatterImpl(p, getContainer());
       }
   }


Whoa! So both Apache formats are implemented already and one just needs to know how to "unlock" them. The "common" and "combined" constants looked like the magic keywords to do just that, and sure enough, when one sets either of them as the formatting string, the log will contain the expected output.



You can also use asadmin to make this config change:
asadmin set server.http-service.access-log.format="combined"

After a restart the log now uses the requested format:
0:0:0:0:0:0:0:1%0 - - [21/Dec/2009:07:42:45 -0800] "GET /s/1722/3/_/images/icons/star_grey.gif HTTP/1.1" 304 0
0:0:0:0:0:0:0:1%0 - - [21/Dec/2009:07:42:45 -0800] "GET /images/icons/add_space_32.gif HTTP/1.1" 304 0
0:0:0:0:0:0:0:1%0 - - [21/Dec/2009:07:42:45 -0800] "GET /images/icons/feed_wizard.gif HTTP/1.1" 304 0
0:0:0:0:0:0:0:1%0 - - [21/Dec/2009:07:42:45 -0800] "GET /images/icons/people_directory_32.gif HTTP/1.1" 304 0
0:0:0:0:0:0:0:1%0 - - [21/Dec/2009:07:42:45 -0800] "GET /s/1722/3/_/images/icons/add_12.gif HTTP/1.1" 304 0


Believe it or not, this information is not documented anywhere in the official documentation, and even folks Matthew chatted with on Sun's internal support mailing lists had no clue about it. Ideally the GF documentation and UI should be updated to make changing the access log format as simple as it should be.

Oh btw, open source FTW, when documentation is lacking one can at least read the sources!

Sunday, December 20, 2009

Running Confluence on GlassFish v3

Even though Atlassian considers GlassFish to be an unsupported servlet container for Confluence, it is quite easy to use Confluence with GlassFish v2.1. In fact that's the container that I've been using for a long time during my Confluence and Confluence plugin development.

I've been monitoring progress of GlassFish v3 development for several months and noticed that at some point Confluence 2.x and 3.0.x stopped working due to conflicts between different versions of Apache Felix used by both GFv3 and Confluence.

Fortunately Confluence 3.1 now contains Felix v2.x (an upgrade from 1.x), which solves the previously mentioned issues. Excited about the change, I tried to deploy Confluence 3.1 to GFv3 (final) and observed that there are a few more issues that one needs to deal with. I filed these two bugs and one RFE against Confluence and provided patches that anyone can use to get Confluence to run with GFv3:

Once the patches are applied to the Confluence source code, build a war file in the usual way, deploy it to GFv3 and you should be good to go. (There is a harmless exception thrown when Confluence starts, more info, just ignore it)

Oh, and be sure to vote for CONF-6603 to get Atlassian to officially support GlassFish.

Saturday, November 14, 2009

Using Mercurial Bisect to Find Bugs

Yesterday I tried to find a regression bug in Grizzly that was preventing grizzly-sendfile from using blocking IO. I knew that the bug was not present in grizzly 1.9.15, but somewhere between that release and the current head someone introduced a changeset that broke things for me. Here is how I found out who that person was.

Grizzly is unfortunately still stuck with subversion, so the only thing (besides complaining) that I can do to make my life easier, is to convert the grizzly svn repo to some sane SCM, such as mercurial. I used hgsvn to convert the svn repo.

Once I had a mercurial repo, I wrote BlockingIoAsyncTest - a JUnit test for the bug. And that was all I needed to run bisect:
$ echo '#!/bin/bash                                                                          
mvn clean test -Dtest=com.sun.grizzly.http.BlockingIoAsyncTest' > test.sh
$ chmod +x test.sh
$ hg bisect --reset #clean repo from any previous bisect run
$ hg bisect --good 375 #specify the last good revision
$ hg bisect --bad tip #specify a known bad revision
Testing changeset 604:82e43b848ae7 (458 changesets remaining, ~8 tests)
517 files updated, 0 files merged, 158 files removed, 0 files unresolved
$ hg bisect --command ./test.sh #run the automated bisect
...
(output from the test)
...
...
...

[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESSFUL
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 9 seconds
[INFO] Finished at: Sat Nov 14 11:41:07 PST 2009
[INFO] Final Memory: 25M/79M
[INFO] ------------------------------------------------------------------------
Changeset 500:983a3fc2debe: good
The first good revision is:
changeset:   501:b5239bf9427b
branch:      code
tag:         svn.3343
user:        jfarcand
date:        Wed Jun 17 17:20:32 2009 -0700
summary:     [svn r3343] Fix for https://grizzly.dev.java.net/issues/show_bug.cgi?id=672
In under two minutes I found out who and with which revision caused all the trouble! Bisect is very useful for large projects, developed by multiple users, where the amount of code and changes is not trivial. Finding regressions in this way can save a lot of time otherwise spent by debugging.

The only caveat I noticed is that you need to create a shell script that is passed in as an argument to the bisect command. It would be a lot easier if I could just specify the maven command directly without the intermediate shell script.

Thursday, May 28, 2009

grizzly-sendfile to Become an Official Grizzly Module

After a chat with JFA about grizzly-sendfile's future, I'm pleased to announce today that grizzly-sendfile 0.4 will be the first version of grizzly-sendfile released as an official module of grizzly. This is a huge news for grizzly-sendfile and I believe an equally important news for grizzly and its community.

What this "merger" means for grizzly-sendfile:

  • great opportunity to extend the reach
  • opportunity to become the default static file handler in Grizzly
  • aspiration to become the default static file handler in GlassFish v3
  • more testing and QA
  • easier and faster access to grizzly developers and contributors

What this "merger" means for grizzly:

  • contribution of 1 year of research, development and testing time in the area of static http downloads
  • several times better performance and scalability of http static file downloads
  • built-in X-Sendfile functionality
  • better JMX instrumentation for http downloads
  • and more

If you can't wait for 0.4, go and get recently released version 0.3.

This is a great day for both projects! :-)

Project site: http://grizzly-sendfile.kenai.com/

Thursday, May 14, 2009

grizzly-sendfile 0.3 is out!

After a few months of late night hacking, grizzly-sendfile 0.3 is finally ready for prime time!

New features include:

I also started using kenai's JIRA for issue tracking. So feel free to file bugs or RFE's there.

Benchmark & Enjoy!

Project Website The source code The binaries

Sunday, May 10, 2009

grizzly-sendfile and Comparison of Blocking and NonBlocking IO

From the very early beginnings of my work on grizzly-sendfile (intro) I was curious to compare blocking and non-blocking IO side to side. Since I didn't have any practical experience to understand which one would be more suitable when, I designed grizzly-sendfile to be flexible so that I could try different strategies and come to conclusions based on some real testing rather than theorizing or based on the words of others. In this post I'd like to compare blocking and nonblocking IO, benchmark them, and draw some conclusions as to which one is more suitable for specific situations.

grizzly-sendfile has a notion of algorithms that control the IO operations responsible for writing data to a SocketChannel (grizzly-sendfile is based on NIO and leverages lots of great work put into grizzly). Different algorithms can do this in different ways, and this is explained in depth on the project wiki. The point is that this allows me to create algorithms that use blocking or nonblocking IO in different ways, and easily swap them and compare their performance (in a very isolated manner).

Two algorithms I implemented right away were SimpleBlockingAlgorithm (SBA) and EqualNonBlockingAlgorithm (ENBA), and only recently followed by EqualBlockingAlgorithm (EBA). The first one employs the traditional approach of sending a file via the network (while not EOF write data to a SocketChannel using blocking writes), while ENBA uses non-blocking writes and Selector re-registration (in place of blocking) to achieve the same task. This means that a download is split into smaller parts, each sequentially streamed by an assigned worker thread to the client. EBA works very similarly to ENBA, but uses blocking writes.

I ran two variations of my faban benchmark[0] against these three algorithms. At first I made my simulated clients hit the server as often as possible and download files of different sizes as quickly as possible. Afterward I throttled the file download speed to 1MB/s per client (throttling was done by clients). While the first benchmark simulates traffic close to the one on the private network in a datacenter, the second benchmarks better represents client/server traffic on the Internet.

grizzly-sendfile delegates the execution of the selected algorithm to a pool of worker threads, so the maximum number of the treads in the pool, along with the selected algorithm, are one of the major factors that affects the performance[1] and scalability[2] of the server. In my tests I kept the pool size relatively small (50 threads), in order to easily simulate situations when there are more concurrent requests than the number of workers, which is common during traffic spikes.

Conc. ClientsDownload limitAlgorithmAvg init time[3] (sec)Avg speed[4] (MB/s)Avg total throughput (MB/s)
50noneSBA0.0194.36208.76
50noneENBA0.0214.15198.79
50noneEBA0.0184.23202.29
100noneSBA4.6664.32212.79
100noneENBA0.0481.84168.15
100noneEBA0.1401.96175.71
200noneSBA14.2884.31208.59
200noneENBA0.1080.87144.69
200noneEBA0.2640.97158.83


Conc. ClientsDownload limitAlgorithmAvg init time[3] (sec)Avg speed[4] (MB/s)Avg total throughput (MB/s)
501MB/sSBA0.0031.042.9
501MB/sENBA0.0020.9841.82
501MB/sEBA (81k)[5]0.0030.9841.91
501MB/sEBA (40k)[6]0.0020.9842.85
1001MB/sSBA20.51.040.4
1001MB/sENBA0.0030.9985.14
1001MB/sEBA (81k)0.0181.084.19
1001MB/sEBA (40k)0.0130.9984.34
2001MB/sSBA64.81.037.12
2001MB/sENBA0.1120.86141.8
2001MB/sEBA (81k)0.20.95156.59
2001MB/sEBA (40k)0.1590.96154.2
3001MB/sSBA113.91.034.2
3001MB/sENBA0.1850.58127.53
3001MB/sEBA (81k)0.310.61133.66
3001MB/sEBA (40k)0.2390.63132.75


The interpretation of the results is that with SBA the individual download speeds are slightly higher than when ENBA or EBA is used (this is mainly due to some extra scheduling related to the Selector reregistration). However, EBA and ENBA can utilize the available server bandwidth significantly better than SBA. This is especially true when there is a large number of slow clients downloading larger files. One big downside of SBA is that if the number of concurrent downloads is higher than the number of worker threads, the time to initiate download easily increases into extreme heights.

The conclusion is that SBA is well suited for controlled environments where there is a small number of fast clients (server-to-server communication on an internal network), while EBA shines in environments where there is very little control over the number and speed of clients (file hosting on the Internet). While EBA performs and scales better than ENBA, two advantages that ENBA has over EBA are smaller latency and higher resiliency to DoS or DDoS attacks when malicious clients open connections and block.

The results above do not represent well the performance and throughput of grizzly-sendfile (the benchmarks were run on my laptop!), but they certainly provide some evidence that can be used to determine characteristics of different algorithms. I'll do some more thorough testing later when I feel that grizzly-sendfile has enough features and it is time for some fine tuning (there is still a lot that can be done to make things more efficient).

I love explaining things visually, so I drew the following diagrams that describe the differences between the two algorithms much better than many words.

SimpleBlockingAlgorithm

The server can concurrently handle only the same number of requests as the number of worker threads in the pool. All the extra downloads have to be queued until one of some workers completes a download. The downloads take shorter to process, but the worker is blocked while a write is blocked. The slower the client the more blocking occurs and the worker utilization (and server throughput) goes down.

EqualNonBlockingAlgorithm

The number of downloads a server can concurrently handle is not limited by the number of workers. The downloads take slightly longer to process, but the workers are much better utilized. The increase in utilization is due to the fact that no blocking occurs and workers can multiplex - "pause" downloads for which clients are processing the data (stored in OS/network buffers). In the meantime workers can serve whichever client is ready to receive more data. This causes the download to be split into several parts, each possibly served by a different worker thread.

EqualBlockingAlgorithm

This algorithm is a combination of the previous two. It uses blocking IO and multiplexing. I think that thanks to multiplexing the client has more time to process data in OS/network buffers and thus deplete the buffer more than without multiplexing, which results in less blocking. The blocked writes are also more efficient because they decrease the number of parts a download is split into and thus decrease the amount of overhead associated with re-registration.

Based on these benchmarks, I'm going to call EqualBlockingAlgorithm the winner and make it the default grizzly-sendfile algorithm for now. It is quite easy to override this via the grizzly-sendfile configuration, so one will still be able to pick the algorithm that fits their deployment environment the best. To be honest the results of EBA benchmarks surprised me a bit because I expected ENBA to be the winner in throttled tests, so I'm really glad that I went into the trouble of creating and benchmarking it.

All this work will be part of the 0.3 release, which is due any day now. Follow the project on kenai and subscribe to the announce mailing list if you are interested to hear more news.



[0] a few notes on how I tested - both clients and the grizzly-sendfile-server were running on my mac laptop using Java 6 and server vm. I set the ramp up period to 1min so that the server can warm up and then I started counting downloads for 10min and calculated the result. Files used for the tests were 1KB, 200KB, 500KB, 1MB 20MB and 100MB large and equaly represented. All the tests passed with 0 errors. A download is successful when the length, md5 checksum and http headers match expected values.
[1] performance - ability to process a single download quickly
[2] scalability - ability to process large number of concurrent downloads at acceptable performance
[3] init time - duration from the time a request is made, until the first bytes of the http response body (not headers) are received
[4] avg speed - for 100MB files. The smaller the file the lower the effective download speed because of the overhead associated with a download execution.
[5] EBA (81k) - EqualBlockingAlgorithm with buffer size 81KB (the default socket buffer size on mac)
[6] EBA (40k) - EqualBlockingAlgorithm with buffer size 40KB

Tuesday, March 31, 2009

Identifying ThreadLocal Memory Leaks in JavaEE Web Apps

A few weeks ago wikis.sun.com powered by Confluence "Enterprise" Wiki grew beyond yet another invisible line that triggered intermittent instabilities. Oh boy, how I love these moments. This time the issue was that Confluence just kept on running out of memory. Increasing the heap didn't help, even breaking the 32bit barrier and using a 64bit JVM was not good enough to keep the app running for more than 24 hours.

The Xmx size of the heap suggested that something was out of order. It was time to take a heap dump using jmap and check what was consuming so much memory. I tried jhat to analyze the heap dump, but 3.5GB dump was just too much for it. The next tool I used was IBM's Heap Analyzer - a decent tool, which was able to read the dump, but consumed a lot of memory in order to do so (~8GB), and was pretty hard to use once the dump was processed.

While looking for more heap analyzing tools, I found SAP Memory Analyzer, now known as Eclipse Memory Analyzer, a.k.a MAT. I thought "What the heck does SAP know about JVM?" and reluctantly gave it a try, only to find out how prejudiced I was. MAT is a really wonderful tool, which was able to process the heap really quickly, visualize the heap in a easy-to-navigate way, use special algorithms to find suspicious memory regions, and all of that while using only ~2GB of memory. An excellent preso that walks through MAT features and how heap and memory leaks work, can be found here.

Thanks to MAT I was able to create two bug reports for folks at Atlassian (CONF-14988, CONF-14989). The only feature I missed was some kind of PDF or HTML export, but I did quite well with using Skitch to take screenshots and annotate them.

One of the leaks was confirmed right away, while it wasn't clear what was causing the other one. All we knew was that significant amounts of memory were retained via ThreadLocal variables. More debugging was in order.

I got this idea to create a servlet filter, that would inspect the thread-local store for the thread currently processing the request and log any thread-local references that exist before the request is dispatched down the chain and also when it comes back. Such a servlet could be packaged as a Confluence Servlet Filter Plugin, so that it is convenient to develop and deploy it.

There was only one problem with this idea, the thread-local store is a private field of the Thread class and is in fact implemented as an inner class with a package default access - kinda hard to get your hands on to. Thankfully private stuff is not necessarily private in Java, if you get your hands dirty with reflection code:
Thread thread = Thread.currentThread();

Field threadLocalsField = Thread.class.getDeclaredField("threadLocals");
threadLocalsField.setAccessible(true);

Class threadLocalMapKlazz = Class.forName("java.lang.ThreadLocal$ThreadLocalMap");
Field tableField = threadLocalMapKlazz.getDeclaredField("table");
tableField.setAccessible(true);

Object table = tableField.get(threadLocalsField.get(thread));

int threadLocalCount = Array.getLength(table);
StringBuilder sb = new StringBuilder();
StringBuilder classSb = new StringBuilder();


int leakCount = 0;

for (int i=0; i < threadLocalCount; i++) {
    Object entry = Array.get(table, i);
    if (entry != null) {
        Field valueField = entry.getClass().getDeclaredField("value");
        valueField.setAccessible(true);
        Object value = valueField.get(entry);
        if (value != null) {
            classSb.append(value.getClass().getName()).append(", ");
        } else {
            classSb.append("null, ");
        }
        leakCount++;
    }
}

sb.append("possible ThreadLocal leaks: ")
        .append(leakCount)
        .append(" of ")
        .append(threadLocalCount)
        .append(" = [")
        .append(classSb.substring(0, classSb.length() - 2))
        .append("] ");

logger.warn(sb);

A simple plugin like this, was able to confirm that the leaked SAXParser instances are created and stored as thread-local variables somewhere within the code that exports content as PDF. That is good enough info to pinpoint the exact line of code that creates the thread-local instance by BTrace (or code review), but that's a story for a separate blog post.

The morale of the story: ThreadLocal variables are a very powerful feature, which as is common for powerful stuff can result in a lot of nasty things when not used properly. Hopefully all the info I provided to Atlassian will be enough to get a speedy fix for the issue and bring stability to wikis.sun.com - at least until we step over the next "invisible line".

Thursday, February 05, 2009

Announcing grizzly-sendfile!

It's my pleasure to finally announce grizzly-sendfile v0.2 - the first stable version of a project that I started after I got one of those "Sudden Burst of Ideas" last summer.

For people who follow the grizzly development or mediacast.sun.com, this is not exactly hot news. grizzly-sendfile has been used by mediacast since last September and mentioned on the grizzly mailing list several times since then, but I haven't had time to promote it and explain what it does and how it works, so here I go.

If you don't care about my diary notes, skip down to "What is grizzly-sendfile".

A bit of background: the whole story goes back to the end of 2007 when a bunch of us where finishing up the rewrite of mediacast.sun.com in JRuby on Rails. At that time we realized that one of the most painful parts of the rewrite would be implementing the file streaming functionality. Back then Rails was single-threaded (not any more, yay!), so sending the data from rails was not an option. Fortunately, my then-colleague Peter, came up with an idea to use a servlet filter to intercept empty download responses from rails and stream the files from this filter. That did the trick for us, but it was a pretty ugly solution that was unreliable from time to time and was PITA to extend and maintain.

At around this time, I learned about X-Sendfile - a not well known http header - that some webservers (e.g. apache and ligttpd) support. This header could be used to offload file transfers from an application to the web server. Rails supports it natively via the :x_sendfile option of send_file method.

I started looking for the X-Sendfile support in GlassFish, which we have been using at mediacast, but it was missing. After some emails with glassfish and grizzly folks, mainly Jean-Francois, I learned that the core component of glassfish called grizzly could be extended via custom filters, which could implement this functionality.

The idea stuck in my head for a few weeks. I looked up some info on grizzly and NIO and then during one overnight drive to San Diego, I designed grizzly-sendfile in my head. It took many nights and a few weekends to get it into reasonable shape and test it under load with some custom faban benchmarks that I had to write, but in late August I had version 0.1 and was able to "sell" it to Rama as a replacement of the servlet filter madness that we were using at mediacast.

Except for a few initial bugs that showed up under some unusual circumstances, the 0.1 version was very stable. A few minor 0.1.x releases were followed by 0.2 version, which was installed on mediacast servers some time in November. Since then I've worked on docs and setting up the project at kenai.com.

What is grizzly-sendfile?

From the wiki: grizzly-sendfile is an extension for grizzly - a NIO framework that among other things powers GlassFish application server.

The goal of this extension is to facilitate an efficient file transfer functionality, which would allow applications to delegate file transfers to the application server, while retaining control over which file to send, access control or any other application specific logic.

How does it work?

By mixing some NIO "magic" and leveraging code of the hard working grizzly team, I was able to come up with an ARP (asynchronous request processing) filter for grizzly. This filter can be easily plugged in to grizzly (and glassfish v2) and will intercept all the responses that contain X-Sendfile header. The value of this header is the path of the file that the application that processed the request wants to send to the client.

All that an application needs to do is to set the header. In Java a simple example of such a code looks like this:
 response.setHeader("X-Sendfile", "/path/to/file.avi");
In Rails, it looks even nicer:
send_file '/path/to.png', :x_sendfile => true
That's it, grizzly-sendfile will take care of the rest.



Why should you care?


For me it was all about keeping my code clean and solving problems at layers where they made the most sense. Then it was also about performance and scalability - the kind of stuff that one can do with NIO, can't be now done in JavaEE because of its synchronous nature. And then of course it was about having full control over downloads (like successful download notification and other customizations that are possible via grizzly-sendfile plugins). Oh, and I must mention JMX monitoring:



What's next?

There is a lot of stuff on my roadmap. Two of the main missing features are partial downloads and glassfish v3 (grizzly 1.9.x) support. Then there is better monitoring and tons of performance and scalability tuning, which I haven't really focus on yet. A lot of the API still needs to be polished and cleaned-up. Also needed is a solid test suite that is more fine grained than the system/integration tests that I created with faban.

Can you use grizzly-sendfile?

Yeah, go for it. This is my pet project that I developed in my free time. The project is licensed under GPL2, so you can even grab the code if you want.

Can you help?

Sure. Code reviews, patches, suggestions and help with testing and documentation are more than welcome!

Saturday, January 31, 2009

Benchmarking JRuby on Rails

Last night, while working on a project I found a really neat use of Rails Components, but I also noticed that this part of Rails is deprecated, among other reasons because it's slow.

Well, how slow? During my quest to find out, I collected some interesting data, and even more importantly put JRuby and MRI Ruby face to face.

Disclaimer: the benchmarks were not done on a well isolated and specially configured test harness, but I did my best to gather data with informational value. All the components were used with OOB settings.

Setup

  • ruby 1.8.6 (2008-03-03 patchlevel 114) [universal-darwin9.0] + Mongrel Web Server 1.1.4
  • jruby 1.1.6 (ruby 1.8.6 patchlevel 114) (2008-12-17 rev 8388) [x86_64-java] + GlassFish gem version: 0.9.2
  • common backend: mysql5 5.0.75 Source distribution (InnoDB table engine, Rails pool set to 30)


Benchmarks

I used an excellent high quality benchmarking framework Faban for my tests. I was lazy, so I only used fhb (very similar to ab, but without its flaws) to invoke simple benchmarks:
  • simple request benchmark: bin/fhb -r 60/120/5 -c 10 http://localhost:3000/buckets/1
  • component request benchmark: bin/fhb -r 60/120/5 -c 10 http://localhost:3000/bucket1/object1
Both tests were run with JRuby as well as with RMI Ruby and in addition to that I ran the tests with Rails in single-threaded as well as multi-threaded modes. I didn't use mongler clusters or glassfish pooled instances - there was always only one Ruby instance serving all the requests.

Results

ruby 1.8.6 + mongrel
---------------------------------
simple action + single-threaded:
ops/sec: 210.900
% errors: 0.0
avg. time: 0.047
max time: 0.382
90th %: 0.095

simple action + multi-threaded:
ops/sec: 226.483
% errors: 0.0
avg. time: 0.044
max time: 0.180
90th %: 0.095

component action + single-threaded:
ops/sec: 132.950
% errors: 0.0
avg. time: 0.075
max time: 0.214
90th %: 0.130

component action + multi-threaded:
ops/sec: 131.775
% errors: 0.0
avg. time: 0.076
max time: 0.279
90th %: 0.125

jruby 1.2.6 + glassfish gem 0.9.2
----------------------------------
simple action + single-threaded:
ops/sec: 141.417
% errors: 0.0
avg. time: 0.070
max time: 0.259
90th %: 0.115

simple action + multi-threaded:
ops/sec: 247.333
% errors: 0.0
avg. time: 0.040
max time: 0.318
90th %: 0.065

component action + single-threaded:
ops/sec: 107.858
% errors: 0.0
avg. time: 0.092
max time: 0.595
90th %: 0.145

component action + multi-threaded:
ops/sec: 179.042
% errors: 0.0
avg. time: 0.055
max time: 0.357
90th %: 0.085


Platform/ActionSimple+/-Component+/-
Ruby ST 210ops0%132ops0%
Ruby MT226ops7.62%131ops-0.76%
JRuby ST141ops-32.86%107ops-18.94%
JRuby MT247ops17.62%179ops35.61%
(ST - single-threaded; MT - multi-threaded)

Conclusion

From my tests it appears that MRI is faster in single threaded mode, but JRuby makes up for the loss big time in the multi-threaded tests. It's also interesting to see that the multi-threaded mode gives MRI(green threads) a performance boost, but it's nowhere close to the boost that JRuby(native threads) can squeeze out from using multiple threads.

During the tests I noticed that rails was reporting more times spent in the db when using JRuby (2-80ms) compared to MRI (1-3ms). I don't know how reliable this data is but I wonder if this is the bottleneck that is holding JRuby back in the single threaded mode.

Tuesday, January 13, 2009

Using ZFS with Mac OS X 10.5

A few days ago I got a new MacBook Pro. While waiting for it to be delivered, I started thinking about how I want to layout the installation of the OS. For a long long time I wanted to try to use ZFS file system on Mac and this looked like a wonderful opportunity. Getting rid of HFS+, which was causing me lots of problems (especially its case insensitive re-incarnation), sounds like a dream come true.

If you've never heard of ZFS before, check out this good 5min screencast of some of the important features.

A brief google search revealed that there are several people using and developing ZFS for Mac. There is a Mac ZFS porting project at http://zfs.macosforge.org and I found a lot of good info at AlBlue's blog.

Some noteworthy info:
  • The current ZFS port (build 119) is based on ZFS code that shipped with Solaris build 72
  • It's currently not possible to boot Mac OS X from a ZFS filesystem
  • Finder integration is not perfect yet - Finder lists a ZFS pool as an unmountable drive under devices
  • There are several reports of kernel panics, most of which appeared in connection to the use of cheap external USB disks (I haven't experienced any)
  • There are a bunch of minor issues, which I'm sure will eventually go away.
None of the above was a show stopper for me, so I went ahead with the installation. My plan was simple - repartition the internal hard drive to a small bootable partition and a large partition used by ZFS, which will hold my home directory and other filesystems.

Install ZFS

Even though MacOS X 10.5 comes with ZFS support, it's only a read-only support. In order to be able to really use ZFS, full ZFS implementation must be installed.

The installation is very simple and can be done by following these instructions: http://zfs.macosforge.org/trac/wiki/downloads. Alternatively, AlBlue created a fancy installer for the lazy ones out there.

Repartition Disk

Once ZFS is installed and the OS was rebooted, I could repartition the internal disk. If you are using an external hard drive, you'll most likely need to use zpool command instead.

First let's check what the disk looks like:
$ diskutil list
/dev/disk0
#:                       TYPE NAME                    SIZE       IDENTIFIER
0:      GUID_partition_scheme                        *298.1 Gi   disk0
1:                        EFI                         200.0 Mi   disk0s1
2:                  Apple_HFS boot                    297.8 Gi   disk0s2
Good, the internal disk was identified as /dev/disk0 and it currently contains an EFI (boot) slice and ~300G data slice/partition. Let's repartition the disk so that it contains two data partitions.
$ sudo diskutil resizeVolume disk0s2 40G ZFS tank 257G
Password:
Started resizing on disk disk0s2 boot
Verifying
Resizing Volume
Adjusting Partitions
Formatting new partitions
Formatting disk0s3 as ZFS File System with name tank
[ + 0%..10%..20%..30%..40%..50%..60%..70%..80%..90%..100% ]
Finished resizing on disk disk0
/dev/disk0
#:                       TYPE NAME                    SIZE       IDENTIFIER
0:      GUID_partition_scheme                        *298.1 Gi   disk0
1:                        EFI                         200.0 Mi   disk0s1
2:                  Apple_HFS boot                    39.9 Gi    disk0s2
3:                        ZFS tank                    252.0 Gi   disk0s3


Great, the disk was repartitioned and the existing data partition, which I call boot, was resized into a smaller 40GB partition and the extra space was used to create a ZFS pool called tank. Btw all the data on the boot partition was preserved.

Let's check my new pool:
$ zpool list
NAME                    SIZE    USED   AVAIL    CAP  HEALTH     ALTROOT
tank                    256G    360K    256G     0%  ONLINE     -
$ zpool status
pool: tank
state: ONLINE
status: The pool is formatted using an older on-disk format.  The pool can
 still be used, but some features are unavailable.
action: Upgrade the pool using 'zpool upgrade'.  Once this is done, the
 pool will no longer be accessible on older software versions.
scrub: none requested
config:

 NAME        STATE     READ WRITE CKSUM
 tank        ONLINE       0     0     0
   disk0s3   ONLINE       0     0     0

errors: No known data errors
The warning above just means that a new ZFS storage format is available but is not used by the current pool. As far as I could find there are no benefits for upgrading to the new format on Mac, but if I did, I would lose compatibility with Macs that have only the read-only ZFS support.

Create Filesystems

So now that the new pool exists, I can create a shiny new filesystem using a single command:
$ sudo zfs create tank/me3x
$ zfs list
NAME        USED  AVAIL  REFER  MOUNTPOINT
tank        388K   252G   270K  /Volumes/tank
tank/me3x    19K   252G    19K  /Volumes/tank/me3x
To configure this new filesystem as my home directory, I created a temporary admin account, logged in under this account and mounted the ZFS fs as /Users/me3x:
$ sudo mv /Users/me3x /Users/me3x.hfs
$ sudo zfs set mountpoint=/Users/me3x tank/me3x
$ sudo cp -rp /Users/me3x.hfs /Users/me3x
That's it. My Mac account now resides on a ZFS file system. Now I can finally enjoy all the benefits of using ZFS on my OpenSolaris box in my office as well as on my Mac. Bye bye HFS, I won't miss you! 

Sunday, January 11, 2009

Freezing activerecord-jdbc Gems into a Rails Project

Over the Christmas break a Slovak friend of mine (Hi Martin!) asked me to build a simple book library management app for a school in the Philippines where he's been volunteering for the past year. I thought to my self that if someone can volunteer one year of his life in such an amazing way, I could spend a few hours to help him out too.

Since from his description it was obvious that he was looking for a low maintenance solution, I though that a rails application with an embedded database would be a good choice. I worked with derby (JavaDB) in the past and I knew that derby drivers were already available as an active-record adapter gem, so I thought that it would be pretty simple to set up dev environment using Rails, JRuby, and embedded derby db. Surprisingly there were a few issues along the way.

I started with defining the database config in config/database.yml:
development:
adapter: jdbcderby
database: db/library_development
pool: 5
timeout: 5000
...
...
The database files for the dev db will be stored under RAILS_ROOT/db/library_development

Secondly I specified the gem dependency in config/environment.rb (you gotta love this Rails 2.1+ feature):
Rails::Initializer.run do |config|
...
config.gem "activerecord-jdbcderby-adapter", :version => '0.9', :lib => 'active_record/connection_adapters/jdbcderby_adapter'
...
end
Note that you must specify the :lib parameter, otherwise Rails won't be able to initialize the gem and you'll end up with:
no such file to load -- activerecord-jdbcderby-adapter
So far so good. Now let's install the gems we depend on:
$ jruby -S rake gems:install
(in /Users/me3x/Development/library)
rake aborted!
Please install the jdbcderby adapter: `gem install activerecord-jdbcderby-adapter` (no such file to load -- active_record/connection_adapters/jdbcderby_adapter)

(See full trace by running task with --trace)
Huh? I asked rake to install gems and I get an error that I need to install gems first? It turns out that this error comes from ActiveRecord, which tries to initialize db according to database.yml, and only then environment.rb gets to be read.

Ok, so let's install the db dependencies manually:
$ sudo jruby -S gem install activerecord-jdbcderby-adapter
Password:
JRuby limited openssl loaded. gem install jruby-openssl for full support.
http://wiki.jruby.org/wiki/JRuby_Builtin_OpenSSL
Successfully installed activerecord-jdbc-adapter-0.9
Successfully installed jdbc-derby-10.3.2.1
Successfully installed activerecord-jdbcderby-adapter-0.9
3 gems installed
Installing ri documentation for activerecord-jdbc-adapter-0.9...
Installing ri documentation for jdbc-derby-10.3.2.1...
Installing ri documentation for activerecord-jdbcderby-adapter-0.9...
Installing RDoc documentation for activerecord-jdbc-adapter-0.9...
Installing RDoc documentation for jdbc-derby-10.3.2.1...
Installing RDoc documentation for activerecord-jdbcderby-adapter-0.9...
Cool, let's check if all the dependencies are available:
$ jruby -S rake gems
(in /Users/me3x/Development/library)
- [I] activerecord-jdbcderby-adapter = 0.9
- [I] activerecord-jdbc-adapter = 0.9
- [I] jdbc-derby = 10.3.2.1

I = Installed
F = Frozen
R = Framework (loaded before rails starts)
Yay, all dependencies are installed.

In the past when dependencies couldn't be declared in environment.rb, I found developing with frozen rails and gems much more manageable, especially when the app is being developed by more than one person. This also made for less deployment surprises. With the config.gem defined dependencies, the situation changes quite a bit, but there are situations when it still makes sense to freeze gems into the project. So let's freeze the gems:
$ jruby -S rake gems:unpack:dependencies
(in /Users/me3x/Development/library)
WARNING:  Installing to ~/.gem since /usr/local/jruby/jruby-1.1.6/lib/ruby/gems/1.8 and
   /usr/local/jruby/current/bin aren't both writable.
Unpacked gem: '/Users/me3x/Development/library/vendor/gems/activerecord-jdbcderby-adapter-0.9'
Unpacked gem: '/Users/me3x/Development/library/vendor/gems/activerecord-jdbc-adapter-0.9'
Unpacked gem: '/Users/me3x/Development/library/vendor/gems/jdbc-derby-10.3.2.1'
Looks good, let's check it:
$ jruby -S rake gems
(in /Users/me3x/Development/library)
- [F] activerecord-jdbcderby-adapter = 0.9
- [F] activerecord-jdbc-adapter = 0.9
- [F] jdbc-derby = 10.3.2.1

I = Installed
F = Frozen
R = Framework (loaded before rails starts)
Nice all the dependencies are now frozen!