Investigating slow AR System API calls

If you see a performance issue in a particular operation, start by investigating slow API calls. If you see a performance issue by all operations, look for causes of overall system performance degradation.

Before you begin

Before investigating slow API call, ensure that you have performed the following tasks:

• Collect logs for a performance issue.
• Run AR System Log Analyzer to generate results in web (HTML) format.
• View AR System Log Analyzer output to assess the statistics captured.

To investigate a slow API call

1. Under API Aggregates, click Top N to view the longest running individual API calls.

2. Click the line number for the long-running API call.
    The display pane displays the log starting at that line number.
   Log entries for API calls have a dark shaded background, and log entries for SQL statements have a light background, so viewing API calls and the corresponding SQL statements contained within them is easy.

   Tip

   Look at slow  API calls first. Slow bulk API calls and  API calls often appear in the Top N due to slow  API calls or SQL statements. Click Legend under API Aggregates to see the API abbreviation legend.

3. View the Timestamp column and scroll down to look for a gap of several seconds to see where the bulk of the time occurred while the API call was processed.
4. Stop scrolling down when you reach the end of the API call (signified by the OK line).
    The time difference should be the Execution Time reported in Top N. The general guideline is if the bulk of the time gaps occurred in SQL statements, investigate it as a slow SQL statement.

To investigate a slow SQL statement

1. Identify a long-running SQL statement using the previous procedure.
    Note the SQL statement.
2. Under SQL Aggregates, click Top N.
3. Search the list of longest-running individual SQL statements for ones similar to the SQL statement identified earlier.
    The general guideline is if the statement is listed in 10 percent of the Top N longest-running SQL statements, the statement might have an issue running efficiently at the database.
4. For long-running SQL statements, click the line number of a long-running SQL statement.
    The log is displayed at the specified line number.
5. Verify that the SQL statement is immediately followed by an OK entry.
    SQL exceptions, or cases where there is no OK line indicate a false reading on the time to execute the SQL statement.

6. Check if the complete SQL statement is listed or if it ends with an ellipsis (...), indicating that the statement was truncated in the log.
   If the SQL statement was truncated, the database administrator might not have enough information to investigate the issue.

   Tip

   If the SQL statement was truncated, add the following line to the AR System Administration:AR System Configuration Generic UI form, restart the server, and generate a new set of logs:
   Enable-Unlimited-Log-Line-Length: T

7. For long-running SQL statements, send the SQL statement to the database administrator to test whether the query uses appropriate indexes.

   Note

   SQL statements generally run much faster in database query tools because they use dedicated database resources, and the query is run in isolation. The objective of running the query directly at the database is not to compare performance, but to use DBMS features such as show plan/explain plan to test whether the SQL statement uses indexes already defined on the table.

To investigate slow API calls or SQL statements due to contention or blocking events

1. Under API Aggregates, click Top N to view the execution times of the Top N longest running individual API calls.
2. Identify similar API calls that begin at the same time.
    The general guideline is to look for API calls where Start Time occurs within the same one-minute period.
3. Click the line number to view the log entry at that line.
4. Note the value of RPC ID in the third column.
5. Scroll through the list of log entries with the same value of RPC ID, watching the Timestamp column for a gap in the time to identify which API call or SQL statement takes the most time within the long-running individual API call.
    This API call or SQL statement is a potential cause of the contention.
6. Under API Aggregates, click Top N to return to the list of longest-running individual API call, and repeat the procedure for a similar API call that begins at the same time.
7. If the potential cause of contention is an SQL statement, perform the following actions:
   1. Verify optional configuration in the AR System Administration:AR System Configuration Generic UI form for the following settings:
      • Next-ID-Block-Size
      • Select-Query-Hint
   2. Send the SQL statement and Timestamp to the database administrator to check if there were any SQL deadlocks or issues at the database at the Timestamp.
8. If the potential cause of contention is an API call, perform the following actions:
   1. Use the grep command to identify all lines in the Filter log with the value of the RPC ID identified in the API call, and examine the filter log.
   2. Check for system problems reported in the armonitor.log file or on the system hosting .

Example

An administrator investigating a performance issue synchronizing from BMC Atrium Discovery and Dependency Mapping to BMC Atrium CMDB views the top 20 longest running API operations and observes:

(Click the image to expand it.)

There are six instances of the GWIN API call and six instances of the GLEWF BMC.CORE:BMC_Impact_D call, all within the same second.
 This might indicate one API call is embedded within a bulk API call, so the administrator clicks Legend to view the full name of the API calls:

(Click the image to expand it.)

The legend shows:

and

A slow GLEWF API call might be contained in the GWIN API call, and makes it appear slow.

Under API Aggregates, the administrator clicks Top N, and then clicks the line number to view the longest-running API call.

(Click the image to expand it.)

The administrator scrolls up a few lines to review the lines with the same value of RPC ID and observes that the GWIN API call includes the GLEWF API call, and a SQL statement within the API call takes more than 18 seconds to execute.

The administrator reviews the other six long API operations and confirms similar behavior.

The administrator sends the SQL statements and timestamp of when they ran to the database administrator to investigate if the query uses appropriate indexes, and if deadlocks were encountered at the database at the time of the timestamp values.

Where to go from here

Assessing-relevance-of-performance-issues
Analyzing-thread-statistics