tkprof not showing performance query 12.1.0.2 oracle

[satish]

Dear Erman,

Our apps version R12.2.5
DB RAC 12.1.0.2

We have a custom concurrent program which runs 5 minutes for some accounts.The same program when runs for other accounts where we have huge data,this program runs for 1 hour and starts consuminh 100%cpu through out the completion.

When it runs for 5minutes,there is no cpu consumption.We have enabled trace for this program from front end.Once the program completed,we have dont tkprof with below options.

tkprof tracefile_name.trc tracefileoutput.txt explain=apps/apps sort='(exeela,prsela,fchela)'.


and the top command listed in tkprof is not showing any high elapsed times or cpu times.Is it normal?I dint understand where the time goes.

SQL ID: 67264jh510f32 Plan Hash: 368250971

SELECT  description FROM        FND_FLEX_VALUES_VL WHERE        flex_value = :seg_val
  AND   flex_value_set_id = :vset_id


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    16689      0.09       0.11          0          0          0           0
Execute  16689      0.27       0.29          0          0          0           0
Fetch    16689      0.22       0.25          2     136293          0       16689
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    50067      0.58       0.66          2     136293          0       16689

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)   (recursive depth: 2)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  NESTED LOOPS  (cr=8 pr=0 pw=0 time=66 us cost=6 size=83 card=1)
         1          1          1   NESTED LOOPS  (cr=7 pr=0 pw=0 time=55 us cost=6 size=83 card=1)
         1          1          1    TABLE ACCESS BY INDEX ROWID BATCHED FND_FLEX_VALUES (cr=4 pr=0 pw=0 time=36 us cost=4 size=38 card=1)
         1          1          1     INDEX RANGE SCAN FND_FLEX_VALUES_N1 (cr=3 pr=0 pw=0 time=25 us cost=3 size=0 card=1)(object id 398655)
         1          1          1    INDEX UNIQUE SCAN FND_FLEX_VALUES_TL_U1 (cr=3 pr=0 pw=0 time=18 us cost=1 size=0 card=1)(object id 544756)
         1          1          1   TABLE ACCESS BY INDEX ROWID FND_FLEX_VALUES_TL (cr=1 pr=0 pw=0 time=8 us cost=2 size=45 card=1)



Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   NESTED LOOPS
      1    NESTED LOOPS
      1     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID BATCHED) OF
                'FND_FLEX_VALUES' (TABLE)
      1      INDEX   MODE: ANALYZED (RANGE SCAN) OF
                 'FND_FLEX_VALUES_N1' (INDEX)
      1     INDEX   MODE: ANALYZED (UNIQUE SCAN) OF
                'FND_FLEX_VALUES_TL_U1' (INDEX (UNIQUE))
      1    TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF
               'FND_FLEX_VALUES_TL' (TABLE)

********************************************************************************



Thanks,
Satish.G

[satish]

trace file and tkprof attachedtrace.zip attched

Thank you,
Satish

[ErmanArslansOracleBlog]

What is the type of that custom program? Java, PLSQL , C?
What does that custom program do? What is its internal mechanism? I mean it may be waiting for some resource on the apps node.. It may get some data and manipulate it in the apps layer.. So this may be the case..
That elapsed time is low.. But you say you waited for 1 hour to complete.. So there must be some things that is done in the application tier by the custom program ..
First, we needed to know what we are dealing with.. That's why kindly inform me with the info requested above.

[satish]

Dear erman,

This concurrent program name is GL transaction account head wise report which select data for 1 year.

It is plsql package
Input from date,to date,account number,unit number

Thanks,
Satish

[satish]

And this is wait event it shows

SQL> SQL> SELECT event,count(*)
  2  FROM dba_hist_active_sess_history a
WHERE a.sample_time BETWEEN to_date('05-APR-2021 10:00:00','DD-MON-YYYY HH24:MI:SS') AND
  3    4  to_date('05-APR-2021 17:00:00','DD-MON-YYYY HH24:MI:SS') and session_id=611 and SESSION_SERIAL#=19685 and INSTANCE_NUMBER=2 group by event;

Waited for                       COUNT(*)
------------------------------ ----------
   on cpu                                  1244
gcs drm freeze in enter server          2
 mode

read by other session                  43
db file sequential read               353
cursor: pin S                           4
buffer busy waits                      19
gc current block 2-way                  4
gc current grant 2-way                 21
library cache: mutex X                  5
gc current block busy                   1
gc buffer busy acquire                 61
gc current grant busy                  36

12 rows selected.


Process from top shows as consuming 100%.At the same time,when i get the sid and serial%,it is waiting for event db file sequential read

Thanks,
Satish

[ErmanArslansOracleBlog]

It is the wait time and problematic queries or plsql blocks that we need
concantrate not the wait count in this case..we see cpu usage and index
reads here .. but it is not sufficient.. these counts may be misleading.
Pleae enable trace for the conc. program using enable trace check box in
forms screens and rerun it..
Then check the trace. Find the problematic query or queries and analyze..If
the wait times are okay, speak with the developer of that plsql and discuss
the waits that the program may get -- outside the database...




5 Nis 2021 Pzt 13:48 tarihinde satish [via Erman Arslan's Oracle Forum] <
[e-mail]> şunu yazdı:

> And this is wait event it shows
>
> SQL> SQL> SELECT event,count(*)
>   2  FROM dba_hist_active_sess_history a
>   3  WHERE a.sample_time BETWEEN to_date('05-APR-2021
> 14:00:00','DD-MON-YYYY HH24:MI:SS') AND
>   4  to_date('05-APR-2021 16:00:00','DD-MON-YYYY HH24:MI:SS') and
> session_id=611 and SESSION_SERIAL#=19685 group by event;
>
> Waited for                       COUNT(*)
> ------------------------------ ----------
>        ONCPU                    574
> gcs drm freeze in enter server          1
>  mode
>
> db file sequential read               105
> gc current block 2-way                  1
> gc current grant 2-way                 13
>
> Thanks,
> Satish
>
>
> ------------------------------
> If you reply to this email, your message will be added to the discussion
> below:
>
> http://erman-arslan-s-oracle-forum.2340467.n4.nabble.com/tkprof-not-showing-performance-query-12-1-0-2-oracle-tp9572p9581.html
> To start a new topic under EBS 12.2, email [e-mail]
> To unsubscribe from Erman Arslan's Oracle Forum, click here
> <http://erman-arslan-s-oracle-forum.2340467.n4.nabble.com/template/NamlServlet.jtp?macro=unsubscribe_by_code&node=1&code=cm1hbi5hcnNsYW5AZ21haWwuY29tfDF8LTc5Nzg2MjgzNA==>
> .
> NAML
> <http://erman-arslan-s-oracle-forum.2340467.n4.nabble.com/template/NamlServlet.jtp?macro=macro_viewer&id=instant_html%21nabble%3Aemail.naml&base=nabble.naml.namespaces.BasicNamespace-nabble.view.web.template.NabbleNamespace-nabble.view.web.template.NodeNamespace&breadcrumbs=notify_subscribers%21nabble%3Aemail.naml-instant_emails%21nabble%3Aemail.naml-send_instant_email%21nabble%3Aemail.naml>
>

[satish]

Dear Erman,

As suggested,got the trace and the top sql is below.Looks like fetches are taking more cpu and elapsed time.4897574/50916=96 rows per fetch.Any suggestions

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute   2230      0.27       0.28          0          0          0           0
Fetch    50916   4410.58    4426.01          3   23624274          0     4897574
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    53147   4410.85    4426.29          3   23624274          0     4897574

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 173  (APPS)   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
        14         14         14  HASH GROUP BY (cr=3840 pr=2 pw=0 time=66803 us cost=725 size=334 card=1)
        14         14         14   FILTER  (cr=2650 pr=2 pw=0 time=30062 us)
        14         14         14    HASH JOIN  (cr=2650 pr=2 pw=0 time=30045 us cost=724 size=334 card=1)
        14         14         14     NESTED LOOPS  (cr=2650 pr=2 pw=0 time=30028 us cost=724 size=334 card=1)
        24         24         24      NESTED LOOPS  (cr=2626 pr=2 pw=0 time=29879 us cost=724 size=334 card=1)
        24         24         24       STATISTICS COLLECTOR  (cr=2600 pr=2 pw=0 time=29662 us)
        24         24         24        HASH JOIN  (cr=2600 pr=2 pw=0 time=27402 us cost=723 size=278 card=1)
        24         24         24         NESTED LOOPS  (cr=2600 pr=2 pw=0 time=27375 us cost=723 size=278 card=1)
        27         27         27          STATISTICS COLLECTOR  (cr=2555 pr=2 pw=0 time=27068 us)
        27         27         27           HASH JOIN  (cr=2555 pr=2 pw=0 time=25404 us cost=722 size=152 card=1)
        27         27         27            NESTED LOOPS  (cr=2555 pr=2 pw=0 time=25399 us cost=722 size=152 card=1)
         1          1          1             STATISTICS COLLECTOR  (cr=2533 pr=2 pw=0 time=25212 us)
         1          1          1              NESTED LOOPS  (cr=2533 pr=2 pw=0 time=25167 us cost=692 size=102 card=1)
         1          1          1               TABLE ACCESS BY INDEX ROWID GL_JE_CATEGORIES_TL (cr=3 pr=2 pw=0 time=7354 us cost=2 size=47 card=1)
         1          1          1                INDEX UNIQUE SCAN GL_JE_CATEGORIES_TL_U2 (cr=2 pr=2 pw=0 time=7340 us cost=1 size=0 card=1)(object id 544793)
         1          1          1               TABLE ACCESS FULL GL_CODE_COMBINATIONS (cr=2530 pr=0 pw=0 time=17805 us cost=690 size=55 card=1)
        27         27         27             TABLE ACCESS BY INDEX ROWID BATCHED GL_JE_LINES (cr=22 pr=0 pw=0 time=160 us cost=30 size=1950 card=39)
        27         27         27              INDEX RANGE SCAN GL_JE_LINES_N1 (cr=3 pr=0 pw=0 time=44 us cost=2 size=0 card=39)(object id 35240)
         0          0          0            TABLE ACCESS FULL GL_JE_LINES (cr=0 pr=0 pw=0 time=0 us cost=30 size=1950 card=39)
        24         24         24          TABLE ACCESS BY INDEX ROWID GL_JE_HEADERS (cr=45 pr=0 pw=0 time=196 us cost=1 size=126 card=1)
        27         27         27           INDEX UNIQUE SCAN GL_JE_HEADERS_U1 (cr=29 pr=0 pw=0 time=103 us cost=0 size=0 card=1)(object id 35224)
         0          0          0         TABLE ACCESS FULL GL_JE_HEADERS (cr=0 pr=0 pw=0 time=0 us cost=1 size=126 card=1)
        24         24         24       INDEX UNIQUE SCAN GL_JE_BATCHES_U1 (cr=26 pr=0 pw=0 time=120 us cost=0 size=0 card=1)(object id 35175)
        14         14         14      TABLE ACCESS BY INDEX ROWID GL_JE_BATCHES (cr=24 pr=0 pw=0 time=86 us cost=1 size=56 card=1)
         0          0          0     TABLE ACCESS FULL GL_JE_BATCHES (cr=0 pr=0 pw=0 time=0 us cost=1 size=56 card=1)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
     14   HASH (GROUP BY)
     14    FILTER
     14     HASH JOIN
     14      NESTED LOOPS
     24       NESTED LOOPS
     24        STATISTICS COLLECTOR
     24         HASH JOIN
     24          NESTED LOOPS
     27           STATISTICS COLLECTOR
     27            HASH JOIN
     27             NESTED LOOPS
      1              STATISTICS COLLECTOR
      1               NESTED LOOPS
      1                TABLE ACCESS   MODE: ANALYZED (BY
                           INDEX ROWID) OF 'GL_JE_CATEGORIES_TL' (TABLE)
      1                 INDEX   MODE: ANALYZED (UNIQUE SCAN)
                            OF 'GL_JE_CATEGORIES_TL_U2' (INDEX (UNIQUE))
      1                TABLE ACCESS   MODE: ANALYZED (FULL)
                           OF 'GL_CODE_COMBINATIONS' (TABLE)
     27              TABLE ACCESS   MODE: ANALYZED (BY INDEX
                         ROWID BATCHED) OF 'GL_JE_LINES' (TABLE)
     27               INDEX   MODE: ANALYZED (RANGE SCAN) OF
                          'GL_JE_LINES_N1' (INDEX)
      0             TABLE ACCESS   MODE: ANALYZED (FULL) OF
                        'GL_JE_LINES' (TABLE)
     24           TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID)
                      OF 'GL_JE_HEADERS' (TABLE)
     27            INDEX   MODE: ANALYZED (UNIQUE SCAN) OF
                       'GL_JE_HEADERS_U1' (INDEX (UNIQUE))
      0          TABLE ACCESS   MODE: ANALYZED (FULL) OF
                     'GL_JE_HEADERS' (TABLE)
     24        INDEX   MODE: ANALYZED (UNIQUE SCAN) OF
                   'GL_JE_BATCHES_U1' (INDEX (UNIQUE))
     14       TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF
                  'GL_JE_BATCHES' (TABLE)
      0      TABLE ACCESS   MODE: ANALYZED (FULL) OF 'GL_JE_BATCHES'
                 (TABLE)

********************************************************************************

Thanks,
SG

[ErmanArslansOracleBlog]

I think you need to get rid of the following FULL TABLE SCAN ->

TABLE ACCESS FULL GL_CODE_COMBINATIONS (cr=2530 pr=0 pw=0 time=17805 us cost=690 size=55 card=1)

So speak with your sql developers about this and make them tune the query.