Re: Manual execution vs v$session discrepancy

We have run into a very similar situation with another SQL in our prod environment again. The awr reports also show average of 4 seconds/exec for this query in consideration.

I decided to trace the query anyway, but I am not lucky there. I know the sessionid, but when I set the trace I am not able to locate the trace file. I cannot modify the query in the app server since that is a different group; I set the trace on at level 8 with dbms_system.set_ev. v$session shows trace enabled for the session in qn, but I do not know which one is the trace file. I tried trcsess by giving it sid.serial#, that seems to produce a file with just 4 lines and no useful info.

I can sample the sql bind capture but as before, the values from there return superfast when i run the query for those values. I used the values used while peeking (thanks to Jonathans blog), still the results were fast with those values. fyi, I test these values in prod itself. child_cursors - maybe one or two. I should have checked for variation in the child cursors, but was too busy. this is a psft fin app. as before several 1000 executions per day.

At this point, I would really like to see the bind var values for which the queries are taking several seconds. Any help is greatly appreciated.

Thanks.

On Thu, Sep 3, 2015 at 1:51 AM, Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk> wrote:

>
> It's perfectly feasible for a session to report a much longer run-time for
> a query than v$sql shows. The session time you're looking at may include
> all the network roundtrip time and any client processing time that goes on
> between round-trips.
>
> As far as dealing with 7 seconds vs. 2/10th seconds - some of that may be
> down to the way the client and server communicate, some of it may be down
> to the server being busy while the production query was being run, some may
> be down very specifically to the concurrency of usage (competing for
> latches and mutexes, driving up CPU time), some may be down to the
> production data being subject to update and read-consistency overheads
> while the queries were being run. However, the difference does look a
> little extreme so ...
>
>
> Apart from acquiring sets of bind values, did you also acquire the bind
> values used when the cursors were optimised ? Did you check the plan(s)
> actually used matched the plan(s) your tests produced.
>
> When you tested did you use the bind variable sets as literals to the
> query, or did you have a framework that injected them as bind variables of
> the correct type? When you tested was it against the same data set with the
> same set of object statistics and similar concurrent rate of change of data
> ? When you queried v$sql how many child cursors were in existence (and what
> was the highest child number) ? If there were multiple child cursors was
> there much variation in the stats between children. Were the figures in
> v$sqlstat consistent with those in v$sql. vary Did the details from v$sql
> show you similar buffer_gets in the production and test cases. There are
> several time-related columns in v$sql beyond elapsed_time and cpu_time
> (e.g. plsql_exec_time, java_exec_time, user_io_wait_time,
> cluster_wait_time) are there any clues where the time was spent?
>
>
> Regards
> Jonathan Lewis
> http://jonathanlewis.wordpress.com
> _at_jloracle
> ------------------------------
> *From:* oracle-l-bounce_at_freelists.org [oracle-l-bounce_at_freelists.org] on
> behalf of Ram Raman [veeeraman_at_gmail.com]
> *Sent:* 03 September 2015 03:50
> *To:* ORACLE-L
> *Subject:* Manual execution vs v$session discrepancy
>
>
> List,
>
> We had a SQL that was being run repeatedly over 10K times in our prod
> system today. Turned out to be something related to fiscal year. It spiked
> up our CPU big time. I got several value sets for the SQL from the sql bind
> capture and executed them myself for about a dozen value sets; each and
> everyone of my manual execution returned in about 2/10ths of a second.
> However the v$session view would show the sessions run that SQL (sql_id,
> last_call_et, status) for a few minutes. That was the case for several
> users the whole day. Per v$sql, the average execution time for that SQL
> was 7 seconds since the first load this morning. AWR reports showed that
> the averages are anywhere from 4 seconds and up depending on the hour. I
> was confused by what the v$session showed me vs my execution times. Am I
> missing something here? bind capture interval is left at default 900
> seconds.
>
> Could it be that the values I checked (about 15) just happened to be 'good
> values' or the environment could have been different for the executed SQLs?
> I was hesitant to turn on the trace with the CPU usage through the roof.
> v10.2
>
> Thanks.
>
> --
>
>
>

--

--
http://www.freelists.org/webpage/oracle-l