Is it the CPU from parsing?

In my last post I did some fuzzy math, I assumed the sql-s with literals were active whole day. The ASH report was generated for business hours, I had to adjust for the full day to match AWR reports. To verify the math  we will now count the number of distinct sql-s for the two FORCE_MATCHING_SIGNATURE-s in the “Top SQL using literals” section.

DAY          COUNT(*)
 ---------- ----------
 2016-04-18       4258
 2016-04-19       5348
 2016-04-20       4716
 2016-04-21       7753
 2016-04-22      54550
 2016-04-23     166662
 2016-04-24     181838
 2016-04-25     106872
 2016-04-26     183511
 2016-04-27     186936 <- math/assumption was correct, good match with ASH data for 4/27 in previous post
 2016-04-28     129485
 2016-04-29      47922
 2016-04-30     161283
 2016-05-01      70369
 2016-05-02      30410
 2016-05-03       9765
 2016-05-04       7505
 2016-05-05       3927
 2016-05-06      11423

ASH (active session history) gathers data by sampling active sessions every second…out of which every 10th makes it into AWR. Not an exact science, but the trend is clear, we had a bump in sql-s with literals starting around 4/23 for several days.

We can get more information about parsing from DBA_HIST_SYSSTAT:

TIME STAT_NAME                    VALUE_DIFF   DIFF_PER_SEC
---- --------------------------- ----------- --------------
0418 parse count (hard)               978020          11.32
0427 parse count (hard)              1177316          13.62 <- around 200thousand more hard parses for the day, matching ASH
0418 parse time elapsed               126050           1.46
0427 parse time elapsed              2442229          28.26 <- around 2.3 million seconds added to DB time
0418 parse time cpu                    38299            .44
0427 parse time cpu                   487414           5.64 <- CPU increased by 450 thousand seconds for the day, it is 5 more seconds on CPU each second
0418 CPU used by this session         498708           5.77
0427 CPU used by this session         890131          10.30 <- CPU usage doubled, the db is using 10 CPU-s every second, the extra 5 came from parsing

The numbers are pretty close to what I saw in the AWR reports, the query I used to generate the report is correct.

Let’s look at “parse time CPU” [red] over time. The graph is normalized for time (per second values). Including “CPU used by this session” [blue] allows us to see how much parsing contributed to overall CPU used by the db. systat_cpusystat_cpu.jpg
It is obvious we had excessive hard parsing from around 4/23 for a week, DB CPU utilization doubled from around 5 to 10 for each second.

 

I was wondering if the 2 fold increase in CPU utilization by the DB is too much for the machine? Let’s show DB and OS CPU numbers on the same chart to decide. DBA_HIST_SYSMETRIC_SUMMARY has both, this makes our query very simple.sysmetrics_cpu.jpg
sysmetrics_cpu.jpg
From 4/23 “CPU Usage Per Sec” [blue line] flattens for a week at around 1000 centicesonds (=10 seconds), it is matching the info from systat above. At the same time OS CPU [red line] shuts up to around 50 seconds on average which translates to 40% CPU utilization (=50/128)… we may get to this later, but I can assure you the OS CPU numbers are matching data from v$osstat and also what we see in OEM and from vmstat.

The periodic DB CPU peaks before 4/23 are from over night batches followed by normal activity at business hours. I may get to this in a future post, remind me if I forget.

This is getting interesting, the machine is not maxed out on CPU even when parsing doubled the CPU used by the DB. Also, the small spikes in DB CPU use correlate with bigger spikes in OS utilization…like a magnifier effect, strange. In addition, most load on this machine should come from the database, so who else is using the rest of the CPU?

I smell discrepancy between the CPU numbers reported by OS and the DB… read on!

BTW, you can find the sql-s I used in this post in isitthecpufromparsing.txt.

Advertisements