illumos gate

In doing some work, we encountered the fact that uuid generation on illumos is much slower than on other platforms. To recreate this, simply:

$ git clone git://github.com/mcavage/node-libuuid.git
$ cd node-libuuid
$ node-gyp rebuild
$ npm test

The following are notes from Jerry's investigations. I went back to my full set of syscall aggregations and see this:

  read                                              
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1000006  
               1 |                                         2        
               2 |                                         0        

  open                                              
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2000015  
               1 |                                         3        
               2 |                                         0        

  close                                             
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2000023  
               1 |                                         3        
               2 |                                         0        

So even though the time is not high, we can see that we are doing an open/read on something each time we generate a uuid. I aggregated the files we're opening.

  /dev/kstat                                                        1
  /lib/libc.so.1                                                    1
  /lib/libdl.so.1                                                   1
  /lib/libkstat.so.1                                                1
  /lib/libm.so.2                                                    1
  /lib/libnsl.so.1                                                  1
  /lib/libpthread.so.1                                              1
  /lib/libsendfile.so.1                                             1
  /lib/libsocket.so.1                                               1
  /lib/libumem.so.1                                                 1
  /lib/libumem_trampoline.so.1                                      1
  /lib/libuuid.so.1                                                 1
  /opt/local/gcc47/i386-sun-solaris2.11/lib/./libgcc_s.so.1                1
  /opt/local/gcc47/i386-sun-solaris2.11/lib/./libstdc++.so.6                1
  /opt/local/lib/libcrypto.so.1.0.0                                 1
  /opt/local/lib/libssl.so.1.0.0                                    1
  /root/node-libuuid/build/Release/uuid.node                        1
  /var/ld/ld.config                                                 1
  /dev/urandom                                                2000000

So it is virtually a certainty that the 2m calls to urandom is what is taking all of the time.

I changed the C program to only open /dev/urandom once, do 1m reads, and close the fd. When I run this in the zone I get:

[root@443d424f-ec90-cfc4-ca05-8daf130a167e ~]# time ./rand

real 0m1.762s
user 0m0.221s
sys 0m1.540s

So it seems like the fact that node is opening /dev/urandom 2m times is the big issue here. I changed the test program to not do any reads and simply open/close /dev/urandom 2m times, as we see in the dtrace result.

[root@443d424f-ec90-cfc4-ca05-8daf130a167e ~]# time ./rand       

real    0m14.426s
user    0m1.129s
sys     0m13.290s

The open of /dev/urandom happens in libuuid which actually opens and closes the dev twice per uuid. I changed the code to only open the dev once and got a significant speedup. In the graphite-dev zone with LD_LIBRARY_PATH pointing to the new library:

> libuuid@0.1.2 test /root/node-libuuid
> node test/t1.js

1000000 over 3.256 seconds
999999.9976493253create/second

So this is a 5-10x speedup.

As an additional change, I added code to cache 64K bytes of random data to reduce the number of reads to /dev/urandom. This helps a little bit and it makes repeated runs a lot more consistent on the elapsed time:

> libuuid@0.1.2 test /root/node-libuuid
> node test/t1.js

1000000 over 2.445 seconds
999999.998234836create/second