williamhathaway.com

I have a lab machine running OpenSolaris 2009.06 (updated to snv_117) and had created an LDIF file with about 100k small entries in it (file size was ~ 63 megs).  I wanted to get a count of the exact number of entries so I ran:

grep -c ^dn:

I expected it to take a second or two.  I was wrong.  It was painfully slow.

I used the time command to re-run the grep and saw it clocked in at just over a minute.

This was weird, so I though it was time to investigate further.  I used the DTrace Toolkit’s hotuser command to see what the hot functions were:

pfexec /opt/DTT/hotuser -c "grep -c ^dn: /var/tmp/search.out"
Sampling... Hit Ctrl-C to end.

FUNCTION                                                     COUNT   PCNT
...<snipped out smaller functions>...
ggrep`check_multibyte_string                                    5480   8.9%
methods_unicode.so.3`__mbrtowc_dense_utf8                      12328  20.1%
libc.so.1`mbrlen                                               13566  22.1%
libc.so.1`memset                                               23014  37.5%

Hmm, interesting to see the calls to mbrlen and methods_unicode among the hot functions.  Lets check my $LANG setting:

echo $LANG

en_US.UTF-8

Bingo!  Lets try it again with a non multi-byte LANG setting.

LANG=C time grep -c ^dn: /var/tmp/search.out

99987

real        0.1
user        0.0
sys         0.0

That looks normal.  Now lets try one more time with a multi-byte LANG to be sure:

LANG=en_US.UTF-8 time grep -c ^dn: /var/tmp/search.out
99987

real     1:01.4
user     1:01.3
sys         0.0

Yep, the problem is confirmed.

Notes

For those unfamiliar with OpenSolaris,  the default path has /usr/gnu/bin first.  The grep I was using was:

grep -V
grep (GNU grep) 2.5

Copyright 1988, 1992-1999, 2000, 2001 Free Software Foundation, Inc.
This is free software; see the source for copying conditions. There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

If you use the non-GNU grep available at /usr/xpg4/bin/grep it doesn’t have the big slowdown regardless of the LANG.

I also tried the same test on the GNU wc command and saw about a 25x difference when using a multi-byte LANG.

For both grep and wc, I re-ran the tests multiple times to make sure that file system caching played no role in the results.

I think these performance differences are way higher than they should be, I’m going to dig further when I have a chance.

I need to upload  more, but you can see the pics at Smugmug.

I got a new camera this week and went up to  Wildwood Park near HACC to take some pictures today.   I really like the 20x zoom lense (the main reason I bought it), and the image stabilization seemed to work pretty well.   I think it is cool that I was able to see the details of the pollen on the bee.

Bee on a flower

Goose swimming in green alge

We all live downstream

Overrun lake

Main trail

My wife and I have decided to move to the San Francisco/SiliconValley area.  We haven’t set a date yet,  but we are definitely moving sometime in 2010.

Just wanting google to start indexing my wiki.

I’ve had my Prius for about 16 months now (got it in early May 2008).  So far I have been largely happy.  I’ve averaged about 44-47 MPG in the warmer months and 42-44MPG in the winter with a roughly  50% highway/50% city mix of driving.  I’ve only had a few  minor nits/issues:

1. The gas tank is made of a (sort of) flexible membrane and it becomes stiff during colder months and won’t hold as much fuel.  During the winter I can often only get about 75% as much gas in the tank as I can during the spring/summer/fall months.   More info available in a hybrid cars forum.
2. The default behavior is to beep inside the car when in reverse (versus trucks which beep outside to warn people behind it).  It turns out it is fairly easy to disable the beeping using these instructions.  I just followed the instructions this morning.
3. It is difficult to jump start other cars.  The positive terminal is really small and when I tried to help a friend get his car started, the metal “jaw” on the jumper cables were too big to fit in the space near the positive terminal.
4. I wish there was better iPod integration by default (I am currently just using the AUX jack).  A friend of mine purchased the factory unit for his Lexus and the interface is dissapointing.  I am considering getting a Vaistech unit.

Other notes:

1. I’ve had no maintenance problems.
2. The leg/headroom seem fine.  While I am not tall, I regular drive 3 other people to lunch, and the bigger guys in the office can fit comfortably (although the 6’6″ guy does always take shotgun).
3. By folding down the back seats I can easily put my mountain bike in the trunk if I take off the front tire.

I’ve been spending a bunch of time lately looking at Java garbage collection (GC) performance & tuning.  One of the old standby options for GC logging is:

-XX:+PrintGCTimeStamps

this option tells the JVM to print a time stamp in the front of each GC line that is the number of seconds since the Java process started.  You end up with lines like:

1.449: [GC 76756K->5892K(504320K), 0.0226648 secs]
1.472: [Full GC 5892K->5752K(504320K), 0.1099638 secs]
4.276: [GC 137848K->14895K(504320K), 0.0333021 secs]
5.653: [GC 146991K->63707K(504320K), 0.0858191 secs]
38.536: [GC 195803K->77393K(636416K), 0.0683676 secs]
144.875: [GC 341585K->97580K(637440K), 0.1131954 secs]

While these are better than nothing, it can be a PITA to translate these to something useful, like say wall clock time, such as when you want to correlate a GC time to an external alarm.

Starting in Sun’s JDK version 1.6u4, there is another option that can be enabled that actually prints both the wall clock time as well as the seconds since process start.  This is way more user-friendly.  I suspect there is a extremely minute performance penalty to add this extra info, but I’d be shocked if it is actually perceptable.  If anyone knows differently, please let me know.  This option is:

-XX:+PrintGCDateStamps

If you have it enabled, the output looks like:

2009-09-02T23:02:07.151-0400: 1.463: [GC 79398K->5887K(504320K), 0.0236701 secs]
2009-09-02T23:02:07.175-0400: 1.486: [Full GC 5887K->5753K(504320K), 0.1095894 secs]
2009-09-02T23:02:10.028-0400: 4.339: [GC 137849K->14987K(504320K), 0.0345331 secs]
2009-09-02T23:04:31.707-0400: 146.018: [GC 147083K->23143K(504320K), 0.0455040 secs]
2009-09-02T23:14:28.502-0400: 742.813: [GC 155239K->28406K(504320K), 0.0912850 secs]

As you can see, this is much more easily digestable to  humans.  Since you still have the ‘seconds since program start’ info handy, you can continue to use scripts/programs to easily calculate the time deltas between GCs.

Some useful links I’ve found for Java tuning in general are:

• Resources from Matty’s presentation:

http://prefetch.net/blog/index.php/2008/02/05/java-performance-presentation/

• Java performance forum:

http://forums.java.net/jive/forum.jspa?forumID=60

• Jon Masamitsu’s blog: (the last post was over a year ago, starting to age, but some good material)

http://blogs.sun.com/jonthecollector/

• Garbage Collection Tuning in the Java HotSpot Virtual Machine presentation at Java One 2009

http://developers.sun.com/learning/javaoneonline/sessions/2009/pdf/TS-4887.pdf