Re: Excessive Logical IOs against which Table/Index

From: Tim Gorman <tim_at_evdbt.com>
Date: Tue, 26 Apr 2016 20:52:17 -0600
Message-ID: <c89c006a-c35e-0de7-963c-ab434e5a0c97_at_evdbt.com>



Jessica,

Sorry for the late response, but I wanted to add one more tool suggestion...

I've encountered similar situations, and I've found it useful to initiate SQL trace (event 10046) before the SQL statement started and then run TKPROF to aggregate the information as the trace information was accumulating. But you can't always have the foresight to initiate SQL tracing in time, and sometimes it is difficult to capture the SQL and run it in a controlled environment. Also, improvements to Active Session History in Oracle11gR1, have provided an easier approach.

When the ASH views were introduced in Oracle10g, they included only the SQL_PLAN_HASH_VALUE for detail about the execution plan. Starting in Oracle11g v11.1, the ASH views were augmented by more specific columns such as SQL_PLAN_LINE_ID, SQL_PLAN_OPERATIONS, SQL_PLAN_OPTIONS, which you might recognize as columns also found in EXPLAIN PLAN tables.

What this meant is that the second-by-second V$ACTIVE_SESSION_HISTORY sampling was being recorded to the level of a line within an execution plan. This means that we had a metric similar to elapsed time (i.e. ASH time) to display next to the individual lines in an execution plan, as the SQL statement was running. As I mentioned, it wasn't exactly elapsed time, but close enough for the purposes of identifying where in the execution plan something like elapsed time was being spent, along with other metrics provided in ASH.

Now, this isn't very earthshaking after the SQL statement has completed executing, because that information is displayed by the DBMS_XPLAN package.

But while the SQL statement is still executing, it isn't available anywhere else in Oracle. Not even SQL Monitoring and SQL Plan Monitoring captures elapsed time.

I've written a pipelined table function within a PL/SQL package called ASH_XPLAN. It is based on the DBMS_XPLAN package (which also consists of pipelined table functions), but for each line of the execution plan, it aggregates information from the V$ACTIVE_SESSION_HISTORY view. So now you can see where the elapsed time proxy called "ASH time" is being spent within the execution plan while the SQL statement is still running.

A presentation slidedeck which describes all this and the ASH_XPLAN package is available online here
<http://evdbt.com/download/presentation-accelerating-devops-using-data-virtualization/>, along with the source code for ASH_XPLAN and sample spooled output.

Please let me know if you have any questions?

Hope this helps!

-Tim

On 4/25/16 11:44, Stefan Koehler wrote:
> Hello Jessica,
> unfortunately you have not mentioned your Oracle version and OS, but several ways to identify the objects.
>
> I guess you want to know possibilities for step 3 in case of logical I/O - so here we go:
>
> 1) SQL Monitoring Report (needs additional license)
> 2) DTrace for Solaris: https://alexanderanokhin.wordpress.com/2011/11/13/dynamic-tracing-of-oracle-logical-io/
> 3) SystemTap for Linux: https://db-blog.web.cern.ch/blog/luca-canali/2014-12-life-oracle-io-tracing-logical-and-physical-io-systemtap
> 4) SQLd360 using ASH (needs additional license and can be queried manually as well, but i highly recommend SQLd360 for it):
> https://mauro-pagano.com/2016/01/06/execution-plan-tree-temperature/
>
>
> Your step 1 and 2 can be done with one tool - the well known fish called "Snapper": http://blog.tanelpoder.com/files/scripts/snapper.sql
>
> Best Regards
> Stefan Koehler
>
> Freelance Oracle performance consultant and researcher
> Homepage: http://www.soocs.de
> Twitter: _at_OracleSK
>
>> Jessica Mason <jessica.masson85_at_gmail.com> hat am 25. April 2016 um 19:10 geschrieben:
>>
>> Hello List,
>>
>> Last week, I was involved in a production issue, where a data load job, which normally takes few hours to complete, had been running for more than
>> 48 hours. I tried to take the following systematic approach to identify the cause -
>>
>> Step 1 - Identify the session and started profiling it. All the time, the session was on CPU.
>>
>> Step 2 - To understand why the session was burning CPU, the v$sesstat view was queried and below were the top statistics that were changing :
>>
>> 43126075162624 logical read bytes from cache
>> 240440566773 table scan rows gotten
>> 2632208820 session logical reads
>> 2632206511 consistent gets
>> 2632206511 consistent gets from cache
>> 2632205708 consistent gets from cache (fastpath)
>>
>> Step 3 - Next, I wanted to know the object ( table/index) against which these logical IOs were happening so that I could focus on the operations,
>> involving these objects, in the execution plan but didn't know which view to query.
>>
>> The above information could have saved us lot to time to identify the cause ( in this case, an unique index was dropped and Oracle was doing FTS on
>> a table which was referred 6 times in the query fetching million of records).
>>
>> So, my questions to the list is that which v$ view should I have checked?
>> Or is there a better approach to troubleshoot such issues?
>>
>>
>> Thanks
>> JM
> --
> http://www.freelists.org/webpage/oracle-l
>
>
>
>

--
http://www.freelists.org/webpage/oracle-l
Received on Wed Apr 27 2016 - 04:52:17 CEST

Original text of this message