Blog

Know Your Numbers. A Quick Analysis with AWR and Characteristic Numbers. Part II.

troype, 10/27/2014

In Part II we put our knowledge of characteristic time ranges to a service to find a bottleneck in one particular SQL statement that was a part of one particular initial ETL run.

The session was moving data from a set of source tables into a target table using INSERT /*+ APPEND */ INTO ... SELECT ... FROM ... SQL statement. The amount of rows to move was in excess of 400 million and projected run time (monitoring with help of V$SESSION_LONGOPS view) was fluctuating around 70 hours.

An 8-hour AWR report was taken in the middle of the run and this report was our primary source of information about the database instance and that active SQL statement.

A quick check of Top 5 Timed Foreground Events table shows that the instance was primarily CPU-bound and all other events were insignificant.

Event

Waits

Time(s)

Avg wait (ms)

% DB time

Wait Class

DB CPU

 

21,027

 

98.18

 

control file sequential read

10,635

10

1

0.05

System I/O

The instance runs on a box equipped with 24 CPU cores so the full CPU capacity is 24 CPU seconds per physical second and according to Load Profile table the amount of DB CPU time was 0.7 CPU second per a physical second. An average CPU utilization was therefore 2.9%. This closely matches Instance CPU view of the AWR Report.

%Total CPU

%Busy CPU

%DB time waiting for CPU (Resource Manager)

3.1

97.1

0.0

It also appears that the DB instance was practically the only client of the operating system (% Busy CPU = 97.1).

These numbers above prove that the database instance was not really loaded much when that session was running.

Another look at Load Profile table brings the following interesting number into consideration.

Per Second

Per Transaction

Per Exec

Per Call

Logical reads:

619.9

3,320.1

 

 

So the instance was processing only about 620 logical reads per second. It is about 1,612 microseconds per operation. That's where our knowledge of LIO characteristic range comes in handy. There is no way that logical read can take that long! We have reviewed the statement and we found it not overly complicated in terms of join and filter predicates. There were no overly complicated expressions in SELECT list either. But even if they were there it could hardly have consumed more than 100 microseconds per logical read. In other words if CPU/memory sub-system were a bottleneck the estimated number of logical reads per second would have been around 1 / 0.0001 = 10,000 ops / second. Apparently something in the session's pipeline was throttling data flow down to a much lower speed.

Let's have a look at the session's numbers. We are interested in SQL Ordered by CPU Time and SQL Ordered by Gets tables.

CPU Time (s)

Execs

CPU per Exec (s)

%Total

Elapsed Time (s)

%CPU

%IO

SQL Module

SQL Text

20,892.26

1

20,892.26

99.36

21,279.26

98.18

0.00

insert /*+ append */ into ...

Buffer Gets

Execs

Gets per Exec

%Total

Elapsed Time (s)

%CPU

%IO

SQL Module

SQL Text

15,284,417

3

5,094,805.67

85.71

50.75

95.2

3.5

JDBC Thin Client

select ...

1,658,005

1

1,658,005.00

9.30

21,279.26

98.2

0

insert /*+ append */ into...

First thing to notice is that CPU time for our session (20.892.26 seconds) accounts for 99.3% of total DB CPU time (21,027 seconds). For any practical purpose that session was the only significant client of the instance! By dividing 20,892.26 seconds by 1,658,005 buffer gets we obtain 12,600 microseconds per buffer. This is way too long! A SELECT query in the first row of the same table performs 15.2M buffer gets in less than 50 seconds of CPU time. A computed time per buffer in this case is equal to 3.27 microseconds - that is on the verge of our empirical characteristic range of 5 - 100 microseconds and that is also a proof that our CPU/memory subsystem is capable of reaching that speed.

Let's summarize what we have achieved so far.

In Part III we will take a closer look at IO subsystem and how it affects our problematic SQL statement.