My 2nd Head

Splunking Oracle's ZFS Appliance Part II

2011-10-12T08:30:00.000+02:00

In my first part I wrote about storing long term analytics data in Splunk.

Wouldn't it be nice to also have storage capacity tracked with Splunk?

This is how it's done:

1. Get pool properties

#!/bin/ksh

# list capacity all Pools in a System to ${outputdir}/${poolname}.pools.log

# Example: listPools.ksh /tmp 10.16.5.14

typeset outputdir=$1
typeset ipname=$2
typeset debug=$3
typeset user=monitor

if [ -z "$1" -o -z "$2" ]; then
printf "\nUsage: $0 <output Dir≷ <ZFSSA ipname> [ debug ]\n\n"
exit 1
fi

mkdir -p ${outputdir}
dat=$(date +'%y-%m-%d %H:%M:%S')

ssh -T ${user}@${ipname} << --EOF-- > ${outputdir}/${ipname}.pools.log
script
run('status');
run('storage');
var poollist=list();

printf("Time,pool,avail,compression,used,space_percentage\\n");

for(var k=0; k&lt:poollist.length; k++) {
run('select ' + poollist[k]);

var space_used=get('used')/1024/1024/1024;
var space_avail=get('avail')/1024/1024/1024;
var compression=get('compression');
var space_percentage=space_used/(space_used + space_avail)*100;

printf("$dat,%s,%0.0f,%0.2f,%0.0f,%0.0f\\n",poollist[k],space_avail,compression,space_used,space_percentage);

run('done');
}
run('done');

--EOF--

exit $?

2. Write Splunk props.conf

As an exercise...

3. Enjoy Splunk Dashboards:

4. Repeat for projects and shares.

PS: If I find the time, I will eventually package this into a Splunk App.

Splunking Oracle's ZFS Appliance

2011-10-07T16:43:00.001+02:00

We have a bunch of Oracle ZFS Appliances. What I really like is their integrated dtrace based analytics feature.

However, some things are missing or causing problems:

-Storing long-term analytics data on the appliances produces a lot of data on the internal disks. This can fill up your appliance and in the worst case slow down the appliance software

-Scaling the timeline out too much, makes peaks invisible. This is probably a problem of the rendering software used on the appliance (JavaScript)

-Comparing all our appliances is not possible. There is no central analytics console.

As we are a heavy Splunk user, I sat together with our friendly storage consultant from Oracle and we brought these two great products closer together:

This is how we did it:

1. Setting up analytics worksheets

First we had to create the analytics worksheets. This is best done using the CLI interface, as the order of drilldowns should be always the same. Otherwise fields in the generated csv file might be in a different order on every appliance. Doing this in the BUI is possible, but hard...

I would also recommend to store the worksheet under a separate Appliance User.

Sample CLI commands:

analytics
worksheets
create Monitor
select worksheet-???

dataset
set name=io.ops[op]
set drilldowns=read,write
set seconds=3600
commit

dataset
set name=nfs4.ops
set seconds=3600
commit
...

2. Fetch Analytics Data

Script Excerpt:

ssh -T ${user}@${ipname} << --EOF--
${outputdir}/${wsname}.${ipname}.out
script
run('analytics');
run('worksheets');
var ws=list();
printf("Worksheets:%d\\n",ws.length);
printf("%s\\n",ws);
for(var i=0; i<ws.length; i++)="" p="" {<=""></ws.length;>
run('select ' + ws[i]);
var wsname=get('name');
printf("Worksheet Name:%s\\n",wsname);
if ( wsname == "$wsname" ) {
var ds=list();
for(var j=0; j<ds.length; j++)="" p="" {<=""></ds.length;>
run('select ' + ds[j]);
var dsname=get('name');
printf("zfssa_%s\\n",dsname);
dump(run('csv'));
run('done');
}
}
run('done');
}
run('done');

--EOF--

3. Configure Splunk Inputs

4. Create Splunk Dashboards

5. Enjoy Analytics Data Under Splunk

Happy Spelunking...

Splunk: Unscaling units

2011-05-22T22:49:00.000+02:00

I'm working on a Splunk Application for Solaris.

One of the commands that is of interest to me is the fsstat(1m) command output. Here's the output for two filesystem types (zfs, nfs4):

solaris# fsstat zfs nfs4 1 1
 new  name   name  attr  attr lookup rddir  read read  write write
 file remov  chng   get   set    ops   ops   ops bytes   ops bytes
2.21K   881   521  585K 1.22K  1.71M 9.34K 1.66M 21.3G  765K 10.7G zfs
    0     0     0     0     0      0     0     0     0     0     0 nfs4
    0     0     0    20     0      0     0   279  997K   142  997K zfs
    0     0     0     0     0      0     0     0     0     0     0 nfs4

While Splunk is very flexible in parsing whatever output, for command outputs it is better to do a little pre-formatting:

-Make headers single line

-Drop the summary line (activity since fs loaded/mounted)

-Find a solution to be able to do stats on the autoscale values (K,M,G,T)

First, I wrote a script to adjust the output. The output looks like this now:

./fsstat.pl zfs nfs4
new_file name_remov name_chng attr_get attr_set lookup_ops rddir_ops read_ops read_bytes write_ops write_bytes fstype
    1     0     1     9     1     27     0   260 1.14M   145 1.18M zfs
    0     0     0     0     0      0     0     0     0     0     0 nfs4

This makes it much easier to parse the data.

A splunk search with multikv will split this into several fields:

sourcetype="solaris_fsstat" |multikv

We will now have single line events with the fields new_file, name_remov, name_chng etc...

The trouble is, that the fsstat command scales values automatically into human readable format. This can not be disabled.

But we are lucky, Splunk is able to solve the problem. To unscale e.g. read_ops, we add a bit Splunk magic to the search:

| rex field=read_ops "(?[\d\.]+)(?\w+)?" | eval read_ops_unscaled=case(
read_ops_unit=="",read_ops_amount,
read_ops_unit=="K",read_ops_amount*1024, read_ops_unit=="M",read_ops_amount*1024*1024, read_ops_unit=="G",read_ops_amount*1024*1024*1024, read_ops_unit=="T",read_ops_amount*1024*1024*1024*1024)

Now we have created a new field called read_ops_unscaled.

Wasn't this cool?

As this is quite hard to type I have created macros for every field that has to be scaled.

After this, I have created a master macro called `unscale_fsstat` which calls all other macros. Now it is trivial to run a search and do some stats on the results.

Happy Splunking!

Adjusting ZFS resilvering speed

2011-03-13T20:25:00.003+01:00

There are two kernel parameters that can be adjusted if ZFS resilvering speed is too slow/fast:

zfs_resilver_delay /* number of ticks to delay resilver */

and

zfs_resilver_min_time_ms /* min millisecs to resilver per txg */

In some cases the values can be too low or two high (e.g. when using Mirroring vs. RAIDZ).

A boost could be:

# echo zfs_resilver_delay/W0|mdb -kw

# echo zfs_resilver_min_time_ms/W0t3000|mdb -kw

whereas a handbrake is e.g.:

# echo zfs_resilver_delay/W2|mdb -kw

# echo zfs_resilver_min_time_ms/W0t300|mdb -kw

Disclaimer: Use at your own risk. Do not try on production systems without contacting support first.

Useful Dtrace One-Liners....

2011-03-01T22:35:00.000+01:00

Finding write operations for a process. Especially when writing to a NFS share...

# dtrace -n 'fsinfo:::write /execname == "execname"/ \

  { printf("%s", args[0]->fi_pathname) }'

Finding the top userland stacks for a process

# dtrace -n 'syscall:::entry /execname == "execname"/ \
{ @[ustack()] = count();}'

Finding the same for a certain system call

# dtrace -n 'syscall::mmap:entry /execname == "execname"/ \
{ @[ustack()] = count();}'

New ZFS Appliances...

2011-03-01T22:13:00.000+01:00

Measuring Read/Write durations with DTrace

2011-01-21T16:34:00.000+01:00

I had the situation, where I wanted to see if read/write operations take too much time.

It was something that I thought could be done easily with DTrace. Unfortunately, my DTrace skills are a bit rusty, so I contacted my personal DTrace guru Javier, who gave me a script.

Here is the script for read operations:

slow_read.d:

#!/usr/sbin/dtrace -s

#pragma D option quiet
#pragma D option switchrate=10hz

syscall::*read:entry
{
        this->filistp = curthread->t_procp->p_user.u_finfo.fi_list;
        this->ufentryp = (uf_entry_t *)((uint64_t)this->filistp + (uint64_t)arg0 * (uint64_t)sizeof (uf_entry_t));
        this->filep = this->ufentryp->uf_file;
        self->offset = this->filep->f_offset;
        this->vnodep = this->filep != 0 ? this->filep->f_vnode : 0;
        self->vpath = this->vnodep ? (this->vnodep->v_path != 0 ? cleanpath(this->vnodep->v_path) : "") : "";
        self->sc_trace = this->vnodep ? this->vnodep->v_type == VREG || this->vnodep->v_type == VDIR ? 1 : 0 : 0;
        self->start=timestamp;
}

syscall::*read:return
/self->sc_trace && (timestamp - self->start) > 30000000 /
{
        printf ("Read from %s took %d ms\n", self->vpath, ((timestamp-self->start)/1000000));
        self->vpath = 0;
        self->offset = 0;
        self->sc_trace = 0;
        self->start = 0;
}

The script will return all read operations that take longer than 30ms (adjustable by changing the value of 30000000) , with the respective file name. Of course, if you have large files, this dtrace script doesn't necesserily make sense, but it's perfect for my small files environment...

Running the script will produce this output:

./slow_read.d
Read from /blabla/xyz.log took 205 ms
Read from /blabla/xyz.log took 42 ms
Read from /blabla/xyz.log took 65 ms
...

Turning this into scripts for writes was easy... just replace the syscall into "write".

slow_write.d:
#!/usr/sbin/dtrace -s

#pragma D option quiet
#pragma D option switchrate=10hz

syscall::*write:entry
{
        this->filistp = curthread->t_procp->p_user.u_finfo.fi_list;
        this->ufentryp = (uf_entry_t *)((uint64_t)this->filistp + (uint64_t)arg0 * (uint64_t)sizeof (uf_entry_t));
        this->filep = this->ufentryp->uf_file;
        self->offset = this->filep->f_offset;
        this->vnodep = this->filep != 0 ? this->filep->f_vnode : 0;
        self->vpath = this->vnodep ? (this->vnodep->v_path != 0 ? cleanpath(this->vnodep->v_path) : "") : "";
        self->sc_trace = this->vnodep ? this->vnodep->v_type == VREG || this->vnodep->v_type == VDIR ? 1 : 0 : 0;
        self->start=timestamp;
}

syscall::*write:return
/self->sc_trace && (timestamp - self->start) > 30000000 /
{
        printf ("Write to %s took %d ms\n", self->vpath, ((timestamp-self->start)/1000000));
        self->vpath = 0;
        self->offset = 0;
        self->sc_trace = 0;
        self->start = 0;
}

With little effort, I have now another view of how my storage is behaving.

Just in time delivery...

2010-12-31T08:31:00.001+01:00

...before the end of year.

In the picture below:

4x S7420
1TB RAM
4TB ReadZilla
16x LogZillas
352x 1TB SAS-2 Disks
16 JBODs

53734 NFSv4 ops/sec

2010-10-29T16:27:00.000+02:00

Not bad.

Still more than enough headroom left...

Adventures in Application Performance Management: Part II

2010-10-22T19:37:00.000+02:00

Firing up AppDynamics inside the browser shows a list of application agents, and also external systems being called by our application.

The nice thing is, AppDynamic automatically detects calls to external systems, like WebServices etc.

Grouping the agent and surrounding systems a little bit, AppDynamics presents us a nice dashboard, with the most important information.

The large area shows the calls to other systems.

On the bottom we see the load (calls/minute) and average response time:

As you can see, the number of calls goes down, while the response time goes up at the same time. A clear case of a bottleneck...

To find the reason for this, we look at the right side of the dashboard.

AppDynamics automatically classifies requests into categories (can be adjusted). We can clearly see that we have 1.2% Stalls, for this timeperiod.

We can further see which were the top transactions by load and by response time.

Transactions are autodetected by AppDynamics and will be monitored automatically.

You can look at suspicious transactions, or look at stalled requests. AppDynamics automatically takes request snapshots including call graphs.

Back to our performance problem...

After finally seeing how the application works internally, we found the reason for our performance problem within hours. We had a method that was synchronised. During the peak-hours, requests (many!) had to wait. This caused not only a huge slow-down, but also lots of objects that had to be collected by the garbage collector, and caused long application pauses

After fixing this single method, our application has been faster than ever...

Adventures in Application Performance Management: Part I

2010-10-22T18:53:00.000+02:00

Who follows my blog, knows that I'm a Splunk addict, because I really like to know what my applications and systems are doing.

Although Splunk is my favorite tool in my toolbox (and will be in the future... :-), there are some blind spots it can't see.

We have struggled with some serious performance problems in one of our core applications during peak-hours.

The application is Java-based, and usually performs well, when everything is ok. But during peak-hours, the response time gets worse and worse, having the side-effect of long major garbage collections. Not very user friendly, when there is a long stop-the-world.

We were looking at the problem from the top (log analysis, monitoring) to the bottom (gc logs, jprofiler) never really finding the root cause of the problem. The fact that the problem did not occur all the time did not make it easier...

As the situation got worse over time, and adding even more hardware was not really a solution, we were looking for some external help.

Lucky for us, the company we asked for help brought in a brand new Application Performance Management tool called AppDynamics, which was recently released.

Installing of AppDynamics was a no-brainer. It took 5 Minutes to install the server, and only a few minutes to install the Agents. Only a jar-file needs to be loaded into the JVM as an agent. The agent only needs to know where it can find the AppDynamics Server. Communication is done through http.

Now we were ready to find the root cause.

Countdown to ONE BILLION FILES!

2010-10-19T21:25:00.000+02:00

I was reading Ric Wheelers "One Billion Files: Scalability Limits in Linux Filesystems". As a ZFS user, I was wondering how many files we store on one of our mail storage systems in a single zpool.

My colleague was so kind to start a find on the system. Four days later we got

# find /export -type f | wc -l 

811874848

Interesting. We are already close to one billion files in production.

Next step was to look at the average file size. Currently, 12.5TB are referenced, compression ratio is 1.77x. This results in a average size of ~30kB.

How long will it take to reach one billion files?

In average, 60 mails get delivered per second to the storage system (over NFSv4!). Therefore, to get the missing 190 million files, we only need to wait a little bit more than a month.

DTrace saving the planet again....

2010-09-13T21:38:00.002+02:00

...maybe not the planet, but DTrace was again a big help in finding another performance problem.

During peak-hours and when we had a spam-wave coming in, we saw a spike on our T5120 systems.

Where we usually see a very low load of ~ 1-2, the load jumped up to 400 within a few minutes.

Something did'nt seem right.

Like with the previous DTrace Problem, we saw that our userland processes had a high system time, so most of the things it was doing (or maybe not) was in the kernel.

It was time to use one of the secret weapons that Solars Admins have: lockstat (uses DTrace).

Sorry for the lengthy output...

# lockstat -i 133 -I sleep 5    

Profiling interrupt: 43328 events in 5.088 seconds (8516 events/sec)

Count indv cuml rcnt     nsec CPU+PIL                Caller                  

-------------------------------------------------------------------------------

  155   0%   0% 0.00     2347 cpu[42]                rdccr_delay+0x8         

  152   0%   1% 0.00     2184 cpu[53]                rdccr_delay+0x4         

  151   0%   1% 0.00     2135 cpu[58]                rdccr_delay+0x8         

  150   0%   1% 0.00     2201 cpu[10]                rdccr_delay+0x4         

  149   0%   2% 0.00     2486 cpu[24]                rdccr_delay+0x8         

  147   0%   2% 0.00     2296 cpu[57]                default_lock_delay+0x74 

  147   0%   2% 0.00     2476 cpu[56]                default_lock_delay+0x74 

  147   0%   3% 0.00     2138 cpu[46]                default_lock_delay+0x74 

  146   0%   3% 0.00     2148 cpu[55]                default_lock_delay+0x74 

  145   0%   3% 0.00     2157 cpu[61]                rdccr_delay+0x8         

  143   0%   4% 0.00     2098 cpu[49]                rdccr_delay+0x8         

  143   0%   4% 0.00     2231 cpu[45]                rdccr_delay+0x4         

  143   0%   4% 0.00     2025 cpu[28]                rdccr_delay+0x8         

  142   0%   5% 0.00     2000 cpu[63]                rdccr_delay+0x4         

  141   0%   5% 0.00     2106 cpu[55]                rdccr_delay+0x4         

  141   0%   5% 0.00     2173 cpu[52]                rdccr_delay+0x4         

  141   0%   6% 0.00     2464 cpu[48]                default_lock_delay+0x74 

  141   0%   6% 0.00     2097 cpu[4]                 default_lock_delay+0x74 

  140   0%   6% 0.00     2195 cpu[54]                rdccr_delay+0x4         

  140   0%   7% 0.00     2084 cpu[14]                rdccr_delay+0x4         

  140   0%   7% 0.00     2475 cpu[8]                 default_lock_delay+0x74 

  139   0%   7% 0.00     2196 cpu[53]                rdccr_delay+0x8         

  139   0%   8% 0.00     2123 cpu[44]                rdccr_delay+0x8         

  139   0%   8% 0.00     2167 cpu[41]                default_lock_delay+0x74 

  139   0%   8% 0.00     2386 cpu[31]                rdccr_delay+0x8         

  139   0%   9% 0.00     2551 cpu[16]                default_lock_delay+0x74 

  139   0%   9% 0.00     2598 cpu[16]                rdccr_delay+0x8         

  139   0%   9% 0.00     2204 cpu[11]                default_lock_delay+0x74 

  138   0%  10% 0.00     2238 cpu[62]                rdccr_delay+0x4         

  138   0%  10% 0.00     2163 cpu[51]                rdccr_delay+0x8         

  138   0%  10% 0.00     2164 cpu[47]                rdccr_delay+0x4         

  138   0%  11% 0.00     2221 cpu[22]                default_lock_delay+0x74 

  138   0%  11% 0.00     2158 cpu[22]                rdccr_delay+0x4         

  137   0%  11% 0.00     2082 cpu[59]                rdccr_delay+0x4         

  137   0%  11% 0.00     2190 cpu[54]                rdccr_delay+0x8         

  137   0%  12% 0.00     2139 cpu[47]                default_lock_delay+0x74 

  137   0%  12% 0.00     2169 cpu[46]                rdccr_delay+0x4         

  137   0%  12% 0.00     2234 cpu[36]                default_lock_delay+0x74 

  137   0%  13% 0.00     2491 cpu[32]                rdccr_delay+0x8         

  137   0%  13% 0.00     2074 cpu[23]                default_lock_delay+0x74 

  137   0%  13% 0.00     2198 cpu[19]                default_lock_delay+0x74 

  137   0%  14% 0.00     2185 cpu[5]                 default_lock_delay+0x74 

  136   0%  14% 0.00     2076 cpu[60]                rdccr_delay+0x8         

  136   0%  14% 0.00     2160 cpu[50]                default_lock_delay+0x74 

  136   0%  15% 0.00     2225 cpu[43]                rdccr_delay+0x4         

  136   0%  15% 0.00     2250 cpu[39]                rdccr_delay+0x8         

  136   0%  15% 0.00     2088 cpu[20]                rdccr_delay+0x4         

  136   0%  16% 0.00     2209 cpu[7]                 rdccr_delay+0x4         

  135   0%  16% 0.00     2253 cpu[62]                default_lock_delay+0x74 

  135   0%  16% 0.00     2191 cpu[61]                rdccr_delay+0x4         

  135   0%  17% 0.00     2539 cpu[40]                rdccr_delay+0x4         

  135   0%  17% 0.00     2233 cpu[36]                rdccr_delay+0x4         

  135   0%  17% 0.00     2047 cpu[28]                rdccr_delay+0x4         

  135   0%  17% 0.00     2192 cpu[19]                rdccr_delay+0x8         

  135   0%  18% 0.00     2203 cpu[1]                 default_lock_delay+0x74 

  134   0%  18% 0.00     2354 cpu[37]                default_lock_delay+0x74 

  134   0%  18% 0.00     2411 cpu[37]                rdccr_delay+0x4         

  134   0%  19% 0.00     2062 cpu[23]                rdccr_delay+0x4         

  134   0%  19% 0.00     2317 cpu[15]                rdccr_delay+0x8         

  133   0%  19% 0.00     2161 cpu[41]                rdccr_delay+0x4         

  133   0%  20% 0.00     2211 cpu[19]                rdccr_delay+0x4         

  133   0%  20% 0.00     2282 cpu[9]                 rdccr_delay+0x4         

  133   0%  20% 0.00     2093 cpu[4]                 rdccr_delay+0x8         

  133   0%  21% 0.00     2753 cpu[0]                 default_lock_delay+0x74 

  132   0%  21% 0.00     2444 cpu[48]                rdccr_delay+0x4         

  132   0%  21% 0.00     2223 cpu[45]                rdccr_delay+0x8         

  132   0%  21% 0.00     2238 cpu[39]                default_lock_delay+0x74 

  132   0%  22% 0.00     2164 cpu[22]                rdccr_delay+0x8         

  131   0%  22% 0.00     2572 cpu[56]                rdccr_delay+0x8         

  131   0%  22% 0.00     2121 cpu[46]                rdccr_delay+0x8         

  131   0%  23% 0.00     2539 cpu[40]                rdccr_delay+0x8         

  131   0%  23% 0.00     2246 cpu[36]                rdccr_delay+0x8         

  131   0%  23% 0.00     2388 cpu[31]                rdccr_delay+0x4         

  131   0%  24% 0.00     1957 cpu[26]                default_lock_delay+0x74 

  131   0%  24% 0.00     2252 cpu[18]                rdccr_delay+0x4         

  131   0%  24% 0.00     2374 cpu[17]                default_lock_delay+0x74 

  131   0%  24% 0.00     2287 cpu[12]                rdccr_delay+0x4         

  131   0%  25% 0.00     2307 cpu[3]                 rdccr_delay+0x4         

  131   0%  25% 0.00     2221 cpu[1]                 rdccr_delay+0x8         

  130   0%  25% 0.00     2088 cpu[60]                rdccr_delay+0x4         

  130   0%  26% 0.00     2198 cpu[51]                default_lock_delay+0x74 

  130   0%  26% 0.00     2141 cpu[44]                default_lock_delay+0x74 

  130   0%  26% 0.00     2264 cpu[42]                default_lock_delay+0x74 

  130   0%  27% 0.00     2203 cpu[33]                default_lock_delay+0x74 

  130   0%  27% 0.00     2110 cpu[14]                default_lock_delay+0x74 

  130   0%  27% 0.00     2170 cpu[12]                default_lock_delay+0x74 

  130   0%  27% 0.00     2251 cpu[7]                 default_lock_delay+0x74 

  130   0%  28% 0.00     2065 cpu[2]                 default_lock_delay+0x74 

  129   0%  28% 0.00     2028 cpu[63]                rdccr_delay+0x8         

  129   0%  28% 0.00     2090 cpu[59]                default_lock_delay+0x74 

  129   0%  29% 0.00     2418 cpu[56]                rdccr_delay+0x4         

  129   0%  29% 0.00     2099 cpu[49]                rdccr_delay+0x4         

  129   0%  29% 0.00     2290 cpu[38]                default_lock_delay+0x74 

  129   0%  30% 0.00     2256 cpu[35]                default_lock_delay+0x74 

  129   0%  30% 0.00     2324 cpu[17]                rdccr_delay+0x8         

  129   0%  30% 0.00     2688 cpu[0]                 rdccr_delay+0x4         

  128   0%  30% 0.00     2237 cpu[30]                default_lock_delay+0x74 

  128   0%  31% 0.00     2330 cpu[30]                rdccr_delay+0x4         

  128   0%  31% 0.00     2291 cpu[29]                rdccr_delay+0x4         

  128   0%  31% 0.00     1969 cpu[26]                rdccr_delay+0x8         

  128   0%  32% 0.00     2224 cpu[18]                default_lock_delay+0x74 

  128   0%  32% 0.00     2104 cpu[6]                 rdccr_delay+0x8         

  127   0%  32% 0.00     2148 cpu[60]                default_lock_delay+0x74 

  127   0%  33% 0.00     2191 cpu[51]                rdccr_delay+0x4         

  127   0%  33% 0.00     2143 cpu[49]                default_lock_delay+0x74 

  127   0%  33% 0.00     2247 cpu[38]                rdccr_delay+0x4         

  127   0%  33% 0.00     2261 cpu[30]                rdccr_delay+0x8         

  127   0%  34% 0.00     2288 cpu[29]                default_lock_delay+0x74 

  127   0%  34% 0.00     2027 cpu[28]                default_lock_delay+0x74 

  127   0%  34% 0.00     2189 cpu[13]                default_lock_delay+0x74 

  127   0%  35% 0.00     2497 cpu[8]                 rdccr_delay+0x4         

  127   0%  35% 0.00     2079 cpu[6]                 rdccr_delay+0x4         

  126   0%  35% 0.00     2174 cpu[50]                rdccr_delay+0x4         

  126   0%  35% 0.00     2449 cpu[48]                rdccr_delay+0x8         

  126   0%  36% 0.00     2229 cpu[34]                rdccr_delay+0x4         

  126   0%  36% 0.00     2267 cpu[21]                rdccr_delay+0x4         

  126   0%  36% 0.00     2569 cpu[16]                rdccr_delay+0x4         

  126   0%  37% 0.00     2294 cpu[15]                rdccr_delay+0x4         

  126   0%  37% 0.00     2213 cpu[5]                 rdccr_delay+0x4         

  126   0%  37% 0.00     2265 cpu[3]                 default_lock_delay+0x74 

  125   0%  37% 0.00     2523 cpu[32]                rdccr_delay+0x4         

  125   0%  38% 0.00     2371 cpu[17]                rdccr_delay+0x4         

  125   0%  38% 0.00     2242 cpu[9]                 default_lock_delay+0x74 

  124   0%  38% 0.00     2185 cpu[50]                rdccr_delay+0x8         

  124   0%  39% 0.00     2201 cpu[43]                rdccr_delay+0x8         

  124   0%  39% 0.00     2172 cpu[41]                rdccr_delay+0x8         

  124   0%  39% 0.00     2162 cpu[33]                rdccr_delay+0x8         

  124   0%  39% 0.00     2237 cpu[21]                default_lock_delay+0x74 

  123   0%  40% 0.00     2153 cpu[58]                default_lock_delay+0x74 

  123   0%  40% 0.00     2240 cpu[39]                rdccr_delay+0x4         

  123   0%  40% 0.00     2121 cpu[33]                rdccr_delay+0x4         

  123   0%  41% 0.00     2256 cpu[21]                rdccr_delay+0x8         

  123   0%  41% 0.00     2360 cpu[15]                default_lock_delay+0x74 

  123   0%  41% 0.00     2181 cpu[11]                rdccr_delay+0x8         

  122   0%  41% 0.00     2249 cpu[57]                rdccr_delay+0x8         

  122   0%  42% 0.00     2120 cpu[55]                rdccr_delay+0x8         

  122   0%  42% 0.00     2136 cpu[52]                rdccr_delay+0x8         

  122   0%  42% 0.00     2231 cpu[34]                rdccr_delay+0x8         

  122   0%  43% 0.00     2115 cpu[20]                default_lock_delay+0x74 

  122   0%  43% 0.00     2211 cpu[5]                 rdccr_delay+0x8         

  121   0%  43% 0.00     2274 cpu[35]                rdccr_delay+0x8         

  121   0%  43% 0.00     2263 cpu[29]                rdccr_delay+0x8         

  121   0%  44% 0.00     2125 cpu[25]                rdccr_delay+0x8         

  121   0%  44% 0.00     2298 cpu[3]                 rdccr_delay+0x8         

  121   0%  44% 0.00     2711 cpu[0]                 rdccr_delay+0x8         

  120   0%  45% 0.00     2002 cpu[63]                default_lock_delay+0x74 

  120   0%  45% 0.00     2124 cpu[43]                default_lock_delay+0x74 

  120   0%  45% 0.00     2539 cpu[40]                default_lock_delay+0x74 

  120   0%  45% 0.00     2018 cpu[27]                default_lock_delay+0x74 

  120   0%  46% 0.00     2184 cpu[25]                rdccr_delay+0x4         

  120   0%  46% 0.00     2089 cpu[23]                rdccr_delay+0x8         

  120   0%  46% 0.00     2202 cpu[13]                rdccr_delay+0x8         

  120   0%  47% 0.00     2243 cpu[10]                default_lock_delay+0x74 

  119   0%  47% 0.00     2158 cpu[58]                rdccr_delay+0x4         

  119   0%  47% 0.00     2489 cpu[24]                rdccr_delay+0x4         

  119   0%  47% 0.00     2085 cpu[14]                rdccr_delay+0x8         

  118   0%  48% 0.00     2064 cpu[59]                rdccr_delay+0x8         

  118   0%  48% 0.00     2187 cpu[47]                rdccr_delay+0x8         

  118   0%  48% 0.00     2277 cpu[35]                rdccr_delay+0x4         

  118   0%  48% 0.00     2063 cpu[27]                rdccr_delay+0x4         

  118   0%  49% 0.00     2259 cpu[10]                rdccr_delay+0x8         

  117   0%  49% 0.00     1937 cpu[26]                rdccr_delay+0x4         

  117   0%  49% 0.00     2174 cpu[11]                rdccr_delay+0x4         

  117   0%  49% 0.00     2516 cpu[8]                 rdccr_delay+0x8         

  117   0%  50% 0.00     2113 cpu[4]                 rdccr_delay+0x4         

  116   0%  50% 0.00     2228 cpu[61]                default_lock_delay+0x74 

  116   0%  50% 0.00     2111 cpu[44]                rdccr_delay+0x4         

  116   0%  51% 0.00     2285 cpu[42]                rdccr_delay+0x4         

  116   0%  51% 0.00     2432 cpu[37]                rdccr_delay+0x8         

  116   0%  51% 0.00     1997 cpu[27]                rdccr_delay+0x8         

  116   0%  51% 0.00     2472 cpu[24]                default_lock_delay+0x74 

  116   0%  52% 0.00     2113 cpu[6]                 default_lock_delay+0x74 

  116   0%  52% 0.00     2040 cpu[2]                 rdccr_delay+0x4         

  115   0%  52% 0.00     2219 cpu[54]                default_lock_delay+0x74 

  114   0%  52% 0.00     2221 cpu[38]                rdccr_delay+0x8         

  114   0%  53% 0.00     2466 cpu[32]                default_lock_delay+0x74 

  114   0%  53% 0.00     2148 cpu[25]                default_lock_delay+0x74 

  114   0%  53% 0.00     2103 cpu[20]                rdccr_delay+0x8         

  114   0%  53% 0.00     2259 cpu[9]                 rdccr_delay+0x8         

  113   0%  54% 0.00     2175 cpu[13]                rdccr_delay+0x4         

  112   0%  54% 0.00     2367 cpu[31]                default_lock_delay+0x74 

  112   0%  54% 0.00     2191 cpu[12]                rdccr_delay+0x8         

  112   0%  55% 0.00     2060 cpu[2]                 rdccr_delay+0x8         

  112   0%  55% 0.00     2174 cpu[1]                 rdccr_delay+0x4         

  111   0%  55% 0.00     2240 cpu[57]                rdccr_delay+0x4         

  111   0%  55% 0.00     2196 cpu[45]                default_lock_delay+0x74 

  110   0%  56% 0.00     2189 cpu[52]                default_lock_delay+0x74 

  108   0%  56% 0.00     2257 cpu[7]                 rdccr_delay+0x8         

  107   0%  56% 0.00     2224 cpu[53]                default_lock_delay+0x74 

  107   0%  56% 0.00     2236 cpu[34]                default_lock_delay+0x74 

  106   0%  57% 0.00     2267 cpu[18]                rdccr_delay+0x8         

  105   0%  57% 0.00     2224 cpu[62]                rdccr_delay+0x8         

   55   0%  57% 0.00     2643 cpu[8]                 cpu_halt+0x10c          

   54   0%  57% 0.00     2251 cpu[41]                cpu_halt+0x10c          

   54   0%  57% 0.00     2469 cpu[12]                cpu_halt+0x10c          

   54   0%  57% 0.00     2326 cpu[11]                cpu_halt+0x10c          

   54   0%  57% 0.00     2373 cpu[7]                 cpu_halt+0x10c          

   54   0%  58% 0.00     2380 cpu[5]                 cpu_halt+0x10c          

   54   0%  58% 0.00     2535 cpu[3]                 cpu_halt+0x10c          

   53   0%  58% 0.00     2409 cpu[34]                cpu_halt+0x10c          

   52   0%  58% 0.00     2691 cpu[24]                cpu_halt+0x10c          

   52   0%  58% 0.00     2365 cpu[19]                cpu_halt+0x10c          

   52   0%  58% 0.00     2520 cpu[17]                cpu_halt+0x10c          

   52   0%  58% 0.00     2345 cpu[9]                 cpu_halt+0x10c          

   51   0%  58% 0.00     2315 cpu[53]                cpu_halt+0x10c          

   51   0%  58% 0.00     2311 cpu[52]                cpu_halt+0x10c          

   51   0%  59% 0.00     2471 cpu[42]                cpu_halt+0x10c          

   51   0%  59% 0.00     2358 cpu[38]                cpu_halt+0x10c          

51 0% 59% 0.00 2367 cpu[21] cpu_halt+0x10c

What the h... are these rdccr_delay functions? Don't ask me :-) But looking at the code rcddr_delay appears somewhere in a mutex construct. Mutex? Sounds like we have a bad locking situation here....

Ok, let's check, if we have mutex spins:

# lockstat -C sleep 5

Adaptive mutex spin: 289321 events in 5.074 seconds (57021 events/sec)

Count indv cuml rcnt     nsec Lock                   Caller
-------------------------------------------------------------------------------
174359 60% 60% 0.00   863315 0x6003fe15a38        nfs4_start_open_seqid_sync+0x68
87472 30% 90% 0.00   424820 0x6003fe15e98         nfs4_start_open_seqid_sync+0x68
2572   1% 91% 0.00    41206 door_knob              door_return+0x1e8
2499   1% 92% 0.00    25247 door_knob              door_upcall_limited+0x27c
2469   1% 93% 0.00    36722 door_knob              door_return+0x23c
1664   1% 94% 0.00   260935 0x6003fe15e98          open_owner_rele+0x8
1506   1% 94% 0.00    53714 door_knob              door_return+0xbc
1490   1% 95% 0.00   168535 0x6003fe15e98          find_open_owner_nolock+0x2c
1484   1% 95% 0.00    54843 door_knob              door_return+0x44
1410   0% 96% 0.00    71905 door_knob              door_upcall_limited+0x94
884   0% 96% 0.00   769573 0x6003fe15a38          open_owner_rele+0x8
762   0% 96% 0.00   894325 0x6003fe15a38          find_open_owner_nolock+0x2c
730   0% 97% 0.00    75239 0x6003fe15e98          nfs4_start_open_seqid_sync+0x48
386   0% 97% 0.00   766709 0x6003fe15a38          nfs4_start_open_seqid_sync+0x48
359   0% 97% 0.00   196996 0x6003c393000          wait_for_recovery+0x4
357   0% 97% 0.00   558062 0x6003fe15a38          nfs4_end_open_seqid_sync+0xc
350   0% 97% 0.00    17691 0x6003c393000          nfs4_rfscall+0x48
317   0% 97% 0.00   895414 0x6003c2a4000          wait_for_recovery+0x4
307   0% 97% 0.00 1561398 0x60033a86e80          sigunintr+0x38
275   0% 97% 0.00   123310 0x6003c2a4000          nfs4_rfscall+0x48
274   0% 97% 0.00    24396 0x6003c393000          nfs4_rfscall+0x17c
271   0% 98% 0.00    92475 0x6003fe15e98          nfs4_get_otw_cred+0x34
268   0% 98% 0.00    73946 0x6003fe15e98          nfs4_end_open_seqid_sync+0xc
260   0% 98% 0.00   236558 0x60033a86e80          clock_tick_process+0xc8
257   0% 98% 0.00   483864 0x6003c393000          nfs4_start_open_seqid_sync+0x9c
219   0% 98% 0.00     4798 mod_lock               mod_hold_stub+0x18
211   0% 98% 0.00    64277 0x6003c2a4000          nfs4_rfscall+0x17c
197   0% 98% 0.00    18179 0x6003c393000          nfs4_start_open_seqid_sync+0x4
181   0% 98% 0.00   950176 0x6003c2a4000          nfs4_attr_cache+0xc
175   0% 98% 0.00   823990 0x60033a86e80          sigintr+0x2c
163   0% 98% 0.00   628697 0x6003fe15a38          nfs4_get_otw_cred+0x34
161   0% 98% 0.00   685230 0x6003fe15a38          nfs4open_otw+0xfa8
160   0% 98% 0.00   547855 0x6003fe15a38          open_owner_hold+0xc
159   0% 98% 0.00   643441 0x6003fe15a38          nfs4_get_otw_cred_by_osp+0x178
132   0% 98% 0.00   524536 0x60033a86e80          post_syscall+0x320
128   0% 98% 0.00    57596 0x6003c2a4000          nfs4_start_open_seqid_sync+0x4
123   0% 99% 0.00     4786 mod_lock               mod_release_stub+0x10
120   0% 99% 0.00    15053 0x6003c392000          find_open_owner+0x4
115   0% 99% 0.00    13426 0x6003fe15e98          nfs4open_otw+0xfa8
115   0% 99% 0.00   222285 0x6003c393000          find_open_owner+0x4
113   0% 99% 0.00   173366 0x6003c393000          nfs4_attr_cache+0xc
109   0% 99% 0.00     8928 0x6003c392000          nfs4write+0x174
108   0% 99% 0.00    14343 0x6003fe15e98          open_owner_hold+0xc
105   0% 99% 0.00   924250 0x6003c2a4000          nfs4_start_open_seqid_sync+0x9c
103   0% 99% 0.00    86073 0x6003fe15e98          nfs4_get_otw_cred_by_osp+0x178
94   0% 99% 0.00     2909 0x60031e81380          hook_run+0xd8
93   0% 99% 0.00     9617 0x6003c392000          nfs4write+0x78
89   0% 99% 0.00     9063 0x6003c392000          nfs4_rfscall+0x48
89   0% 99% 0.00     5480 0x6003c24ef28          mir_wput+0xc4
88   0% 99% 0.00     8461 0x6003c392000          nfs4_rfscall+0x17c
87   0% 99% 0.00 1146262 0x60033a86e80          lookuppnat+0x2c
84   0% 99% 0.00   295989 0x6003c393000          nfs4_delegation_accept+0x2c8
83   0% 99% 0.00     4963 0x6003c393ae8          nfs_rw_exit+0xc
79   0% 99% 0.00    10948 0x6003c392000          wait_for_recovery+0x4
75   0% 99% 0.00    13338 0x6003c393000          nfs4_start_fop+0x378
75   0% 99% 0.00   380086 0x6003c2a4000          find_open_owner+0x4
61   0% 99% 0.00     2234 zone0+0x18             zone_getspecific+0x8
59   0% 99% 0.00     3084 0x60031e81380          hook_run+0x10
57   0% 99% 0.00     6601 0x60034fb6a40          e1000g_rxfree_func+0x48
54   0% 99% 0.00    12081 0x6003c393ae8          nfs_rw_enter_sig+0x8
49   0% 99% 0.00     1100 0x6003505a6a0          e1000g_send+0x1534
43   0% 99% 0.00     5959 0x6003c392000          nfs4_async_start+0x278
43   0% 99% 0.00   641531 0x6003c2a4000          nfs4_delegation_accept+0x2c8
43   0% 99% 0.00   916554 0x6003c2a4000          nfs4open_otw+0xbc0
43   0% 99% 0.00     7897 0x60037b50a38          nfs_idmap_str_uid+0xb0
40   0% 99% 0.00    19531 0x6003c392000          nfs4write+0x4dc
38   0% 99% 0.00     1135 0x60037554900          tcp_wput+0xa4
37   0% 99% 0.00   101535 0x6003c2a4000          nfs4_start_fop+0x378
35   0% 99% 0.00     6144 0x60037b50a38          nfs_idmap_str_gid+0xb0
34   0% 99% 0.00    23000 0x6003c392000          nfs4write+0x234
30   0% 99% 0.00    14483 0x6003c393000          nfs4open_otw+0x5e4
28   0% 99% 0.00   452930 0x6003c2a4000          nfs4write+0x174
27   0% 99% 0.00 1138896 0x6003c2a4000          nfs4read+0x240

This looks like we have a congestion of nfs4 operations!

I was not able to find much more information about this issue, so I contacted my Solaris Guru of Choice. He was able to find a bug:

"NFSv4 can be much slower and more expensive than NFSv3 when creating files at high concurrency"

This sounded exactly what our application does. Putting spam-mails into folders, using parallel threads. :-)

Now it was time to open a support-case. About 10 days after opening the support case, we received an "Interim Diagnostic Relief (IDR)" -Patch.

And this is how it helped us (Sunday/Monday on the right):

Again, it was relatively easy to find the root-cause for our problem, with the help of a few *stat commands.

The question remains, why did it happen.

First of all NFSv4 is still a relatively new protocol, with new bugs. We have also tried out NFSv3, but what we've seen, for our workload (small files) version 4 is much more efficient.

Second, while our workload is a perfect fit for these CoolThread CPUs (normally ;-), we're still on new grounds.

My guess is, the world will see much more concurrency problems like these in the future.

DTrace to the rescue!

2010-08-30T20:02:00.005+02:00

We recently migrated data to some older servers and ran into a performance problem during peakhours.

Analysis

On our busiest days, we've seen the load go up to over 300. Luckily this is a SPARC system, and it was still somewhat responsive. Not bad for an old 2 Socket system...

Looking at the CPU utilization using vmstat, showed a high percentage of time spent in SYS.

You can see this in the two performance graphs (the graphs were made on a Sunday, with a lower load).

After looking at the processes with prstat -Lm (microstate accounting) and seeing the high SYS-percentage, we decided to look at what the kernel is doing.

Solaris has a nifty tool called lockstat. This is what it revealed:

# lockstat -i 133 -I sleep 5

Profiling interrupt: 1394 events in 5.241 seconds (266 events/sec)

Count indv cuml rcnt     nsec CPU+PIL                Caller
-------------------------------------------------------------------------------
214 15% 15% 0.00     1982 cpu0                   (usermode)
174 12% 28% 0.00     3809 cpu[0]                 (usermode)
105   8% 35% 0.00     6559 cpu[0]                 dnlc_purge_vp+0xa4
   53   4% 39% 0.00     3583 cpu0                   dnlc_purge_vp+0xa4
   35   3% 42% 0.00     2684 cpu0                   copyout_more+0x190
   31   2% 44% 0.00     7042 cpu[0]                 dnlc_purge_vp+0xa8
   24   2% 46% 0.00     6714 cpu[0]                 dnlc_purge_vp+0x148
   19   1% 47% 0.00     3929 cpu0                   dnlc_purge_vp+0xa8
   15   1% 48% 0.00     5041 cpu[0]                 mutex_enter+0x8
   13   1% 49% 0.00     3799 cpu0                   mutex_enter+0x8
   12   1% 50% 0.00     3449 cpu0                   dnlc_purge_vp+0x148
   10   1% 51% 0.00     2712 cpu[0]                 i_ddi_splx+0x1c
    9   1% 51% 0.00     2320 cpu0                   hwblkclr+0x94
    8   1% 52% 0.00     7265 cpu[0]                 dnlc_purge_vp+0xa0
    8   1% 52% 0.00     3183 cpu0                   hwblkclr+0x9c
    8   1% 53% 0.00     3397 cpu0                   hwblkclr+0x98
    7   1% 53% 0.00     2592 cpu0                   copyout_more+0x194
    5   0% 54% 0.00     2005 cpu0                   segmap_getmapflt+0x124
    4   0% 54% 0.00     3784 cpu[0]+11              disp_getwork+0x88
    4   0% 54% 0.00     1441 cpu[0]+11              spl6+0x14
    4   0% 55% 0.00     3253 cpu[0]                 spl6
    4   0% 55% 0.00     5103 cpu[0]                 _resume_from_idle+0x1f8
    4   0% 55% 0.00     2466 cpu0+0x6               pci_pbm_dma_sync+0x8c
    4   0% 56% 0.00     2735 cpu0                   hwblkclr+0xb0
    4   0% 56% 0.00     2555 cpu0                   dnlc_purge_vp+0xa0
    4   0% 56% 0.00     2998 cpu0                   page_lookup_create+0x90
    3   0% 56% 0.00     2449 cpu[0]+11              disp_getwork+0x15c
    3   0% 57% 0.00     3502 cpu[0]+11              disp_getwork+0xa4
    3   0% 57% 0.00     3233 cpu[0]+11              i_ddi_splx
    3   0% 57% 0.00     6187 cpu[0]                 r4find+0x14c
    3   0% 57% 0.00     5585 cpu[0]                 copyout+0x25c

There's a strange function stealing almost 20% of the interrupts: dnlc_purge_vp

The dnlc_purge_vp function belongs to the directory name lookup cache. It purges cache entries from time to time. You can read more about it here.

Next step was to find out how much time is spend in this function. A small dtrace script helped us:

purge.d: 

fbt::dnlc_purge_vp:entry
{
        self->t = timestamp;
}

fbt::dnlc_purge_vp:return
/self->t/
{
        @["latency"] = quantize((timestamp-self->t)/1000);
        self->t = 0;
}

Running it, gives us a nice latency distribution table:

#  dtrace -s purge.d                    
dtrace: script 'purge.d' matched 2 probes
^C

  latency                                           
           value  ------------- Distribution ------------- count    
             128 |                                         0        
             256 |                                         1        
             512 |                                         0        
            1024 |                                         2        
            2048 |@                                        6        
            4096 |@                                        10       
            8192 |@@@@@@                                   65       
           16384 |@@@@@@@@@@@@@@@@@@@@@@                   247      
           32768 |@@@@@@@@@@                               112      
           65536 |                                         3        
          131072 |                                         5        
          262144 |                                         3
          524288 |                                         0        

Looking at the result, we can see that most function calls take about 8-32ms. Really slow!

Solution

Knowing that the CPU is too slow for purging a large cache, we decided to decrease the cache from its default size to 25% of the default size. The ncsize kernel parameter is unfortunately not dynamic. We had to enter it in /etc/system and reboot the OS.

This was done on an indentical system with approx. the same load, and this is what lockstat reported after the reboot:

# lockstat -i 133 -I sleep 5   

Profiling interrupt: 1344 events in 5.054 seconds (266 events/sec)

Count indv cuml rcnt     nsec CPU+PIL                Caller                  
-------------------------------------------------------------------------------
   55   4%   4% 0.00     2301 cpu0                   (usermode)              
   47   3%   8% 0.00     2510 cpu[0]                 (usermode)              
   42   3%  11% 0.00     1717 cpu[0]                 splx+0x1c               
   41   3%  14% 0.00     1667 cpu0                   splx+0x1c               
   29   2%  16% 0.00     1718 cpu0                   idle+0x12c              
   26   2%  18% 0.00     1758 cpu[0]+11              disp_getwork+0x98       
   22   2%  19% 0.00     1511 cpu[0]                 disp_getwork+0x174      
   20   1%  21% 0.00     1249 cpu[0]+11              disp_getwork+0x78       
   20   1%  22% 0.00     1406 cpu0+0xb               disp_getwork+0x98       
   20   1%  24% 0.00     1627 cpu0+0xb               disp_getwork+0x88       
   20   1%  25% 0.00     1498 cpu0+0xb               i_ddi_splhigh+0x14      
   18   1%  27% 0.00     1324 cpu[0]+11              splx                    
   18   1%  28% 0.00     1663 cpu0                   disp_getwork+0x174      
   17   1%  29% 0.00     1592 cpu0+0xb               disp_getwork+0x78       
   16   1%  31% 0.00     1284 cpu[0]+11              i_ddi_splhigh+0x14      
   16   1%  32% 0.00     1500 cpu[0]                 disp_getwork+0x1b4      
   16   1%  33% 0.00     1602 cpu[0]                 idle+0x12c              
   16   1%  34% 0.00     1438 cpu[0]                 i_ddi_splhigh+0xc       
   16   1%  35% 0.00     1696 cpu0+0xb               splx                    
   14   1%  36% 0.00     1571 cpu0                   idle+0xf4               
   14   1%  37% 0.00     1411 cpu0                   i_ddi_splhigh           
   13   1%  38% 0.00     1664 cpu[0]                 i_ddi_splhigh           
   12   1%  39% 0.00     1697 cpu[0]                 idle+0xec           

...

There's no dnlc_purge_vp function in the first 40% of the interrupts!

Running the dtrace script also confirms, that purge times have dropped linearly to about 25%:

# dtrace -s purge.d
dtrace: script 'purge.d' matched 2 probes
^C

latency
           value ------------- Distribution ------------- count
             256 |                                         0
             512 |@                                        1
            1024 |@                                        2
            2048 |@@@@@@                                   10
            4096 |@@@@@@@@@@@@@@@@@@@@                     32
            8192 |@@@@@@@@@@@@                             19
           16384 |                                         0

Looking at the system over a day, the load and CPU utilization was much lower:

Conclusion

Solaris' dtrace tool is not just a marketing gag, but is real value for all production enviroments. We were able to find the bottleneck in no time (about 30 minutes of investigation + in this case reboot during off-peak hours).

Most importantly, we didn't have to risk production as dtrace is production safe.

Package Deployment with OpsCenter

2010-08-26T22:15:00.001+02:00

There has been some discussion on Constantins blog about working around IPS' scripting limitations.

I don't want to talk about the reasons, why IPS does not have classical pre/postinstall-scripts, but I want to demonstrate how this functionality could be achieved with Oracle's Enterprise Manager OpsCenter.

If you don't know OpsCenter, it's _the_ management tool from Oracle for Solaris, Unbreakable Linux and OracleVM.

OS Updates

In OpsCenter terminology Package deployments are called "OS Updates". OS Updates consist of Update Components (Packages, Patches and Configurations), Update Policies and Update Profiles. If an OS is to be updated, so called "Update Profile"-jobs will be sent to hosts run.

Update Profiles

There are two types of Update Profiles, System-defined and User-defined. What we're looking for are user defined profiles. A user-defined profile contains components. These components can be Packages, Pre/Postinstall-Scripts and Configuration files.

They can also contain macros to be run on the target system to return information about the system. This information can then be used to dynamically create a configuration file.

It is also possible to run probes, to check if pre-requisites are met.

Update Profiles can also contain other update profiles. (e.g. to create a Mail-Server profile or Web-Server profile)

In the picture we can see two Splunk Profiles. Below you can see some components, like the SMF Manifest or a postinstall script.

Update Components

Update components are organised into folders:

Configuration Files carry a version number.

Uploading configuration file (-templates) or scripts is simple:

Running OS Update Job

It is easy to run update jobs on one or several hosts. There are different options that can be set how to run the jobs...

While the job is running and after it's finished the job details can be monitored. Of course it makes sense to have good error handling in the pre/postscript.

Summary

The examples shown are with SysV packages, as OpsCenter for obvious reasons lacks IPS support at the moment. But it shows how scripts can be run before and after package installation. As an alternative to OpsCenter, the same can be achieved using e.g. Puppet, bcfg2 or cfenginge.

The nice thing about using a management tool is, to compare different systems, find differences and keep them standardized.

Core Dump Analysis with mdb/dbx

2010-07-15T10:20:00.000+02:00

We had a Java application core dump. pstack and jstack will show all threads, but does not reveal which thread's guilty. Finding this one thread is simple:

# mdb /usr/bin/java /var/core/core_hostname_java_8081_8081_1276625241_1986

mdb: core file data for mapping at ffb80000 not saved: Bad address
Loading modules: [ libumem.so.1 libc.so.1 libuutil.so.1 ld.so.1 ]
> $C
4d2fe5f8 libc.so.1`_lwp_kill+8(6, 0, 20f04, ff36932c, ff38a000, ff38abdc)
4d2fe658 libumem.so.1`umem_do_abort+0x1c(3c, 4d2fe5a8, 6, 20e40, ff376ad8, 0)
4d2fe6b8 libumem.so.1`umem_err_recoverable+0x7c(ff377b54, a, 20d38, 656ebd84, ff38d0e8, ff377b5f)
4d2fe718 libumem.so.1`process_free+0x114(59c2008, 1, 0, 3e3a1000, 1ec08, 656d3e9c)
4d2fe778 libxy_xyzclient_native.so.solaris`XYZfree+0x1b8(59c2008, 65725b48, 15b, 4, 45a, 4d2fe9f8)
4d2fe810 libxy_xyzclient_native.so.solaris`XYZ_XYZ_FreeUser+0x28(59c2008, 4d2fea64, 4d2fe9e0, ffffff80, 80000000, 0)
4d2fe880 libxy_xyzclient_native.so.solaris`Java_net_xyz_xyzserver_XYZUser_free+0x24(68204c4, 4d2fea64, 0, 4, 45a, 4d2fe9f8)
...

Or using dbx (included in Oracle Solaris Studio):

# dbx /usr/bin/java /var/core/core_hostname_java_8081_8081_1276625241_1986

 For information about new features see `help changes'
To remove this message, put `dbxenv suppress_startup_message 7.7' in your .dbxrc
Reading java
core file header read successfully
Reading ld.so.1
Reading libumem.so.1
... (omitted) ...
Reading libpthread.so.1
Reading libcmd.so.1
Reading libaio.so.1
WARNING!!
A loadobject was found with an unexpected checksum value.
See `help core mismatch' for details, and run `proc -map'
to see what checksum values were expected and found.
dbx: warning: Some symbolic information might be incorrect.
t@null (l@79) terminated by signal ABRT (Abort)
0xff2c642c: _postfork1_child+0x00ac:    add      %i4, 212, %o1
Current function is XYZfree
dbx: warning: can't find file "/tmp/builds/XYZ-UI-8.0.031/XYZ-UI-8.0.031-source/CommonLibraries/nplexlib/unix/../src/mdebug.c"
dbx: warning: see `help finding-files'
(dbx) lwps                                                                  
  l@1 LWP suspended in door_create_server()
  l@2 LWP suspended in _postfork1_child()
... (omitted) ...

  l@77 LWP suspended in _postfork1_child()
  l@78 LWP suspended in _postfork1_child()
o>l@79 signal SIGABRT in _postfork1_child()
  l@80 LWP suspended in libc_init()
  l@81 LWP suspended in _postfork1_child()
  l@82 LWP suspended in door_create_server()

... (omitted) ...

(dbx) select l@79

(dbx) where
  [1] _postfork1_child(0x6, 0x0, 0x20f04, 0xff36932c, 0xff38a000, 0xff38abdc), at 0xff2c642c 
  [2] umem_do_abort(0x3e, 0x68f7e2b8, 0x6, 0x20e40, 0xff376ad8, 0x0), at 0xff369188 
  [3] umem_err_recoverable(0xff377b54, 0xa, 0x20d38, 0x652ebd84, 0xff38d0e8, 0xff377b5f), at 0xff36932c 
  [4] process_free(0x7262008, 0x1, 0x0, 0x3e3a1000, 0x1ec08, 0x652d3e9c), at 0xff36b504 
=>[5] XYZfree(ptr = 0x7262008, f = 0x65325b48 "../src/xy_xyz_user.c", l = 347), line 311 in "mdebug.c" 

... (omitted) ...

Now off to the SW vendor... :-)

Read/Write Performance Observations

2010-07-12T22:24:00.000+02:00

As I mentioned in my previous post, we have now moved more active mailboxes to the ~~Sun~~ Oracle 7000 Storage System. Active means, incoming mails, POP3/IMAP4 accesses etc.

Reads

First we will take a look at disk read latency. We can see that more than 50% are lower than 10ms.

A sanity check on one of the NFS-clients confirms this

    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t  %w  %b device   

   73.6   36.5  494.4  317.7  0.0  0.3    0.1    2.4   1  22 filer:/filesystemb 

39.8 31.7 322.2 445.4 0.0 0.1 0.4 1.8 1 12 filer:/filesystemb

We can see that the average service time over this 10 second sample is around 2ms. Usually I'm not interpreting the %b value too much, other than if it constantly is at 100%. Newer file-systems read/write in bursts, which makes it not a good problem indicator.

Next we will take a look at the read I/Os. We can see a moderate number of read I/Os per disk.

We can also see the bandwith usage for this operation. For comparison I've marked the same physical disk.

Writes

Writes are handled differently by the Oracle Storage 7000 systems, as syncronous writes are written to the SLOG/SSD devices. Asynchronous writes are collected into the ARC and then flushed to disk. You can see this as long bars in the latency graph.

A different view of this is the I/O per second graph for writes. The yellow area on the graph are the SLOG devices. You can see an almost straight line, whereas the blue area has some peaks.

The last graph shows the same as I/O bytes per second graph. Here we see about the same peaks.

Read/Write-Ratio

Looking at the read/write-ratio, shows us, that we have much more write I/Os than read I/Os.

Summary

Analytics helps us tremendously in monitoring how the system behaves during migration. This is especially important, with workloads, that can not be easily simulated.

As we already had ZFS experience, the patterns have not been too surprising. What comes to me as a surprise is the high write portion. On our FC-attached storage array, we see a ~ 50%/50% read/write ratio for the same workload using VxFS. While not being a problem at all, I will investigate the reason for this further.

ARC Cache revisited

2010-07-09T21:36:00.001+02:00

As we move more and more active mailboxes onto our OpenStorage box, it's time to have a look at the ARC cache.

If you remember, I already blogged a while ago about the ARC. At that time we had only inactive mailboxes, with almost no access other than incoming mails.

This is how it looks with active mailboxes:

I've colored all the hits. As you can see, there is a huge amount of metadata hits and prefetched metadata hits. You can also see some data hits and prefetched data hits.

We're now constantly adding more and more mailboxes to the system, resulting in more and more metadata. As the amount of data grows L2ARC will become more important. Stay tuned for a blog entry about how the L2ARC behaves...

Btrfs or how to lose space

2010-06-21T23:27:00.000+02:00

On the linux-btrfs mailinglist there was an interesting entry about internal fragmentation in btrfs.

A basic test brought up many questions about the btrfs filesystem design. Btrfs is a filesystem that uses the b-tree algorithm. There has been a debate if it is a good idea to use b-trees for filesystems.

I'm not enough into algorithms, but I let you decide...

The test consists of a loop, creating as much 2k sized files as possible on a 1GB Filesystem:

# for i in $(seq 1000000); \

do dd if=/dev/zero of=/mnt/file_$i bs=2048 count=1; done

(terminated after getting "No space left on device" reports).

The result from Edward Shishkin (RedHat) was 59480 Files. This would give us 2048*59480 ~ 116MB. Or in other words, we would waste around 880MB of Space.

In the meanwhile, Chris Mason, inventor of btrfs created a patch for increased utilisation.

He was able to achieve 106894 Files. That's 208 MB or a waste of 800MB. I'm not sure what he meant by the comment about the duplicate of metadata. Maybe, If you took the duplicates away, you're able to store as twice as much data on it (putting data at risk?). It still wastes almost 60% of the space...

Next on the list was of course to see how ZFS behaves.

I've created a testpool from a 1GB File. The usable space according to zfs list is 984M. I was able to squeeze in 444555 files. This results in 868MB of used space.

If we compare this to the initial 1GB capacity, we lose about 13% for metadata etc. I think that's not much, if we think of all the validation and checksumming happening behind the curtains...

Now, someone might say, nobody stores that many small files. On our mail platform we do. So any wasted space cost $$$ in the end.

Real-Time visualization of Spamhaus with Splunk

2010-06-13T19:56:00.003+02:00

Static visualization is boring :-)

This time I've run the same search in real-time...

Spamhaus Blacklist visualized with Splunk

2010-06-12T09:48:00.003+02:00

I was interested in how the Spamhaus blacklist works, so I ran a Splunk search for 5 Minutes and generated a map with the results.

Every dot is at least one IP-Address listed (high probability of an infected machine). Impressive...

(Click to enlarge...)

Some OpenSolaris Flashdisk Tests

2010-05-29T22:15:00.002+02:00

I've done some "academic" tests with a STEC Mach8 IOPS Flash Disk and Opensolaris SNV_134

The test included measuring installation time (from USB Image), first boot time (importing SMF manifests takes time), and normal boot time (both after GRUB Menu until login screen).

The test was done on a Intel Core 2 Duo @ 2.4GHz Laptop and as a comparison on a EeePC 1000H with an Intel Atom CPU.

The Flashdisk was recognized immediatly:

Here are the measured times on my Core 2 Duo system:

Installation: 6'39''
First boot: 3'22''
Normal boot: 30''

Here are times for the EeePC with Atom CPU with SSD:

Installation: 17'24''
First boot: 3'50''
Normal boot: 54''

Normal boot time for EeePC with Atom CPU with Harddisk and OS 2009.06:

Normal boot: 1'25''

Opinion: Don't waste your money on an expensive SSD if your overall system is slowish. For comparison, the Atom boot time is only marginally better with SSD than with a HardDisk.

On a faster system, you get much more out of a Flashdisk. Remember that (Open-)Solaris was never the fastest system to boot, but I think 30s is a quite good achievement.

Real-Time Splunk on Android

2010-05-23T21:19:00.000+02:00

I've updated my Nexus One today with Froyo (Android 2.2)

Froyo contains Flash Support. First thing to try is of course Real-Time Splunking :-)

Storm Botnet Comeback

2010-05-02T23:11:00.006+02:00

Normally we see about 20-30 million incoming connections per day to our MTAs.

Around the 16th of March, we saw a drop in incoming connections.

Suddenly, after the 5th of April, there is a huge spike in connections, with a peak of almost 50 million connections.

As McAfee has reported, the Storm Botnet has made a Comeback.

Splunk on Android (Nexus One)

2010-05-02T20:35:00.005+02:00

Rumors are, that Flash will be available next month on Android devices such as the Google's Nexus One I own.

I was wondering how good Splunk's will work on the Nexus One, as it uses AJAX a lot.

Not bad at all (Click on image to enlarge).

Ok. We get a "missing flash" message, but even real-time search is working:

I would say, as soon as Flash is available, this is the ultimate Splunk Mobile Device.

I feel sorry for all iPhone users who will never get Flash...

GeoIP with Splunk

2010-04-19T22:05:00.003+02:00

People are checking their emails all over the world. Maybe they're stuck because of Eyjafjallajökull ...?

Fighting Spammers with Splunk 4.1

2010-04-17T07:59:00.017+02:00

I haven't blogged about Splunk for a while, but with Release 4.1 there are some new cool features, that helps us tremendously in fighting spammers.

Most of you may not know, that a substantial part of running an ISP mail platform consists of fighting abuse.

Almost all abuse cases are caused by Spammers. Their main target is to control as many mailbox accounts as possible, where they can send spam from. Spammers can send Spam through bot-nets, acquire passwords through phishing attacks, or just do a smpt-auth brute-force attack.

Anyways, the Internet is 24x7, Spammers never sleep and we do neither. There is always someone on-call.

I want to show you, how we currently detect abuse on our platform, and what we do against it.

Detecting Abuse

There are many ways how to detect abuse. I don't want to go into too many details, and also, I don't want to reveal everything we do, as Spammers might read this :-)

One popular way is to count the number of "User unknowns" status messages from the remote mail server. Spammers own address-lists. Often the quality of these lists is bad and these lists contain email addresses that don't exist anymore.

What we do is running a saved search periodically and if we count a certain amount of such user unknown error codes, we trigger an alarm by e-mail and SMS.

SMS Alarming

If the saved search triggers an alarm, it calls a perl script. The script gets different arguments, like the job-id for this search. Using this information, a REST call is done to the Splunk Search-Head to give out the results for this search. The results are formated in XML, which then is parsed using XPATH. After that, an email message is send to an SMS-Gatewas resulting in following alarm on a mobile phone.

The SMS shows basic information, so that the poor guy on-call can decide if it is a false positive or not. If it's obviously spam, things get interesting.

Finding the Abuser
As I mentioned earlier, Splunk does not only trigger an SMS, but also sends an email for this alert.

Clicking on the result link opens the Splunk Web Interface.

For some searches you can just click on any field to drill down to the events, but because we use "fillnull", we can't do that. Instead we will just modify the search slightly. This will give us all events.

From here we can select the options for the field "transaction_id". You can see an option "Show This Transaction Only". Pressing this will open a single transaction:

Blocking the Abuser

Now comes the interesting part. You can see two options, "Block smtp auth", and "Block webmail". Clicking on these, will issue an HTTP Post to another system, blocking all access to this account.

Job almost done.

Informing the Account Owner

As all access is blocked now, we will report the incident to our abuse team. The abuse team's tracking system will receive all the necessary information, as well as the original log-entries as an evidence. After that, the account owner will be informed about this abuse case.

Summary

Splunk 4.1 makes life for us much easier. We don't have to copy-paste information into various applications. Everything can be done by simply clicking on it.

Sun Ray Dualhead on OpenSolaris

2010-04-16T15:31:00.004+02:00

It wasn't hard to set up at all, took about 2h to remember all the commands ;-)

Cloud of 100 Blades

2010-01-12T19:32:00.005+01:00

800 CPU Cores
6400 HW Threads
3.2 TB RAM
600 1Gb Ports

I guess we could call this a small cloud :-)

Santa's got a huge sleigh this year...

2009-12-29T17:21:00.004+01:00

Delivery on the 24.12.2009

18 Pallets
365 Boxes (One for every day I was a good boy)
2.7 Tons

Efficient metadata caching

2009-12-10T23:06:00.006+01:00

In my last post I was talking about 1 Million mailboxes. Each of them is a directory with several subdirectories, like Trash, Sent Items etc.

The mailbox directory itself lies 4 directories below the root node (like /a/b/c/mailbox). The hierarchy is managed by our mail-store application.

I don't know the average number of files/directory, but let's assume, each mailbox consists in average of 20 files/directories, we would currently have about 20'000'000 inodes.

Mailbox access is mostly random. We don't know when a mail is coming in, we also don't know about when a user is reading his mails. What we now from experience is, that a lot of time is spend in looking up metadata.

With mostly random access (we measured it as ~ 55% write / 45% read a while ago), and the amount of data, the chance to identify a data working set is quite low. Ok, maybe recently received emails could be part of a "working-set".

But wouldn't it be great if we could cache as much metadata as possible?

Roch Bourbonnais wrote a blog entry a while ago about inodes on zfs. This is by no means a scientific analysis, but let's take his numbers:

"23.8M files consuming 27GB of data. Basically less than 1.2K of used disk space per KB of files"

Let's say, each mail/directory uses 0.2K, and we have 20'000'000 of them, we would currently have 3.8GB of inode data. No problem to cache that. I certainly have to investigate a little bit more what kind of metadata the ARC Cache is caching.

Thanks to analytics, I can at least do a bit of sanity checking, it currently shows me that around 11G inside ARC are used for metadata caching.

If we take another view, we can see that not only do we have metadata cached, it is also heavily used. In this picture I have colored all cache hits.

Lessons learned today:

-ZFS does not waste space for inodes and therefore not cache.
-ARC is very efficient

Questions to be answered:

-What does "metadata" include?

The noise of 1'000'000 inactive mailboxes

2009-12-02T10:22:00.008+01:00

We have now migrated all inactive mailboxes (some may obviously be active again) to one 7410 Cluster.

What you can see is the IO generated by these boxes. Even if the mailboxes are abandoned they receive mails (spam, newsletters etc.)

Storage2/HDD4 and storage2/HDD8 are again the mirrored SLOG devices. As we can see here, they don't have any problems at all with the write load. If you look at all the other HDDs you see the low IOPS numbers

Looking at how many bytes per seconds are going through the disks we can see that the SLOGs are busy collecting all synchronous bits and bytes.

The slow 1TB disks get about ~700k of data per second. Looking at e.g. HDD11 we see a low number of IOPS. I would guess the average IO size is about 60-70kB. As a reference, an email is around 4k to 8k.

What this means: We get larger IOs to the disk thanks to the slog.

Thanks, mighty Logzilla :-)

SLOG Latency

2009-10-18T19:04:00.009+02:00

After reading Brendan's newest blog entry, I was curious about what kind of slog latency we can see for our data migration load.

To remind you, only synchronous writes go into the slog SSD devices.

As this is a migration running, we can see mostly NFS write operations:

In our configuration the SSD slog is mirrored (HDD4 and HDD8). Hence the same number of IOPS:

The next picture shows us the latency for our SDD SLOG Device HDD 4. We can see here that latencies start at 79 us and are mostly under 200 us. There are some outliers, but approx. 95% are under 500 us:

This matches quite well with the values Brendan blogged about (137-181 us), which includes NFSv3 latency. For reference (no picture here), we can see latencies of about 170-500 us mostly for NFSv4.

By the way. SLOG Devices are mostly one way devices, as shown here. Only if things go really bad, they are read from...

Resilvering progress...found!

2009-10-06T20:48:00.002+02:00

Found the CLI menu for resilvering progress :-)

file1:configuration storage (pool-1)> show
Pools:

POOL OWNER DATA PROFILE LOG PROFILE STATUS
pool = pool-1 file1 mirror_nspf log_mirror_nspf degraded

Properties:
pool = pool-1
status = degraded
owner = file1
profile = mirror_nspf
log_profile = log_mirror
cache_profile = cache_stripe
scrub = resilver in progress for 4h46m, 83.85% done, 0h55m to go

High IOPS for 1TB Disks

2009-10-01T21:45:00.003+02:00

Wondering how 1TB disk can have such a high IOPS.

HDD8 and HDD4 are Log-Devices (SSD)

UPDATE: For the moment I assume, these are writes to the disk cache.

Being bored....

2009-10-01T07:01:00.004+02:00

...while doing 22536 NFS ops per second, and doing gzip-2 at the same time.

HSP really works. NFS synchronous operations get "eaten" by the SSD devices (1133 IOPS).

Trekkie Stuff...

2009-09-01T20:41:00.008+02:00

Enterprise Warp Core:

Borg Cube:

PS: We all know who won in the end ;-)

Opensolaris, Huawei E220, Swisscom and Sunrise

2008-11-03T22:25:00.002+01:00

I was able to open a 3G connection to Swisscom and Sunrise using a Huawei E220 3G Modem under Opensolaris.

Here are the config files (If PIN is enabled on the SIM, add OK "AT+CPIN=????" to the chat script)

Swisscom:

/etc/ppp/chat-swisscom:


ABORT BUSY
ABORT 'NO CARRIER'
ABORT ERROR
REPORT CONNECT
TIMEOUT 120
"" "AT&F"
OK "ATZ"
OK "ATQ0 V1 E1 S0=0 &C1 &D2"
#OK "AT+CPIN=????"
OK 'AT+CGDCONT=1,"IP","gprs.swisscom.ch"'
SAY "Calling Swisscom"
OK "ATDT*99***1#"
TIMEOUT 120
CONNECT ''

/etc/ppp/peers/swisscom:


term/1
115200
connect "/usr/bin/chat -V -t15 -f /etc/ppp/chat-swisscom"
idle 7200
lock
crtscts
noipdefault
modem
user "gprs"
password "gprs"
noauth
passive
usepeerdns
defaultroute
connect-delay 6000
novj
nodetach

Sunrise:

/etc/ppp/chat-sunrise:


ABORT BUSY
ABORT 'NO CARRIER'
ABORT ERROR
REPORT CONNECT
TIMEOUT 120
"" "AT&F"
OK "ATZ"
OK 'ATS7=60'
#OK "AT+CPIN=????"
OK "AT+COPS?"
OK "AT&V"
OK "AT+CSQ"
OK 'AT+CFUN=?'
OK 'AT+CGDCONT=?'
OK 'AT+CPBR=?'
OK 'AT+CPBS=?'
OK 'AT+CGDCONT=1,"IP","Internet"'
SAY "Calling Sunrise"
OK 'ATDT*99***1#'
TIMEOUT 120
CONNECT ''

/etc/ppp/peers:


term/1
115200
connect "/usr/bin/chat -V -t15 -f /etc/ppp/chat-sunrise"
idle 7200
lock
crtscts
noipdefault
modem
user ""
password ""
noauth
passive
usepeerdns
defaultroute
connect-delay 6000
novj
nodetach

Don't forget to adjust the term/? line to reflect your /dev/term/? device.

After this, just fire up "pppd call swisscom" or "pppd call sunrise" and adjust your resolv.conf. The DNS Servers are in the output. For debugging just add -d to the pppd command.

There are a few problems with the Huawei E220, as it is recognized as a storage device first, and not as a serial device.

See the Opensolaris Forum

Most of the time the modem is recognized correctly when the Modem is plugged in before booting, and doing a reconfiguration boot with grub. ( press "e" -> append "-rv" -> -> press "b" )

There is also a patch for the Eee PC's Serial USB Port driver. See Masafumi's Blog.

Good luck!

Connecting Opensolaris to a Cisco VPN

2008-11-02T22:47:00.007+01:00

I finally got my Opensolaris box hooked up to a Cisco VPN:

1. Get the tun/tap driver from Kazuyoshi. This driver is used for creating a using between the client and the Cisco VPN router.

2. Compile and install the driver:


pkg install sunstudioexpress
export CC=/opt/SunStudioExpress/bin/cc
./configure
make
make install

3. Download the vpnc client. This program handels the vpn connection. I've used the version 0.5.1.

4. Get gmake


pkg install SUNWgmake

5. Adjust installation paths (my personal preferences):


Makefile:

PREFIX=/opt/vpnc
ETCDIR=/opt/vpnc/etc

config.c (hardcoded locations):

Line 250: return "/opt/vpnc/etc/ssl/certs";
Line 270: return "/opt/vpnc/etc/vpnc-script";
Line 275: return "/var/run/vpnc.pid";
Line 541: ... : /opt/vpnc/etc/", ...
Line 760: ... "/opt/vpnc/etc/default.conf" ...
Line 761: ... "/opt/vpnc/etc/vpnc.conf" ...

gmake
gmake install

6. Convert the pcf file into vpnc format using /opt/vpnc/pcf2vpnc. Store the file in /opt/vpnc/etc

7. Now comes the tricky part. Create the /opt/vpnc/etc/vpnc-script -script. The script opens the connection and sets up the appropriate routing.

My target was to just have a couple of connections go through the tunnel instead of all.

Attention! If you want to have a default route set into the tunnel, be sure to add some direct routes to your vpn gateway before the default route points to the tunnel. Otherwise the vpn gateway will become unreachable and the tunnel goes down. Your remote gateway can be found in your conf file ("IPSec gateway" line).

Depending on what you want to achieve, you have to configure your DNS servers in /etc/resolv.conf manually.

Here is my sample /opt/vpnc/etc/vpnc-script :


#!/bin/sh
#* reason                       -- why this script was called, one of: pre-init connect disconnect
#* VPNGATEWAY                   -- vpn gateway address (always present)
#* TUNDEV                       -- tunnel device (always present)
#* INTERNAL_IP4_ADDRESS         -- address (always present)
#* INTERNAL_IP4_NETMASK         -- netmask (often unset)
#* INTERNAL_IP4_DNS             -- list of dns serverss
#* INTERNAL_IP4_NBNS            -- list of wins servers
#* CISCO_DEF_DOMAIN             -- default domain name
#* CISCO_BANNER                 -- banner from server
#* CISCO_SPLIT_INC              -- number of networks in split-network-list
#* CISCO_SPLIT_INC_%d_ADDR      -- network address
#* CISCO_SPLIT_INC_%d_MASK      -- subnet mask (for example: 255.255.255.0)
#* CISCO_SPLIT_INC_%d_MASKLEN   -- subnet masklen (for example: 24)
#* CISCO_SPLIT_INC_%d_PROTOCOL  -- protocol (often just 0)
#* CISCO_SPLIT_INC_%d_SPORT     -- source port (often just 0)
#* CISCO_SPLIT_INC_%d_DPORT     -- destination port (often just 0)

# =========== script (variable) setup ====================================

PATH=/sbin:/usr/sbin:$PATH

FULL_SCRIPTNAME=/usr/local/sbin/vpnc
SCRIPTNAME=`basename $FULL_SCRIPTNAME`

# =========== tunnel interface handling ====================================

do_ifconfig() {

       ifconfig "$TUNDEV" inet "$INTERNAL_IP4_ADDRESS" "$INTERNAL_IP4_ADDRESS" netmask 255.255.255.255 mtu 1412 up
}

# =========== route handling ====================================

get_default_gw() {
       # isn't -n supposed to give --numeric output?
               # apperently not...
               # Get rid of lines containing IPv6 addresses (':')
               netstat -r -n | sed 's/default/0.0.0.0/' | sed 's/^.*:.*$//' | grep '^0.0.0.0' | awk '{print $2}'
}
      
do_pre_init() {
echo "do_pre_init"
}

do_connect() {
       if [ -n "$CISCO_BANNER" ]; then
               echo "Connect Banner:"
               echo "$CISCO_BANNER" | while read LINE ; do echo "|" "$LINE" ; done
               echo
       fi
      
       do_ifconfig
       if [ -n "$CISCO_SPLIT_INC" ]; then
               i=0
               while [ $i -lt $CISCO_SPLIT_INC ] ; do
                       eval NETWORK="\${CISCO_SPLIT_INC_${i}_ADDR}"
                       eval NETMASK="\${CISCO_SPLIT_INC_${i}_MASK}"
                       eval NETMASKLEN="\${CISCO_SPLIT_INC_${i}_MASKLEN}"
                       i=`expr $i + 1`
               done

       fi
      
       # Hosts 1&2 & 3
       add_host_route "xx.xx.xx.xx"
       add_host_route "xx.xx.xx.xy"
       add_host_route "xx.xx.xx.xz"

       for i in $INTERNAL_IP4_DNS ; do
               add_host_route "$i"
       done
}

do_disconnect() {
       if [ -n "$CISCO_SPLIT_INC" ]; then
               i=0
               while [ $i -lt $CISCO_SPLIT_INC ] ; do
                       eval NETWORK="\${CISCO_SPLIT_INC_${i}_ADDR}"
                       eval NETMASK="\${CISCO_SPLIT_INC_${i}_MASK}"
                       eval NETMASKLEN="\${CISCO_SPLIT_INC_${i}_MASKLEN}"
                       i=`expr $i + 1`
               done
       fi
      
       # Delete all routes again
       del_host_route "xx.xx.xx.xx"
       del_host_route "xx.xx.xx.xy"
       del_host_route "xx.xx.xx.xy"


       for i in $INTERNAL_IP4_DNS ; do
               del_host_route "$i"
       done
}

add_host_route() {
       HOST="$1"
       route add "$HOST" "$INTERNAL_IP4_ADDRESS" -interface
       }

del_host_route() {
       HOST="$1"
       route delete "$HOST" "$INTERNAL_IP4_ADDRESS" -interface
       }


#### Main

if [ -z "$reason" ]; then
       echo "this script must be called from vpnc" 1>&2
       exit 1
fi

case "$reason" in
       pre-init)
               do_pre_init
               ;;
       connect)
               do_connect
               ;;
       disconnect)
               do_disconnect
               ;;
       *)
               echo "unknown reason '$reason'. Maybe vpnc-script is out of date" 1>&2
               exit 1
               ;;
esac

exit 0

8. Now you should be able to connect to your vpn:


/opt/vpnc/sbin/vpnc myvpn.conf

9.The output should look like this:


 /usr/local/sbin/vpnc cia.conf
Enter password for tzhbomi5@bwpir.bluewin.ch: 
do_pre_init
add host xx.xx.xx.xx: gateway zz.zz.zz.zz
add host xx.xx.xx.xy: gateway zz.zz.zz.zz
add host xx.xx.xx.xz: gateway zz.zz.zz.zz
VPNC started in background (pid: 3971)...

10. The interfaces look like this, where zz.zz.zz.zz is the IP Address that got assigned from the other side of the tunnel. The tun0 device was automatically created by vpnc·


ifconfig -a
lo0: flags=2001000849 mtu 8232 index 1
 inet 127.0.0.1 netmask ff000000 
rge0: flags=201004843 mtu 1500 index 2
 inet 192.168.1.35 netmask ffffff00 broadcast 192.168.1.255
 ether 0:22:15:5e:61:2b 
tun0: flags=10010008d1 mtu 1412 index 4
 inet zz.zz.zz.zz --> zz.zz.zz.zz netmask ffffffff 
 ether 2:0:0:0:0:0

OpenSolaris 2008.05, BrandZ and Zattoo

2008-05-11T23:35:00.002+02:00

I've been using OpenSolaris 2008.05 for about a week, and despite some small bugs, I really fell in love.

Until now I did not have the time to play around with Nevada releases, but OpenSolaris 2008.05 could really be my future #1 desktop (beside my Sunray...).

Things that worked so far:
-Getting Windows inside Virtualbox (yeah there are some apps still left running only on windows..)
-CentOS in a Branded Linux Zone (experimental Linux 2.6 support)
-Skype in a Branded Linux Zone(without sound yet)
-Zattoo in a Branded Linux Zone (without sound yet)

What does not work yet:
-TUN for Cisco VPNs
-ACPI (there are some drivers...)
-Sun Secure Global Desktop Client (at least the automatic client download...)

What's left to say?

Thanks to the OpenSolaris Community for all efforts.

OpenSolaris Rocks!!!

Using wget for downloads.oracle.com

2008-04-14T09:20:00.003+02:00

Downloading from oracle.com using wget is simple.

-First go to downloads.oracle.com and select the software to be downloaded

-Log in with your account and accecpt the license

-Copy the download link to your clipboard

-Find your cookies.txt in your $HOME

-Use wget:

$ wget --load-cookies=$HOME/.mozilla/default/.../cookies.txt -c [your url]

-Now you should be able to download the software

-This should also work for other sites.

Debugging sendmail

2007-11-27T13:50:00.000+01:00

To debug outgoing mail use following command

# /usr/lib/sendmail -d -f root@hostname -ODeliveryMode=i recipient@hostname

I've got a green brain

2007-08-13T22:27:00.000+02:00

Your Brain is Green

Of all the brain types, yours has the most balance.
You are able to see all sides to most problems and are a good problem solver.
You need time to work out your thoughts, but you don't get stuck in bad thinking patterns.

You tend to spend a lot of time thinking about the future, philosophy, and relationships (both personal and intellectual).

What Color Is Your Brain?

ZFS Rocks

2007-07-22T10:23:00.000+02:00

Jeff Bonwick writes about ZFS license announcements and how it rocks.

ZFS Take-Off

2007-07-21T15:03:00.001+02:00

Robin Haris (zdnet) and Jörg (c0t0d0s0) are writing about RAID6 respectivly ZFS.

RAID6 will surely be a marketing success as most people do not know about ZFS, or are thinking that making the move from RAID5 to RAID6 will solve all their problems. Those companies who have heard about ZFS have certainly had a look at it.

Most companies are rather conservative when implementing new technology. This is not a bad thing, especially when trusting your precious data to a new filesystem.

Paradoxically, without proper checksumming like ZFS does, your data could be at higher risk, even if ZFS is a rather new technology.

While there have been some problems with ZFS, none of them have affected the on-disk data. This is certainly the result of thoroughly testing ZFS like no other filesystem (leaving real-world "testing" beside).

There are still some issues, that may prevent ZFS to be deployed in a broader area:

-Performance issues on Storage Array with stable storage (not ignoring cache flush)
-No dynamic LUN resizing (not really a ZFS issue)
-Database performance may not be at UFS DirectIO level (work is on the way)
-No long-term database performance experience available
-Booting from ZFS not yet integrated
-3rd Party support missing (e.g. Backup solutions not yet there)

If Sun is working on these technical issues, and I know they are, my guess is that ZFS will really take off in a timeframe of 2 years. Compared with the age of UFS this is a short chapter.

Again ZFS performance improvements for databases

2007-07-19T22:07:00.000+02:00

There is a new fix to improve performance for databases on ZFS.

Can't wait to see OLTP benchmarks where ZFS is being faster than UFS with DirectIO for.

Oh, and did you know there is some work going on for getting the ZIL onto seperate devices (NVRAM or Solid State Disks)

(For those who don't know what the ZIL is, look here)

Xen code drop to OpenSolaris

2007-07-19T21:41:00.000+02:00

After almost waiting a year, the Lego bricks are falling neatly into place. This means, that it is finally possible to run Windows under Solaris (where needed :-).

Splunk 3.0 with Access-Control

2007-07-18T22:37:00.000+02:00

Yeaah!!!

Just found out that Splunk 3.0 will support access control. This means e.g., that developers can debug production problems without logging in to that host. They will see only logfiles relevant to finding the problem...

This is a huge step forward, as logs often contain classified data.

Where should security happen?

2007-07-18T22:04:00.000+02:00

As close to the data as possible!

Yesterday's post from Erik reminded me about a paradigm, that came up when I implemented the SSH Tectia Suite. It's the question where to do security properly. The answer is as close to the data as possible.

The problem with today's corporate networks is, that the "enemy" is already inside. There are so many people (internal/external) connecting to a company's network, which makes firewalls almost irrelevant. This effect is called deperimeterization.

Firewalls have a false reputation, that they protect everything. But because there are so many people who have access to both sides of firewalls, this doesn't make it very secure.

What could be a new approach? The Jericho Forum (a security focused group) says: "Individual Hosts should be able to defend themselves".

I certainly agree with that. Most operating systems contain integrated firewalls waiting for activation. Many applications provide extended authentication features and encryption (e.g. TLS/SSL). Not to forget the SSH protocol for managing the operating system instead of telnet.

While in theory you could take all firewalls away, and rely on host security, in practice you wouldn't do that of course. As an analogy to real life, you would certainly lock the gate to your stately home...

Paul Murphy clarifies the Sun Ray "difference"

2007-07-17T22:20:00.000+02:00

In today's blog, Paul Murphy lists advantages of the Sun Ray technology. This as an answer to a comment of Erik Engbrecht (a regular visitor to Murph's blog).

Of course, Erik has already answered in his blog.

While Erik certainly makes some valid points, I personally believe that having the desktop processing happening in the datacenter would be for a lot of companies the best approach.

I worked for several banks, and you wouldn't believe me, the investments done or planned to make desktops/laptops secure (harddisk encryption, USB-port-locking software, reverse-firewalls, virus-scanners, security audit tools, etc.)

Most of these security activities just aren't needed with a stateless device.

Another point was made, that Sun Rays are dependent on a working network connection. As more and more vital information is kept on servers that require online access, you already are dependent of a connection to your company's network.

Offline work usually requires documents to be carried with in paper form (bad!) or on harddisk. The later would again require harddisk encryption.

Do you trust harddisk encryption made in China?

Links for 2007-07-17

2007-07-17T21:32:00.000+02:00

Comparison of open source configuration management software
(Wikipedia)
Virtual Desktop Talk (Podcast on desktop virtualization)
Sun Desktop Virtualization Solution Blueprint (with VMWare)
Win4Solaris (Running Windows on Solaris)

SunRay Stuff

2007-07-16T22:30:00.001+02:00

ThinGuy has a few interesting blog entries...

First of all there are some Youtube movies about the Sun/Mitel partnership. This sounds like a great deal. The deal consists of two parts. A Multi-Instance Call Server (I guess this is something like a phone switch), and a unified solution for SunRays and the Mitel IP phone. This allows to hotdesk not only between SunRays, but also between IP phone. You can find more information here.

Another entry in ThinGuy's blog sounds also promising. He will talk in august about the upcoming SunRay Software 4.2. He promises some "trendy" new features for desktop virtualisation. As always, these kind of product release events are never around the corner...

I really believe that in the next 1-2 years desktop virtualization will be the next big management buzzword (not in the negative meaning).

The only thing Sun desperately needs if they want SunRays to take off, are salesmen who really want to sell thin clients. Selling Sunrays is certainly harder than selling big boxes, but hey, take it as a challenge!

But maybe Sun salesmen just don't understand the real-life problems of todays desktops and how thin-clients are a solution for most of these problems...

Links for 2007-07-15

2007-07-15T21:53:00.000+02:00

Seattle Conference on Scalability Videos (from Storagemojo)
IT Jungle about Oracle 11g
IT Jungle about AIX 6.1 Beta
Hitachi Data Systems, Upcoming Webinars
storagearchitect.blogspot.com

Configuration Engines for Unix

2007-07-15T10:06:00.000+02:00

As a system administrator, there is one problem that is persistent. Standardizing and keeping track of configuration changes.

Standardizing begins with the installation of a system. All major unix brands have their own installation methods. As mainly a Solaris administrator, I'm very familiar with the Jumpstart framework.

Using plain vanilla jumpstart is ok, if no customization in addition to the OS is needed (special configurations/application installation)

For advanced customization, Sun Professional Services UK developed the JET framework. JET is an addition to Jumpstart. The advantage of JET is in its usage of template files. All information about a client to install is kept in one file. The framework provides a simple way to add additional software, make additional software changes.

With JET it is possible to get a host running with all its settings and applications. But,
as soon as there are changes on a specific host, which could affect standardization, those changes have to be propagated towards JET.

A couple of years ago, when we used our own framework on top of Jumpstart, we already had this discussion, about getting changes back to Jumpstart. We never found a real solution to this problem. Sometimes, changes were forgot by human error (lazyness?), or some changes would not fit into the framework.

Fortunatly there are others, that have had the same problem. After googling some time, I found three configuration engines:

While I haven't looked at these tools in detail, all of them are managing configuration files from a central host. Local configuration changes are always initiated from a central host. The new configuration will either be pushed from the central host or pulled from the local host. If somebody changes configuration files locally they will be overwritten. The local configurations can be generated dynamically by rules.

The more I think about it, the right way seems to be to install a plain-vanilla OS, then install additional software packages (the configuration engines support this too), and finally push the configuration to the host.

This would make it simple to reinstall or upgrading the OS on a host. Jumpstart could be used in a plain-vanilla configuration, with only needing the configuration engine to be installed.

I will certainly further investigate the tools above.

Using ZFS clones with several Application instances

2007-07-12T22:06:00.000+02:00

This was an interesting blog entry about E25Ks, DTrace and ZFS.

One thing I was also thinking about, was the performance gains with ZFS clones, when running several instances of Applications using mostly the same data.

Quote:

"Then came a flash of inspiration. Using clones of a ZFS snapshot of the data together with Zones it was possible to partition multiple instances of the application. But the really cool bit is that ZFS snapshots are almost instant and virtually free.

ZFS clones are implemented using copy-on-write relative to a snapshot. This means that most of the storage blocks on disk and filesystem cache in RAM can be shared across all instances. Although snapshots and partitioning are possible on other systems, they are not instant, and they are unable to share RAM."

I had this idea, when I was thinking about using Solaris as a Xen Dom0 and running several identical (at least in the beginning) MS-Windows instances on Xen DomUs. The cloned MS-Windows images would be located on ZFS clones.

Most of the blocks would then reside in the memory of Dom0. I guess this would certainly improve performance.

The OS images could of course be also served over e.g. ZFS iSCSI Target devices, but the effect would be the same...

Splunk 3.0

2007-07-12T21:36:00.000+02:00

Since I read about Splunk on Ben Rockwood's blog, I'm a huge fan. I even got a Splunk baseball cap and a T-Shirt.

At my former employer, I've implemented Splunk to collect system logs for system monitoring and compliance checks/reporting.

Version 3.0 (still in beta) seems to be a huge step forwards. Reporting e.g. is now very sophisticated, allowing one to create many kinds of reports (charts, tables).

To get a quick overview over different environment aspects, it is possible to create user/role dashboards.

In the beginning Splunk was mainly meant for sucking only log files in, the target has now changed to index any kind of unstructured data.

I'm very much interested in loading configuration files and monitor these for changes (security monitoring/audits anyone?). It is also possible to periodically index command outputs. This could be used for recording performance data (output from e.g. iostat, vmstat, etc.). The output from a config file or a command, looks just like any other multi-line event.

I think this feature is what differentiates Splunk from competitors. Collecting log data is one thing, collecting and analyzing any unstructured data is more difficult. Here Splunk has unique features.

In the near future I will write more about, what I think Splunk could be used for.