{"id":1156,"date":"2006-12-07T12:00:00","date_gmt":"2006-12-07T12:00:00","guid":{"rendered":"http:\/\/orcldoug.com\/blog\/?p=1156"},"modified":"2006-12-07T12:00:00","modified_gmt":"2006-12-07T12:00:00","slug":"a-more-complex-statspack-example-part-2","status":"publish","type":"post","link":"http:\/\/orcldoug.com\/blog\/2006\/12\/07\/a-more-complex-statspack-example-part-2\/","title":{"rendered":"A More Complex Statspack Example – Part 2"},"content":{"rendered":"

So far we’re barely into the comparison of the Statspack reports from the two different test environments and they look quite different<\/a> already.<\/p>\n

Next up, the Instance Efficiency Percentages. I have to confess that I rarely find these very useful because the numbers are always near 100% on most databases I look at and, even when they aren’t, they’re aggregating so much detail that who knows what they’re telling us? (Actually, this is a good point to say that there’s a lot of opinion in these blogs and this is my personal approach in this particular case. I’m very interested in hearing how others approach these reports. For example, here is Jonathan Lewis discussing Statspack instance efficiency percentages<\/a>.)<\/p>\n

This particular example proves an exception to the rule, though, largely because of the Execute to Parse ratio.<\/p>\n

Our Environment<\/strong><\/p>\n<\/p>\n

Instance Efficiency Percentages (Target 100%)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Buffer Nowait %:\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Redo NoWait %:\u00a0\u00a0\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Buffer\u00a0 Hit\u00a0\u00a0 %:\u00a0\u00a0 98.63\u00a0\u00a0\u00a0 In-memory Sort %:\u00a0\u00a0\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Library Hit\u00a0\u00a0 %:\u00a0\u00a0 99.81\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Soft Parse %:\u00a0\u00a0\u00a0\u00a0 99.76\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Execute to Parse %:\u00a0 -59.73\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Latch Hit %:\u00a0\u00a0\u00a0\u00a0 99.99Parse CPU to Parse Elapsd %:\u00a0\u00a0 98.32\u00a0\u00a0\u00a0\u00a0 % Non-Parse CPU:\u00a0\u00a0\u00a0\u00a0 96.73<\/code><\/pre>\n<\/p>\n
Vendor Environment<\/strong><\/p>\n<\/p>\n
Instance Efficiency Percentages (Target 100%)~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Buffer Nowait %:\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Redo NoWait %:\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Buffer\u00a0 Hit\u00a0\u00a0 %:\u00a0\u00a0 95.25\u00a0\u00a0\u00a0 In-memory Sort %:\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Library Hit\u00a0\u00a0 %:\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Soft Parse %:\u00a0 100.00\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Execute to Parse %:\u00a0 -92.37\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Latch Hit %:\u00a0 100.00Parse CPU to Parse Elapsd %:\u00a0\u00a0 97.01\u00a0\u00a0\u00a0\u00a0 % Non-Parse CPU:\u00a0\u00a0 95.48<\/code><\/pre>\n<\/p>\n
Further confirmation of the problem is available by jumping down a few sections in the report to SQL ordered by Parse Calls section (just our environment, this time)<\/p>\n<\/p>\n
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 % Total\u00a0Parse Calls\u00a0 Executions\u00a0\u00a0 Parses\u00a0 Hash Value------------ ------------ -------- ----------\u00a0\u00a0 1,777,416\u00a0\u00a0\u00a0 1,777,416\u00a0\u00a0\u00a0 21.63 1081982467Module: dllhost.exeINSERT INTO W6FORECAST_UNITS_MEASURES (W6Key,W6SubKey_1,Name,RawValue,ActualValue,MinError,MaxError,TrendValue,FittedValue,Description) VALUES(:1,:2,:3,:4,:5,:6,:7,:8,:9,:10)
<\/p>
\u00a0\u00a0 1,777,416\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\u00a0\u00a0\u00a0 21.63 3225036475Module: dllhost.exeSELECT W6Key,W6SubKey_1,Name,RawValue,ActualValue,MinError,MaxError,TrendValue,FittedValue,Description FROM W6FORECAST_UNITS_MEASURES<\/p>
\u00a0\u00a0\u00a0\u00a0 444,354\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 0\u00a0\u00a0\u00a0\u00a0 5.41\u00a0 956924307Module: dllhost.exeSELECT RelatedPlan,PlanScenario,Region,District,JobType,ParentUnit,JobCategory FROM W6FORECAST_UNITS<\/p><\/code><\/pre>\n<\/p>\n
The first statement is using bind variables, so you would think that Oracle wouldn’t need to parse it each time it executes, but that’s not the case here. Worse, the next two statements aren’t even executed, just parsed! I’ve seen this before with certain development tools that parse a statement in order to validate it, but never use the results. (You need to bear in mind the scale of the problem, though. The parse operations for those three statements, divided by the number of minutes that the report covers, is 1100 parse operations per minute, or 18 per second.)<\/p>\n
Okay, on to the Top 5 Timed Events, which is often one of the most useful sections.<\/p>\n
Our Environment<\/strong><\/p>\n<\/p>\n
Event\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Waits\u00a0\u00a0\u00a0 Time (s) Ela Time-------------------------------------------- ------------ ----------- --------CPU time\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 23,832\u00a0\u00a0\u00a0 63.56log file sync\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 423,557\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 6,909\u00a0\u00a0\u00a0 18.43log file parallel write\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 837,369\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2,164\u00a0\u00a0\u00a0\u00a0 5.77sbtwrite2\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 75,108\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 1,366\u00a0\u00a0\u00a0\u00a0 3.64sbtbackup\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 6\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 1,230\u00a0\u00a0\u00a0\u00a0 3.28<\/code><\/pre>\n<\/p>\n
Vendor Environment<\/strong><\/p>\n<\/p>\n
Event\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Waits\u00a0\u00a0\u00a0 Time (s) Ela Time-------------------------------------------- ------------ ----------- --------CPU time\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 2,342\u00a0\u00a0\u00a0 64.40db file scattered read\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 331,760\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 631\u00a0\u00a0\u00a0 17.35db file sequential read\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 152,702\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 466\u00a0\u00a0\u00a0 12.81db file parallel write\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 7,430\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 72\u00a0\u00a0\u00a0\u00a0 1.97log file parallel write\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 76,262\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 42\u00a0\u00a0\u00a0\u00a0 1.15<\/code><\/pre>\n<\/p>\n
In this case, it’s actually not too useful, but let’s start with what I can<\/em> take from it.<\/p>\n
1) There’s an RMAN backup running at some point during our test – signified by the sbt events.
2) There’s a similar percentage of time spent running on the CPU, as opposed to waiting, in both reports.
3) All the other wait events are i\/o related, which isn’t too surprising in a batch job which is moving data around. <\/p>\n
How about the problems, though? Well our system has 23,832 seconds of CPU available over the report period, the vendor’s only 2,342. Considering that the vendor’s Statspack report covers a longer period, how could that be? Well, the servers have completely different CPU configurations and because Statspack is a system-wide report (well, more accurately, an instance-wide report) it’s going to aggregate the CPU resource as well as the wait events. Once you realise this, then it’s obvious, but I’ve seen more than one person wonder how they can get more seconds of CPU than the number of seconds in the snapshot interval.<\/p>\n
In any case, the interval for this report is 12 hours, which is far too long because I don’t know whether all of those wait events are occuring in a short burst, or throughout the reporting period. That’s why I would normally run a report for a 15 minute interval rather than such a long period, except when I’m comparing the performance of a single task and want the report to cover it’s entire progress.<\/p>\n
Another problem\u00a0showing up in\u00a0my current investigations is that our environment seems to have a real problem with log file sync events that isn’t present on the vendor’s environment. My initial reaction to this was that we might have a problem with the disks that our online redo log files sit on. To check this, I flicked down to the next section, containing all the wait events and not just the Top 5, so that I could see the log file sync waits in the vendor’s environment too.<\/p>\n
Our Environment<\/strong><\/p>\n<\/p>\n
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Avg\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Total Wait\u00a0\u00a0 wait\u00a0\u00a0\u00a0 WaitsEvent\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Waits\u00a0\u00a0 Timeouts\u00a0\u00a0 Time (s)\u00a0\u00a0 (ms)\u00a0\u00a0\u00a0\u00a0 \/txn---------------------------- ------------ ---------- ---------- ------ --------log file sync\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 423,557\u00a0\u00a0\u00a0\u00a0\u00a0 4,462\u00a0\u00a0\u00a0\u00a0\u00a0 6,909\u00a0\u00a0\u00a0\u00a0 16\u00a0\u00a0\u00a0\u00a0\u00a0 1.0<\/code><\/pre>\n<\/p>\n
Vendor Environment<\/strong><\/p>\n<\/p>\n
\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Avg\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Total Wait\u00a0\u00a0 wait\u00a0\u00a0\u00a0 WaitsEvent\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 Waits\u00a0\u00a0 Timeouts\u00a0\u00a0 Time (s)\u00a0\u00a0 (ms)\u00a0\u00a0\u00a0\u00a0 \/txn---------------------------- ------------ ---------- ---------- ------ --------log file sync\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 7,874\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 3\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0\u00a0 11\u00a0\u00a0\u00a0\u00a0\u00a0 1\u00a0\u00a0\u00a0\u00a0\u00a0 1.0<\/code><\/pre>\n<\/p>\n
Okay, so our log file syncs do take a lot longer, but the stand-out numbers for me here are that our test suffered 423,557 log file sync waits to the vendor’s 7,874. Are we *sure* these two environments are running the same workload?!?!?<\/p>\n","protected":false},"excerpt":{"rendered":"
So far we’re barely into the comparison of the Statspack reports from the two different test environments and they look quite different already. Next up, the Instance Efficiency Percentages. I have to confess that I rarely find these very useful because the numbers are always near 100% on most databases I look at and, even… Continue reading A More Complex Statspack Example – Part 2<\/span><\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[1],"tags":[],"class_list":["post-1156","post","type-post","status-publish","format-standard","hentry","category-uncategorized","entry"],"jetpack_featured_media_url":"","jetpack-related-posts":[{"id":1159,"url":"http:\/\/orcldoug.com\/blog\/2006\/12\/11\/a-more-complex-statspack-example-summary\/","url_meta":{"origin":1156,"position":0},"title":"A More Complex Statspack Example – Summary","date":"December 11, 2006","format":false,"excerpt":"Looking back at the three blogs (and hopefully the comments, where others have made some very useful contributions), it's all quite unsatisfactory, isn't it? We haven't solved the problem. All we've proved is that the tests aren't equivalent, although I think there's value in that negative result because I was\u2026","rel":"","context":"With 3 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1155,"url":"http:\/\/orcldoug.com\/blog\/2006\/12\/06\/a-more-complex-statspack-example-part-1\/","url_meta":{"origin":1156,"position":1},"title":"A More Complex Statspack Example – Part 1","date":"December 6, 2006","format":false,"excerpt":"Following on from the last Statspack example, up popped an example at work this week of another common reason I use Statspack - comparing the performance of different environments. It's also a nice illustration of some of Statspack's limitations.Because a Statspack report contains a lot of information and this particular\u2026","rel":"","context":"With 8 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1153,"url":"http:\/\/orcldoug.com\/blog\/2006\/12\/01\/a-small-statspack-success\/","url_meta":{"origin":1156,"position":2},"title":"A Small Statspack Success","date":"December 1, 2006","format":false,"excerpt":"I'll warn you up front that this is going to be spectacularly lacking in detail but it's a simple and true example from the other week of the kind of thing I find Statspack useful for.One of the developers scuttled round to my desk one late shift very concerned about\u2026","rel":"","context":"With 7 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1428,"url":"http:\/\/orcldoug.com\/blog\/2008\/08\/14\/time-matters-an-infinite-capacity-for-waiting\/","url_meta":{"origin":1156,"position":3},"title":"Time Matters – An Infinite Capacity for Waiting*","date":"August 14, 2008","format":false,"excerpt":"When I was teaching the 10g Performance class at my last customer site, I remarked that the total number of seconds you see in the \"Top 5 Timed Events\" section of a Statspack or AWR report will often be greater than the total number of seconds between the snapshot intervals.\u2026","rel":"","context":"With 6 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1429,"url":"http:\/\/orcldoug.com\/blog\/2008\/08\/20\/time-matters-db-time\/","url_meta":{"origin":1156,"position":4},"title":"Time Matters – DB Time","date":"August 20, 2008","format":false,"excerpt":"[In retrospect, the title of that first blog post might have suited the subject, but doesn't translate too well for subsequent related blog posts. That was a lack of planning or foresight on my part. These blog posts are tumbling out of my head in a fairly incoherent way. Maybe\u2026","rel":"","context":"With 13 comments","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]},{"id":1050,"url":"http:\/\/orcldoug.com\/blog\/2006\/08\/10\/historical-perspective-part-2\/","url_meta":{"origin":1156,"position":5},"title":"Historical Perspective (Part 2)","date":"August 10, 2006","format":false,"excerpt":"Let's look at items 2 and 3 from the list in my previous blog1) You know you have a performance problem and can re-create it by running a specific part of the application, be it a user interaction or batch job.2) You have an intermittent but recurring performance problem which\u2026","rel":"","context":"Similar post","img":{"alt_text":"","src":"","width":0,"height":0},"classes":[]}],"_links":{"self":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1156","targetHints":{"allow":["GET"]}}],"collection":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/comments?post=1156"}],"version-history":[{"count":0,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/posts\/1156\/revisions"}],"wp:attachment":[{"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/media?parent=1156"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/categories?post=1156"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/orcldoug.com\/blog\/wp-json\/wp\/v2\/tags?post=1156"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}
Here is an excellent Jonathan Lewis article<\/a> that looks into this\u00a0difficulty\u00a0in more detail.<\/p>\n
Isn’t it horrific? That means the application is parsing many more statements than it’s executing. At first this seems so bizarre as to be impossible (and, as Alex Gorbachev points out in a comment to Dan Fink’s blog<\/a>, it’s always worth considering that Statspack itself has bugs). However I know this ratio reflects reality because I’ve already traced this application<\/a>. There’s more on why you might see an negative Execute to Parse ratio in this AskTom thread<\/a>. Suffice to say I’ve already expressed my dismay to the vendor and warned that this is likely to limit scalability, but the application won’t be re-written any time soon.<\/p>\n