Apps Archives » Page 56 of 58 » Musings of an IT Implementor

Basic Performance Tuning Guide – SAP NetWeaver 7.0 – Part II – Reading Single Record Statistics

This is Part II. You may like to see Part I.

In Part I, we showed you how to trace an ABAP program using STAD to show the single record statistics of the response times for a transaction/program.
In this part, we will go through and decipher the statistics to help you decide where the problem may lie in your slow performing program.

Following Part I, we saw the STAD screen output. Below is a snapshot of the right hand side of the screen showing the “standard” view fields:

The “Response time (ms)” field shows the total response time for the dialog step (or summary of steps if you have chosen not to expand the left tree).

As a reminder, SAP says (https://help.sap.com/saphelp_nw70ehp1/helpdata/en/21/2c8f38c7215428e10000009b38f8cf/content.htm
):
“Response time = wait time + execution time
where: execution time =
Generation time during the run
+ Load time for programs, screens, and graphical user interfaces
+ Roll times for rolling in the work data
+ ABAP processing time
+ Database time
+ Enqueue time for logical SAP lock processes
+ CPIC/RFC time
+ Roll wait time (excluding task types RFC/CPIC/ALE).“

So if we take a look at our initial screen of values, the example below shows that the “DB req time (ms)” is one of the larger values (4929):

The total database request time (time taken for database work to be done for this step) is more than 92% of the total response time for the step.
If the database time IS NOT a significant percentage of total response time, then you should check the other parts that make up the total response time, for clues.

At this point, it’s better to change the screen columns so that you can see all the timings.
The best view is the “Time Analysis” view. Switch views by clicking the “Sel. fields” button:

Click “Time Analysis“:

You will now see more timing fields

The fields highlighted are responsible for the total response time calculation.

In our example, TOTAL RESPONSE TIME = Wait Time + DB Req Time + Processing Time + Load Time + Generating Time + Roll In Time + Roll Wait Time + Enqueue Time.
=> 5330 = 0 + 4929 + 122 + 17 + 0 + 262 + 0
(5330 / 1000 = 5.3 seconds total response time)

You should check each of the fields, looking for disproportionate response times.

The “Wait time (ms)” indicates the amount of time the dialog step was waiting to be processed by a dialog work process. High values indicate that the overall system performance is degraded. Maybe a lack of memory, CPU or I/O performance at the O/S layer could be causing issues. Check the dispatcher queue.

The “Time in WPs (ms)” indicates the time that the dialog step was being actively serviced by a work process and not by any other type of process (BTC, UPD, UPD2 etc). Check “SM51 -> Goto -> Server Name -> Information -> Queue Information” and SM66 to see how busy the system is.

The “Processing time (ms)” indicates the amount of time the individual components spent processing (working) and not idle or sleeping or waiting. Check SM50 and SM66 to see how busy the system is.
Use ST06 (O/S monitor) to check CPU usage and system load.

The “Load time (ms)” indicates the amount of time taken to load the program code into memory buffers.
A problem here could indicate the program buffer is not large enough (see ST02). You should check the CPU time if the load time value is large.

Values for “Generating time (ms)” show the time spent compiling the ABAP source code. You will see a value here if the code has not already been compiled through SGEN. Any large values here for programs already generated could mean a problem in the database with the code storage tables.

Large values for “Roll (i+w) time (ms)” indicates that the Roll-In and Roll-Wait times are being affected.

Roll-In is the process of moving the users session context into the work process so that it can be used to execute the dialog step. High values could indicate that the roll buffer is too small (see ST02) or that the user has a very large set of roles and profiles and is consuming too much memory.

Values for “Enqueue time (ms)” show the time waited for a logical database lock to be performed.
A high value here could indicate excessive contention (someone else doing the same work) in the SAP system or the underlying database. Maybe check SM13.

If we look at a CPU time example, a high value here would indicate a large amount of overall processing causing the WP to use more CPU.
Maybe a rogue loop, or a large internal table operation.
The example below shows a high CPU time for a background job performing a lot of RFC calls.
Notice how the processing time (just off the screen shot, sorry) has increased too (some component has to do the work):

Could be that a lot of data/work was transfered by RFC call.

Summary:
If you see high database time in your analysis, Part III will show you how to perform an SQL trace to see what the database is doing for so long.

If you have high CPU/processing time, then in Part IV you will be shown how to find where exactly in the ABAP program is causing the most response time.

Oracle Home Space Cleanup (how random that sounds)

Just a quick post to make you aware of a fantastic option I recently discovered in opatch.
I look after a large number of database systems, some having multiple Oracle homes on the same drive (I know I know, but when you’re limited on drives…).
These homes consist of things like Oracle RDBMS (obvious one), Oracle 10g EM Agent and finally Oracle 10gAS (and 10g OEM if you like to think that OMS is separate, but it’s a 10gAS so I didn’t).

Generally the Oracle home for a 10gR2 RDBMS Enterprise Edition binary codeset seems to be around 1GB in size.
Apply a couple of opatches and you could be looking at 2GB!
All of a sudden, the partition is looking quite full (it used to be 9i on there when it was originally designed!!).

Lets bring in a new opatch command that came in as part of an opatch upgrade in 10gR2 (opatch patch 6880880).
The command is part of the “opatch util” command and is a sub-command called “cleanup”.
It supposedly removes the duplicated binary files taken during an opatch patch application.

Oracle doc 550522.1 states “Starting with 10.2, Opatch does not backup only the affected modules, it also takes a backup of the complete affected libraries to $ORACLE_HOME/.patch_storage//backup//.“.

The cleanup command only removes files that are not required as part of a patch rollback.

Syntax: “$ opatch util cleanup“.

You will be prompted to select the oracle home and confirm the cleanup. It will also inform you of the amount of space saving.
Enjoy the space you get back, while you can!

Checking Lack of Bind Variables & Adhoc SQL in Oracle

The following Oracle SQL is a crude method that can be used to check the V$SQLAREA view for SQL statements that have the same execution plan, but where the SQL is unique. e.g. SQL statements where only the predicate changes in the WHERE clause. These are otherwise known as adhoc queries (something that SQL Server 2008 is supposed to be very good at detecting).

The statement was constructed based on the “Understanding Shared Pool Memory” document by Oracle (https://www.oracle.com/technetwork/database/focus-areas/manageability/ps-s003-274003-106-1-fin-v2-128827.pdf).

The doc basically says that a count of the PLAN_HASH_VALUE column versus the number of SQL_IDs using the plan indicates how bad the SQL needs bind variables since it should have only one or two SQL statements (the lower the better) per plan.

In my opinion, systems that return >60% for ACTION “Could use bind variables.” should either consider revising the application SQL code (permanent fix), or using the CURSOR_SHARING=FORCE init parameter (temporary fix!).
SELECT 'Multiple SQLs in SQLAREA using same plan:' DESCRIPTION,sum(pct_hash_use) PCT,'Could use bind variables.' ACTION FROM ( select hc.plan_hash_value, hc.hash_use_count, sc.sql_count, round((hc.hash_use_count/sc.sql_count*100),2) pct_hash_use from (select s.plan_hash_value, count(s.plan_hash_value) hash_use_count from v$sqlarea s group by s.plan_hash_value having plan_hash_value > 0 ) hc, (select count(1) sql_count from v$sqlarea t where plan_hash_value > 0 ) sc order by pct_hash_use desc ) WHERE hash_use_count > 1 UNION SELECT 'Single SQLs in SQLAREA using same plan:' Description,sum(pct_hash_use) PCT,'No action needed.' ACTION FROM ( select hc.plan_hash_value, hc.hash_use_count, sc.sql_count, round((hc.hash_use_count/sc.sql_count*100),2) pct_hash_use from (select s.plan_hash_value, count(s.plan_hash_value) hash_use_count from v$sqlarea s group by s.plan_hash_value having plan_hash_value > 0 ) hc, (select count(1) sql_count from v$sqlarea t where plan_hash_value > 0 ) sc order by pct_hash_use desc ) WHERE hash_use_count <= 1;
You can also use the following query to determine roughly how much memory is wasted on single SQL statements that have been executed only once (you should use this on a well bedded in system that has been running for a while):
select count(1) num_sql, sum(decode(executions, 1, 1, 0)) num_1_use_sql, sum(sharable_mem)/1024/1024 mb_sql_mem, sum(decode(executions, 1, sharable_mem, 0))/1024/1024 mb_1_use_sql_mem from v$sqlarea where sharable_mem >0;
You should double check the output with the SQL text in V$SQLAREA to ensure that the SQL is truly ad-hoc.

Remember to get some hard and fast values for the “Concurrency” wait class before and after the change (bind variables introduced or init parameter changed).

You can use SQL: “select * from v$system_event where wait_class#=4 order by average_wait desc;” to determine the average wait time.

I would expect the library cache operation wait times to reduce as hard parses are reduced.

Here is an example of a system that is not using bind variables to optimise SQL:

When running the script we get:

You should note that an OLTP system such as SAP ERP should have a much lower count for adhoc SQL compared to a SAP BW system where users can write their own queries.

Oracle Explain Plans: Cardinality & Histograms

This is one of the better white papers on how to read an Oracle explain plan:
https://www.oracle.com/technetwork/database/focus-areas/bi-datawarehousing/twp-explain-the-explain-plan-052011-393674.pdf
The most important point is made on cardinality on page 10 when explaining “Data Skew”.
The term “Data Skew” is used to refer to the imbalance of values with respect to a normal distribution (https://en.wikipedia.org/wiki/Skewness).
The imbalance is shown as the Mode (https://en.wikipedia.org/wiki/Mode_(statistics)) of the values in a column of a table.

Example:SELECT * FROM A_TABLE;

COL1 | COL2 -----|----- 1 | A <== Mode = most frequent. 2 | A 3 | A <== Median = middle one 4 | B 5 | B

Histogram for COL2:

Value |Number ------|------ A |### B |##

Data Skew means that more of (usually it takes a lot more, like +60%) the values in COL2 have a value of “A” than of “B”.
As the Oracle whitepaper points out “One of the simplest formulas is used when there is a single equality predicate in a single table query (with no histogram). In this case the Optimizer assumes a uniform distribution and calculates the cardinality for the query by dividing the total number of rows in the table by the number of distinct values in the column used in the where clause predicate.“.

In example “SELECT * FROM A_TABLE WHERE COL2='A'” this would equate to: Cardinality = 5 / 2 A cardinality value of 2.5 would be rounded to 3.
Accurate enough.

The problem with this is that the larger the number of rows the more skewed the cardinality will become.
Imagine the table with values like so:

Value |Number ------|--------------- A |############### B |##

Now in example “SELECT * FROM A_TABLE WHERE COL2='A'” this would equate to: Cardinality = 17 / 2
A cardinality value of 8.5 would be rounded to 9.
Definitely not 15.

To solve this problem, Oracle has the capability to collect statistics for individual columns.
You can use the DBMS_STATS.GATHER_TABLE_STATS command to collect stats on the column (https://www.dba-oracle.com/t_histograms.htm).

The below statement will collect stats on the COL2 column of A_TABLE in the OE schema with a bucket size of 20 buckets. These column stats are histograms of the distribution of values.

BEGIN DBMS_STATS.GATHER_table_STATS (OWNNAME => 'OE', TABNAME => 'A_TABLE', METHOD_OPT => 'FOR COLUMNS SIZE 20 COL2');
END;
/

Two types of HISTOGRAM are available in Oracle, FREQUENCY and HEIGHT.
Oracle uses HEIGHT based histograms *only* when the number of distinct values of a column is greater than the number of buckets specified.
“In a height-balanced histogram, the column values are divided into bands so that each band contains approximately the same number of rows. The useful information that the histogram provides is where in the range of values the endpoints fall.“.

Oracle will use FREQUENCY based histograms by default when the number of distinct values of a column is less than or equal to the number of buckets specified.
“In a frequency histogram, each value of the column corresponds to a single bucket of the histogram.“.

https://download.oracle.com/docs/cd/B19306_01/server.102/b14211/stats.htm

It is possible to view the collected histogram for a column:

SELECT column_name, num_distinct, num_buckets, histogram FROM USER_TAB_COL_STATISTICS WHERE table_name = 'A_TABLE' AND column_name = 'COL2';

SAP RFC Gateway Error 10060

Yesterday I spent the majority of the morning tracking a problem in the SAP ERP system.

It has been occurring for a while but I have had far more important issues. Finally I got round to looking at it.

In hosta SM21 system log, the gateway process (RD) had registered a network connect error (Q0I) “Operating system call connect failed (error no. 10060)”:

The architecture of the SAP systems involved in the landscape looks like the following diagram, which shows an SAP ERP single ABAP stack (hosta), which is connected to an SAP Enterprise Portal system which is clustered (hostb & hostc):

Looking in the gateway error log (TX: SMGW), I saw the network interface (Ni) timeout error when looking up the hostname for IP address 192.168.1.1:

The business process involved means that an RFC connection is established from the EP server processes (hostb) to the ERP gateway process (hosta).
As you can see in the architecture diagram, the IP 192.168.1.1 is the private IP address of the hostb server in the EP cluster.
The private IP address is only used as a heartbeat address as part of the Microsoft Cluster service.
So the question was, why was the SAP ERP gateway process receiving inbound connections from hostb via the private IP address?

The method of analysis involves understanding how the IP to hostname lookups are performed on the Windows servers:

First, if you open a command prompt and use NSLOOKUP to check the hostname (“C:> nslookup hostb”) it will return the hostname from the Name Service configured for the Windows Server. Usually this is in the order of hosts file first, then DNS. It performs the lookup using the appropriate network interface according to the network routings (“C:> route print”).
In our example, the nslookup correctly returned the public IP address.

Second, you can issue a PING of hostb from hostb (itself) using “C:> ping hostb”.
When using PING, it sends a network packet using the appropriate network interface according to the network routings (“C:> route print”). Since we are pinging ourselves, it will use the first network interface in bind order of the Windows network connections.
In our case, it was pinging the *private* IP address.
According to Microsoft, the PING command in Windows uses gethostbyname() to find the IP address for the destination to be ping’d(https://support.microsoft.com/kb/822713).

So we have established that the private IP address is seen when we ping our own servername on hostb, why does this mean that the private IP is seen as the client in a SAP RFC gateway connection?
Well, in the same way that PING uses gethostbyname(), the RFC connection that is established through jlaunch.exe (host of the JAVA stack server processes) also uses gethostbyname(). Of course, we know what IP address a gethostbyname() call returns, as this is used in the PING command .

(findstr /M gethostbyname jlaunch.exe)

So, the RFC connection performed by the JAVA stack is created from the jlanuch.exe binary, which uses gethostbyname() during the bind() call, which returns the private IP.
The RFC connection is established and part of the RFC connection process the jlanuch.exe process passes it’s calling IP address. Which is the private IP address.
The ERP system gateway at the other end of the connection receives the incoming connection and notes that it is coming from 192.168.1.1. Should the ERP system on hosta wish to make an RFC callback (https://help.sap.com/saphelp_nw04/helpdata/en/22/042a77488911d189490000e829fbbd/content.htm)
(https://help.sap.com/saphelp_nw04/helpdata/en/22/042a91488911d189490000e829fbbd/content.htm), it has no chance of returning the call to the private IP address on hostb. This is where we get the error “NiHsLGetHostByName failed”.

So how do we resolve the problem?
We could code the lookup into the hosts file (172.x.x.2 hostb) on hostb, but this might cause other issues.
A quick look into the SAP documentation for installing Netweaver 7.0 SR3 in a Microsoft Clustered system reveals that a simple step was missed during installation on hostb.
In the document it states “The card of the public network must be displayed before that of the private network. If necessary, change the order in which the cards are listed by using the Move Up and Move Down arrows”.

So I check the binding orders on hostb in Control Panel -> Network Connections -> Advanced Settings:

They are the wrong way around. The “Cluster Heartbeat” (Private IP) should be beneath the Public IP (“Local Area Connection” in our example).
The Microsoft article here (https://support.microsoft.com/kb/894564) lists the process to change it and provides alternative solutions (I would recommend to follow the SAP document).

Changing the binding order on Windows Server 2003 does not require a reboot, but the change will not be effective until a reboot is performed.