Thursday Nov 14, 2013

Performance Analysis of Oracle Traffic Director or Web Server

Performance Analysis of Oracle Trafiic Director or Oracle iPlanet Web Server using Oracle Sun Solaris Studio Performance Analyzer and DTrace scripts.

In this blog I will show how to use the Sun Studio Collector and Performance Analyzer and DTrace script to measure the performance.

1. Using Oracle Solaris Studio 12.2 Performance Analyzer with Oracle Traffic Director or Oracle iPlanet Web Server

Thanx to Basant for teaching me collector and analyzer and thanx to Julien for his help on DTrace scripts.

Install Sun Studio 12. Lets say is installed in /opt/SUNWSpro.

1.1 setting up ~/.er.rc

cat ~/.er.rc
dmetrics e.user:i.user:e!wall:i!wall:e.total:i.total:e.system:i.system:e!wait: \
i!wait:e!lock:i!lock:e!text:i!text:e!data:i!data:e!owait:i!owait:!size:!address:name
dsort e.user
scc basic:version:warn:parallel:query:loop:pipe:inline:memops:fe:cg
dcc basic:version:warn:parallel:query:loop:pipe:inline:memops:fe:cg:src
sthresh 75
dthresh 75
name long
view user
tlmode thread:root:depth=10
tldata sample:clock:hwc:heaptrace:synctrace:mpitrace:msgtrace:datarace
setpath $expts:.
tabs functions:callers-callees:source:disasm:timeline:header:
en_desc on

1.2 Collecting Data Using the collect Command

1.2.1& Run the Collector  using the collect command

# collect collect-options program program-arguments

For OTD or Web Server we edit start script bin/startserv to have a new --collect option as shown below 

Red color lines are the new lines I have added.  Copied all the lines in start option, replaced ${SERVER_BIN} (which is trafficd-wdog) by "trafficd". And added "collect $COLLECT_OPTS" before it.

In the section below replace <profiler directory> by the directory where you want the profiler to collect data.

case $COMMAND in
    --start|-start) 
        ${SERVER_BIN} -d "${SERVER_CONFIG_DIR}" \ 
            -r "${OTD_PRODUCT_HOME}" -t "${SERVER_TEMP_DIR}" \
            -u "${SERVER_USER}" ${SVC_OPT} $@
        STATUS=$?
        if [ $STATUS -ne 0 ] ; then 
             exit $STATUS
        fi
        enable_failover
        ;;
    --collect|-collect)
        PATH=$PATH:/opt/SUNWspro/bin
        COLLECT_OPTS="-t 180-300 -F all -d <profiler directory>";
        collect $COLLECT_OPTS trafficd -d "${SERVER_CONFIG_DIR}" \
            -r "${OTD_PRODUCT_HOME}" -t "${SERVER_TEMP_DIR}" \ 
            -u "${SERVER_USER}" ${SVC_OPT} $@
        STATUS=$?
        if [ $STATUS -ne 0 ] ; then
            exit $STATUS
        fi
        ;;

for web server instead of trafficd it will be webservd. 

1.2.2 start the server using --collect option

Since we replaced trafficd-wdog by trafficd, the server will start up without any watchdog process and will run in console, not in background.  

bin/startserv --collect

1.2.3 run some stress tests

1.2.4 After 5-6 minutes stop the server

This will create a directory called (e.g.) 'test.1.er' which contains the experiment.

The default name for a new experiment is test.1.er.

The Collector automatically increments n by one in the names of subsequent experiments.

1.3 Open the profile and start the Oracle Sun Studio 12.2 analyzer

Set DISPLAY env.

$ cd <profiler directory>
$ export JAVA_PATH=/opt/SUNWwbsvr/jdk 
$ /opt/SUNWspro/bin/analyzer test.1.er/

1.4 The er_print utility prints an ASCII version of the various displays supported by the Performance Analyzer.

$ /opt/SUNWspro/bin/er_print -outfile er_print1.out -functions test.1.er 

In this, functions are sorted by "Exclusive User CPU Time"

or

$ /opt/SUNWspro/bin/er_print -outfile er_print2.out \
-metrics e.user:i.user:e.%user:i.%user:e.total:i.total:e.%total:i.%total:name \
-sort i.total -functions test.1.er 

In this, functions are sorted by "Inclusive Total LWP Time"

You can look at these files and figure out which function is taking how much time.

These files look like :

Functions sorted by metric: Exclusive User CPU Time 
Excl.     Incl.     Excl.       Incl.       Excl.     Incl.      Name  
User CPU  User CPU  Total LWP   Total LWP   Sys. CPU  Sys. CPU         
   sec.      sec.         sec.        sec.     sec.      sec.     
851.666   851.666   105477.573  105477.573  106.525   106.525    <Total>
493.435   493.435      558.110     558.110   26.368    26.368    fn1
 56.840   326.308       64.015     368.568    3.042    17.352    fn2
 28.280    28.280       34.574      34.574    1.701     1.701    fn3

...


2. Using DTrace script to see how much time is spent in which function

#!/usr/sbin/dtrace -s
#pragma D option bufsize=1g
#pragma D option specsize=1g
#pragma D option aggsize=1g
#pragma D option dynvarsize=1g

pid$target:::entry
{
 self->ts[probefunc] = timestamp;
}

pid$target:::return
/self->ts[probefunc]/
{
    @time[probefunc, probemod] = sum(timestamp - self->ts[probefunc]);
    self->ts[probefunc] = 0;
}

Note I have given 1g sizes you can tune it as per your machine.

Run this D script using :

#sudo dtrace -s functime.d -p 27910 -o dtrace.log 

where 27910 is the pid of the process you are examining (in this case webservd or trafficd).

This will generate the output as shown below 

  PListFindValue                       libns-httpd40.so                                        3871
  getbucketnum                         libc.so.1                                               4995
  R_SSL_version                        libnnz11.so                                             6106
  http_format_server                   libns-httpd40.so                                        6807
  void SimpleHashTemplateBase::_insert(unsigned long,hashEntry*)  libns-httpd40.so             7059
  long atoi64(const char*)             libns-httpd40.so                                        7288

...


I wrote this wrapper script to report percentages.

To get the last column I used logic of looking for spaces after the string "lib". For LM1`ld.so.1, I temporarily added a hack.

#!/usr/bin/perl
$logfile = "dtrace.log";
$tmpfile = "temp";
open(IN,"<",$logfile) || die "Can not open $logfile: $!";
$total = 0;
$total_rounded = 0;
while (<IN>) {
    chomp($_);
    s/(.*\s*)lib([^\s]*)\s*([0-9]*)/$1lib$2=$3/g;
    my ($a, $b) = split('=');
    $total += $b;
}
print "total = $total\n";
close(IN);
open(OUT,">", $tmpfile) || die "Can not open $tmpfile: $!";
open(IN,"<",$logfile) || die "Can not open $logfile: $!";
while (<IN>) {
    chomp($_);
    s/LM1`ld.so.1/libld.so.1/g;
    s/(.*\s*)lib([^\s]*)\s*([0-9]*)/$1lib$2=$3/g;
    my ($a, $b) = split('=');
    $rounded = sprintf("%.10f", ($b*100)/$total);
    $a =~ s/libld.so.1/LM1-ld.so.1/g;
    print OUT "$b   $rounded%   $a\n";
    $total_rounded += $rounded;
}
close(IN);
close(OUT);
print "total rounded = $total_rounded\n";
`sort -n -r $tmpfile | tee $logfile.sorted`;
`rm $tmpfile`


This produced output of the following format :

20318357230394   16.4117840797%     poll                                      libc.so.1
20317702791746   16.4112554688%     _pollsys                                  libc.so.1
20313615393944   16.4079539474%     __pollsys                                 libc.so.1
2684593654698   2.1684317735%     int DaemonSession::GetConnection()          libns-httpd40.so

...

3. Using DTrace Profile Probes

 #!/usr/sbin/dtrace -s
profile-1000
/pid == $1 && arg1 != NULL/
{
    @proc[umod(arg1), ufunc(arg1),ustack()] = count(); 
}
END
{
    printa(@proc); 
}


run it as :

dtrace -x ustackframes=20 -s profiler-probes.d <pid> -o dtrace.log

It creates output in the format library name, function name, user stack and the count number of times called, newline

  libc.so.1                                           libc.so.1`mutex_lock_impl        
              libc.so.1`mutex_lock_impl+0xaf
              libc.so.1`mutex_lock+0xb
              libumem.so.1`umem_cache_alloc+0x33
              libumem.so.1`umem_alloc+0xaf
              libumem.so.1`malloc+0x2e
              libnnz11.so`sys_malloc+0x23
             1068

....



4. References

Wednesday Nov 18, 2009

More on Intrusion Detection

I found that experimental Intrusion Detection module as explained in my previous blog doesn't work as expected if an external plugin's AuthTrans SAF is added in obj.conf request processing and if that SAF returns REQ_PROCEED. This may be a rarely happen in customer deployments. Will try to fix it in next update release/ next major release and will let you know when it is fixed.

My id.conf :

SecRuleEngine on 
SecRequestBodyAccess on
SecRule REQUEST_BODY "junk"

case 1: I created a dummy plugin having AuthTrans function myauth1; which just returns REQ_NOACTION it works fine. (look at <ws7-install-dir>/samples/nsapi/ for examples of how to create a plugin)

    #ifdef XP_WIN32
    #define NSAPI_PUBLIC __declspec(dllexport)
    #else /\* !XP_WIN32 \*/
    #define NSAPI_PUBLIC
    #endif /\* !XP_WIN32 \*/

    #include "nsapi.h"

    extern "C"
    NSAPI_PUBLIC int myauth1(pblock \*pb, Session \*sn, Request \*rq)
    {
        return REQ_NOACTION;
    }

Added in Magnus.conf

Init fn="load-modules" shlib="myauth.so" funcs="myauth1"

Error logs in that case show :

    ...
    ... func_exec reports: executing fn="match-browser" browser="\*MSIE\*" ssl-unclean-shutdown="true" Directive="AuthTrans" magnus-internal="1"
    ... func_exec reports: fn="match-browser" browser="\*MSIE\*" ssl-unclean-shutdown="true" Directive="AuthTrans" magnus-internal="1" returned -2 (REQ_NOACTION)

    ... func_exec reports: executing fn="myauth1" Directive="AuthTrans"
    ... func_exec reports: fn="myauth1" Directive="AuthTrans" returned -2 (REQ_NOACTION)

    ... func_exec reports: executing fn="magnus-internal/secrule-filters-insert"
    ... func_exec reports: fn="magnus-internal/secrule-filters-insert" returned -2 (REQ_NOACTION)

    ... func_exec reports: executing fn="ntrans-j2ee" name="j2ee" Directive="NameTrans"
    ...
       

case 2: When I change this AuthTrans SAF to return REQ_PROCEED, it doesn't work as expected:

    #ifdef XP_WIN32
    #define NSAPI_PUBLIC __declspec(dllexport)
    #else /\* !XP_WIN32 \*/
    #define NSAPI_PUBLIC
    #endif /\* !XP_WIN32 \*/
    #include "nsapi.h"

    extern "C"
    NSAPI_PUBLIC int myauth2(pblock \*pb, Session \*sn, Request \*rq)
    {
        return REQ_PROCEED;
    }

Added in Magnus.conf

Init fn="load-modules" shlib="myauth.so" funcs="myauth2"

Error logs in that case shows :

    ... func_exec reports: executing fn="match-browser" browser="\*MSIE\*" ssl-unclean-shutdown="true" Directive="AuthTrans" magnus-internal="1"
    ... func_exec reports: fn="match-browser" browser="\*MSIE\*" ssl-unclean-shutdown="true" Directive="AuthTrans" magnus-internal="1" returned -2 (REQ_NOACTION)

    ... func_exec reports: executing fn="myauth2" Directive="AuthTrans"
    ... func_exec reports: fn="myauth2" Directive="AuthTrans" returned 0 (REQ_PROCEED)

    ... func_exec reports: executing fn="ntrans-j2ee" name="j2ee" Directive="NameTrans
    ...
Note fn="magnus-internal/secrule-filters-insert" is not getting executed here.

You can add this secrule-filters-insert SAF above your ExternalPluginAuthTransSAF function:

<Object name="default">
AuthTrans fn="match-browser" browser="\*MSIE\*" ssl-unclean-shutdown="true"
AuthTrans fn="magnus-internal/secrule-filters-insert"
AuthTrans fn="ExternalPluginAuthTransSAF"
NameTrans fn="ntrans-j2ee" name="j2ee"
...
</Object>
This will work fine when ExternalPluginAuthTransSAF function returns REQ_PROCEED but when it returns REQ_NOATCION, these filters will be added twice.

You can make a dynamic library of myauth2 plugin as shown above and put it below "ExternalPluginAuthTransSAF"
<Object name="default">
AuthTrans fn="match-browser" browser="\*MSIE\*" ssl-unclean-shutdown="true"
AuthTrans fn="magnus-internal/secrule-filters-insert"
AuthTrans fn="ExternalPluginAuthTransSAF"
AuthTrans fn="myauth"
NameTrans fn="ntrans-j2ee" name="j2ee"
...
</Object>

Friday Jul 10, 2009

Installing Sun Java System Web Server 7.0 on CentOS 5.3 or Fedora 10-11 or Ubuntu

Installing Sun Java System Web Server 7.0 on CentOS 5.3 or Fedora 10/11 or Ubuntu

In my free time, I just tried out Sun Java System Web Server 7.0 update 5 on CentOS 5.3 and Fedora10 and 11 and Ubuntu. Joe Mccabe has also written a similar blog on this

Download Sun Java System Web Server 7.0 for Linux and extract the contents of tar.gz file

$gunzip  sjsws-7_0u5-linux-i586.tar.gz; tar -xvf sjsws-7_0u5-linux-i586.tar

Run installer, it will fail

$./setup

error while loading shared libraries: libstdc++.so.5: cannot open shared object file: No such file or directory

CentOS

To fix this problem  install "compat-libstdc++-33" package as shown below
$sudo yum -y install compat-libstdc++-33

Now run setup, it will work fine.

Fedora 10/11

Install "compat-libstdc++-33" package as shown below
$sudo yum -y install compat-libstdc++-33

There is one more problem in Fedora 11 but is I heard fixed in 7.0 update 6 (onwards).

If you get error message like

lib/libfreebl3.so: version `NSSRAWHASH_3.12.3' not found (required by /lib64/libcrypt.so.1)

You need workaround as given in https://forums.oracle.com/forums/thread.jspa?threadID=2212337

Ubuntu

You need to install libstdc++5 as shown below

$sudo apt-get install libstdc++5


If you get an error which has something that looks like /bin/domainname not found, you need to install

$sudo apt-get install nis

I have tested on Ubuntu 9.04.

*Note that Sun Java System Web Server 7.0 update 5 or 6 is not officially certified or supported on CentOS or Fedora or Ubuntu, but here's how you can make it work.

References

Outdated links :


Thursday Mar 05, 2009

Using DTrace in Sun Java System Web Server - part 2

Using DTrace in Sun Java System Web Server - part 2

In my previous blog I was just tracing the flow of request processing, in this blog I have tried to see how much time it takes when <If>/ <Client> tags etc. are evaluated.

Add in obj.conf the following lines to disable accelerator cache

 

AuthTrans fn="log" level="fine" message="Accelerator cache disabled"

Add one "If" condition in obj.conf

<If $uri =~ "/test.html">

Service method="(GET|HEAD|POST)" type="\*~magnus-internal/\*" fn="send-file"

</If>

Check webservd's pid

$ps -eaf | grep webservd | grep highest pid

Run this DTrace script, send a request to GET /test.html HTTP/1.0 via telnet from another window.

Here is the output :

$./ws.d highest-pid
thread 24: Added connection 0x29b3228 to connectionQ
thread 29: Removed connection 0x29b3228 from connectionQ. Time spent in Q 81250 nanoseconds
thread 29: Processing for absolute path /test.html client ip xxx.xxx.xxx.xxx
thread 29: processing objects for uri /test.html
thread 29: object-check called

thread 29: object-check finished. Time spent 8584 nanoseconds
thread 29: Calling saf match-browser
thread 29: saf match-browser returned -2. Time spent is 66916 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2917 nanoseconds
thread 29: Calling saf ntrans-j2ee
thread 29: saf ntrans-j2ee returned -2. Time spent is 26084 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2417 nanoseconds
thread 29: Calling saf pfx2dir
thread 29: saf pfx2dir returned -2. Time spent is 21500 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 3500 nanoseconds
thread 29: Calling saf uri-clean
thread 29: saf uri-clean returned 0. Time spent is 21750 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2500 nanoseconds
thread 29: Calling saf find-pathinfo
thread 29: saf find-pathinfo returned -2. Time spent is 10750 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2250 nanoseconds
thread 29: Calling saf find-index-j2ee
thread 29: saf find-index-j2ee returned -2. Time spent is 8917 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2250 nanoseconds
thread 29: Calling saf find-index
thread 29: saf find-index returned -2. Time spent is 9000 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2750 nanoseconds
thread 29: Calling saf type-j2ee
thread 29: saf type-j2ee returned 0. Time spent is 11584 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2334 nanoseconds
thread 29: Calling saf type-by-extension
thread 29: saf type-by-extension returned 0. Time spent is 38750 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 2833 nanoseconds
thread 29: Calling saf force-type
thread 29: saf force-type returned 0. Time spent is 10833 nanoseconds
thread 29: cond-eval called
thread 29: expr-eval called
thread 29: expr-compiled-re-eval subject /test.html match 1 pattern /test.html, return value 1
thread 29: expr-eval finished. Time spent 65584 nanoseconds
thread 29: cond-eval finished. Time spent 111500 nanoseconds
thread 29: Calling saf send-file
thread 29: saf send-file returned 0. Time spent is 102583 nanoseconds
thread 29: object-check called
thread 29: object-check finished. Time spent 3166 nanoseconds
thread 29: Calling saf flex-log
thread 29: saf flex-log returned 0. Time spent is 47833 nanoseconds

This shows how much time was spent in each SAF, when connection was put in connection queue and when it was removed and which regular expression in obj.conf was evaluated, how much time was spent, what was the result.

Attached are the cvs diffs and ws.d script

 Summary

These DTrace probes will help us to dynamically find out

  1. Which request processing stages were called for a request,  how much time each request processing stage took for a particular request.
  2. When was a connection put into connection queue (Requests in Web server are accepted by acceptor threads and put in connection queue and picked up by Worker threads) so if the requests sit for a long time in connection queue, then worker threads settings in server.xml configuration file should be increased accordingly.
  3. Which regular expression in obj.conf was evaluated, how much time was spent, what was the result.


About

Meena Vyas

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today