Getting insights with DTrace - Part 3

Analyzing SAP Appserver I/O

Introduction / Motivation

SAP provides a rich set of monitoring tools allowing for detailed systems analysis. However, there are situations that go beyond the capabilities of SAP CCMS.

Background

Oracle Disk I/O is pretty easy to trace with SAP transactions ST04N and ST05. However, not only the DB might create I/O. In a real customer situation, high disk I/O really screwing up overall system performance has been observed outside business hours on a specific application server. SAP doesn't provide a lot of help here. In the past, such problems had to be diagnosed online during occurrence (sunday morning 03:00). Solaris 10 and DTrace are a great help, because it is possible to constantly monitor a system and raise an action after thresholds are exceeded. Such actions can even be external comands.

Solution

The DTrace io provider allows fairly easy monitoring of disk I/O. The profile provider adds the option of timer driven probes.
The idea is to track the number of I/O's in a given interval specifically for each process. Once this process hits a threshold, its pid is logged and more information about this process is gathered. To gather this information, the pid is passed to a shell script by issueing a DTrace 'system'-command. The shell script decides, wether the pid belongs to SAP, and then collects SAP internal information about the corresponding SAP workprocess by calling the SAP dpmon utility. This utility provides information about the dispatcher status (queues) as well as the current workprocess activity, in particular it will show the SAP user and ABAP program name actually causing the I/O bottleneck.

Recently Updated

Upgrade- und Patchmanagement in einer virtuellen Betriebsumgebung
updated by d.augustin

(view change)

Nov 13
10 Good Reasons to run SAP on Solaris
updated by malcolmx67

(view change)

Nov 10
10 Good Reasons to run SAP on Solaris
updated by vwetter

(view change)

Aug 26
How to identify the global zone from within a local zone
updated by aperkons

(view change)

Jul 16
More

#!/usr/sbin/dtrace -s
#pragma D option quiet
#pragma D option destructive

/* Usage:
          sap_io_moni.d <intervall in sec> <i/o threshold>

	  example: sap_io_moni.d 2 200

                   measure every 2 seconds
                   fire off when more than 200 io's are triggered
                   by a single process within 2 seconds
*/

self int iops;
self int prev_secs;
self int64 prev_tstamp;
int secs;

io:::start
/self->iops < $2 && pid != 0 && execname != "fsflush"/
{
 	self->lazy_int = (walltimestamp - self->prev_tstamp) > ($1 * 1000000000);
	self->iops = (self->prev_secs > secs || self->lazy_int) ? 1 : self->iops + 1;
	self->prev_secs=secs;
	self->prev_tstamp=walltimestamp;
}

io:::start
/self->iops >= $2 && pid != 0 && execname != "fsflush"/
{
  	system("/opt/dtrace/getprocinfo.sh %d", pid);
  	printf("I/O limit exceeded by process pid: %d	 name: %s !\n", pid, execname);
	printf("last file being accessed:	   %s \n", args[2]->fi_pathname);
  	exit(0);
}

profile:::tick-1sec
{
  	secs = (secs >= $1) ? 0 : secs + 1;
}

This DTrace script basically consists of 3 blocks:

The start-probe of the io provider as long as the threshold has not been reached:
- reset thread-local io-counter if new interval has started
- otherwise increase thread-local io-counter
- store currently elapsed seconds and timestamp to be able to recognize start of new interval on subsequent probe.
The start-probe of the io provider when io threshold has been reached:
- execute external shell script
- print out information about the process generating the io load
The profile provider increasing the counter for elapsed seconds, restarting with 0 if interval elapsed.

The only 'trick' is to realize within the io:::start probe, that the new interval has begun. This is achieved by comparing the previous timer with the current one. If the previous one is greater - let's say 5 sec - than the current one - let's say 0 sec -, then the timer obviously has been reset. Another situation might be, that no I/O occurred during a whole interval (or even longer). Therefore the script tracks timestamps to detect such situations.
As soon as a process is identified to be causing high I/O, sap_io_moni.d calls an external shell script called getprocinfo.sh passing the pid of the process.

#!/bin/bash
#
# determine process infos:
# usage:         getprocinfo <pid>
#
# - if parameter is pid of a SAP disp+work, then start dpmon in the corresponding zone
# - if not, just print ps-output

PS_OUT=`ps -fZ -p $1 | tail -1`
IS_IT_DW=`echo $PS_OUT | grep 'dw.sap' | wc -l`

if [ $IS_IT_DW -ge 1 ]; then
  ZONE=`echo $PS_OUT | awk '{ print $1 }'`
  SIDADM=`echo $PS_OUT | awk '{ print $2 }'`
  PFILE=`echo $PS_OUT | awk '{ print $10 }'`
  if [ $ZONE <> 'global' ]; then
    zlogin -l $SIDADM $ZONE "echo q | dpmon l $PFILE"
  else
    su - $SIDADM -c "echo q | dpmon l $PFILE"
  fi
fi
echo " "
echo "Output from ps -fZ: " 
echo $PS_OUT

getprocinfo.sh retrieves further information via call of 'ps', especially the zonename, the username (sidadm) and the profilename of the SAP instance belonging to the process. If SAP runs within a local zone, the script will do a zlogin to the zone and execute dpmon as SAP Admin user. Other wise it will do a 'su' to this user. The long version of the dpmon process list as well as the 'ps' output will then be listed before returning to the DTrace script.

Note:

The script above assumes, that the SAP <sid>adm user is known within the global zone (e.g. by using LDAP or NIS).

root@r3psap:/opt/dtrace # ./sap_io_moni.d 2 100

Workprocess Table (long)			Sun May 24 19:02:19 2009
========================

No Ty. Pid      Status  Cause Start Err Sem CPU    Time  Program          Cl  User         Action                    Table
-------------------------------------------------------------------------------------------------------------------------------
 0 DIA     8528 Run           yes     0   0        15   ZBBC_EXTSORT     000 VWETTER                                          
 1 DIA     8827 Wait          yes     0   0        0                                                                          
 2 DIA     8024 Wait          yes     0   0        0                                                                          
 3 DIA     8025 Wait          yes     0   0        0                                                                          
 4 DIA     8026 Wait          yes     0   0        0                                                                          
 5 DIA     8029 Wait          yes     0   0        0                                                                          
 6 DIA     8030 Wait          yes     0   0        0                                                                          
 7 UPD     8033 Wait          yes     0   0        0                                                                          
 8 UPD     8038 Wait          yes     0   0        0                                                                          
 9 ENQ     8041 Wait          yes     0   0        0                                                                          
10 BTC     8185 Wait          yes     0   0        0                                                                          
11 BTC     8049 Wait          yes     0   0        0                                                                          
12 BTC     8050 Wait          yes     0   0        0                                                                          
13 SPO     8052 Wait          yes     0   0        0                                                                          
14 UP2     8054 Wait          yes     0   0        0                                                                          


    s - stop workprocess
    k - kill workprocess (with core)
    r - enable restart flag (only possible in wp-status "ended")
    q - quit
    m - menue

-->  
Output from ps -fZ: 
solman demadm 8528 8016 8 20:09:55 ? 2:59 dw.sapDEM_DVEBMGS14 pf=/usr/sap/DEM/SYS/profile/DEM_DVEBMGS14_solman
I/O limit exceeded by process 	pid: 8528    name: disp+work !
last file being accessed:	/usr/sap/DEM/DVEBMGS14/work/myfile 

root@r3psap:/opt/dtrace #

As a result, we can see details about the process causing the high I/O load from an OS perspective as well as from an SAP perspective. In particular we can see:

the OS username (demadm)
the name of the zone the process is belonging to (solman)
the name of the executable (disp+work)
the corresponding SAP Instance (central instance of DEM: DVEBMGS14)
the name of the last file that has been accessed before the I/O limits have been exceeded (/usr/sap/DEM/DVEBMGS14/work/myfile)
the name of the SAP user running the SAP transaction / job causing the io (VWETTER)
and the name of the ABAP program being the source of high I/O

Looking at the ABAP source code, it is easy to figure out, that extensive external sort operations are the cause for high I/O. In this particular example the OS level sort operation could be eliminated by using an already sorted internal table type within SAP.