Strange Performance Issue on 10gR2
DBAsupport.com Forums - Powered by vBulletin
Page 1 of 2 12 LastLast
Results 1 to 10 of 18

Thread: Strange Performance Issue on 10gR2

  1. #1
    Join Date
    Apr 2001
    Posts
    110

    Strange Performance Issue on 10gR2

    Hi,

    I have this strange performance issue which I have been troubleshooting for a week and is getting not very far.

    My users complain to me that all queries on this newly setup database is running much slower than their dev DB.

    New Production DB
    - is on a Sun box Solaris 10, 32 cores CPU, 32GB RAM, Sun storage
    - Oracle 10gR2 64 bit 10.2.0.1.0 Standard Edition
    - SGA_TARGET = 1.5GB
    - PGA_AGGREGATE_TARGET = 1GB
    - optimizer_mode = ALL_ROWS

    Dev DB
    - a normal MS Windows XP notebook
    - Oracle 10gR2 10.2.0.1.0 Standard Edition
    - SGA_TARGET = 270Mb
    - PGA_AGGREGATE_TARGET = 89Mb
    - optimizer_mode = ALL_ROWS

    Dataset for the testing is exactly the same on both system as they were from the same source.

    The query run on Dev DB took only 1min 40secs, while the same query run took 5+mins on Prod DB.
    Explain plan and statistics are the same on both systems.

    Below is the results taken from SQLPLUS with "set autotrace on" and "set timing on"

    Prod DB:
    18 rows selected.

    Elapsed: 00:05:22.72

    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 820129149

    -----------------------------------------------------------------------------------------------------------------------
    | Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
    -----------------------------------------------------------------------------------------------------------------------
    | 0 | SELECT STATEMENT | | 137M| 17G| | 12M (2)| 43:04:06 |
    | 1 | SORT UNIQUE | | 137M| 17G| 37G| 8634K (46)| 28:46:49 |
    | 2 | UNION-ALL | | | | | | |
    | 3 | HASH GROUP BY | | 75M| 9G| 20G| 4782K (2)| 15:56:29 |
    | 4 | MERGE JOIN CARTESIAN | | 75M| 9G| | 35273 (6)| 00:07:04 |
    |* 5 | HASH JOIN | | 1559 | 213K| | 316 (5)| 00:00:04 |
    | 6 | NESTED LOOPS | | 82 | 10414 | | 71 (5)| 00:00:01 |
    |* 7 | HASH JOIN | | 82 | 8364 | | 68 (5)| 00:00:01 |
    |* 8 | HASH JOIN | | 148 | 11544 | | 62 (4)| 00:00:01 |
    |* 9 | TABLE ACCESS FULL | FLIGHT_SCHEDULE_PROCESING | 148 | 6808 | | 42 (3)| 00:00:01 |
    |* 10 | TABLE ACCESS FULL | PERMIT_LICENSE | 355 | 11360 | | 19 (0)| 00:00:01 |
    | 11 | TABLE ACCESS FULL | USER_DETAILS | 520 | 12480 | | 5 (0)| 00:00:01 |
    | 12 | TABLE ACCESS BY INDEX ROWID| AIRLINE_MASTER | 1 | 25 | | 1 (0)| 00:00:01 |
    |* 13 | INDEX UNIQUE SCAN | SYS_C006428 | 1 | | | 0 (0)| 00:00:01 |
    | 14 | TABLE ACCESS FULL | OPERATING_FLIGHT_SCHEDULE | 89240 | 1132K| | 243 (4)| 00:00:03 |
    | 15 | BUFFER SORT | | 48714 | | | 2408K (2)| 08:01:43 |
    | 16 | INDEX FAST FULL SCAN | ACTION_ID_FK | 48714 | | | 22 (5)| 00:00:01 |
    | 17 | HASH GROUP BY | | 61M| 8165M| 16G| 3851K (2)| 12:50:21 |
    | 18 | MERGE JOIN CARTESIAN | | 61M| 8165M| | 28231 (6)| 00:05:39 |
    |* 19 | HASH JOIN | | 1255 | 171K| | 90 (5)| 00:00:02 |
    | 20 | NESTED LOOPS | | 82 | 10414 | | 71 (5)| 00:00:01 |
    |* 21 | HASH JOIN | | 82 | 8364 | | 68 (5)| 00:00:01 |
    |* 22 | HASH JOIN | | 148 | 11544 | | 62 (4)| 00:00:01 |
    |* 23 | TABLE ACCESS FULL | FLIGHT_SCHEDULE_PROCESING | 148 | 6808 | | 42 (3)| 00:00:01 |
    |* 24 | TABLE ACCESS FULL | PERMIT_LICENSE | 355 | 11360 | | 19 (0)| 00:00:01 |
    | 25 | TABLE ACCESS FULL | USER_DETAILS | 520 | 12480 | | 5 (0)| 00:00:01 |
    | 26 | TABLE ACCESS BY INDEX ROWID| AIRLINE_MASTER | 1 | 25 | | 1 (0)| 00:00:01 |
    |* 27 | INDEX UNIQUE SCAN | SYS_C006428 | 1 | | | 0 (0)| 00:00:01 |
    | 28 | TABLE ACCESS FULL | MARKETING_FLIGHT_SCHEDULE | 8264 | 104K| | 19 (6)| 00:00:01 |
    | 29 | BUFFER SORT | | 48714 | | | 1939K (2)| 06:28:00 |
    | 30 | INDEX FAST FULL SCAN | ACTION_ID_FK | 48714 | | | 22 (5)| 00:00:01 |
    -----------------------------------------------------------------------------------------------------------------------

    Predicate Information (identified by operation id):
    ---------------------------------------------------

    5 - access("OFS"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    7 - access("UD"."USER_ID"="PL"."ATMAN_USERID")
    8 - access("FSP"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    9 - filter("FSP"."SEASON_CODE"='NS0909')
    10 - filter("PL"."PERMIT_OR_LICENSE"='L' AND "PL"."DDGO"='1')
    13 - access("AM"."AIRLINE_ID"="FSP"."AIRLINE_ID")
    19 - access("OFS"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    21 - access("UD"."USER_ID"="PL"."ATMAN_USERID")
    22 - access("FSP"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    23 - filter("FSP"."SEASON_CODE"='NS0909')
    24 - filter("PL"."PERMIT_OR_LICENSE"='L' AND "PL"."DDGO"='1')
    27 - access("AM"."AIRLINE_ID"="FSP"."AIRLINE_ID")


    Statistics
    ----------------------------------------------------------
    0 recursive calls
    0 db block gets
    2007 consistent gets
    0 physical reads
    0 redo size
    3008 bytes sent via SQL*Net to client
    480 bytes received via SQL*Net from client
    3 SQL*Net roundtrips to/from client
    3 sorts (memory)
    0 sorts (disk)
    18 rows processed
    What's next after 10g?

  2. #2
    Join Date
    Apr 2001
    Posts
    110
    Dev DB:

    18 rows selected.

    Elapsed: 00:01:41.48

    Execution Plan
    ----------------------------------------------------------
    Plan hash value: 4057473448

    ----------------------------------------------------------------------------------------------------
    | Id | Operation | Name | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
    ----------------------------------------------------------------------------------------------------
    | 0 | SELECT STATEMENT | | 137M| 17G| | 17M (1)| 58:00:23 |
    | 1 | SORT UNIQUE | | 137M| 17G| 37G| 11M (46)| 38:44:20 |
    | 2 | UNION-ALL | | | | | | |
    | 3 | HASH GROUP BY | | 75M| 9G| 20G| 6437K (1)| 21:27:25 |
    | 4 | MERGE JOIN CARTESIAN | | 75M| 9G| | 35148 (6)| 00:07:02 |
    |* 5 | HASH JOIN | | 1559 | 213K| | 315 (5)| 00:00:04 |
    | 6 | NESTED LOOPS | | 82 | 10414 | | 71 (5)| 00:00:01 |
    |* 7 | HASH JOIN | | 82 | 8364 | | 67 (3)| 00:00:01 |
    |* 8 | HASH JOIN | | 148 | 11544 | | 62 (4)| 00:00:01 |
    |* 9 | TABLE ACCESS FULL | FLIGHT_SCHEDULE_PROCESING | 148 | 6808 | | 42 (3)| 00:00
    |* 10 | TABLE ACCESS FULL | PERMIT_LICENSE | 355 | 11360 | | 19 (0)| 00:00:01 |
    | 11 | TABLE ACCESS FULL | USER_DETAILS | 520 | 12480 | | 5 (0)| 00:00:01 |
    | 12 | TABLE ACCESS BY INDEX ROWID| AIRLINE_MASTER | 1 | 25 | | 1 (0)
    |* 13 | INDEX UNIQUE SCAN | SYS_C005605 | 1 | | | 0 (0)| 00:00:01 |
    | 14 | TABLE ACCESS FULL | OPERATING_FLIGHT_SCHEDULE | 89240 | 1132K| | 242 (4)|
    | 15 | BUFFER SORT | | 48714 | | | 3235K (1)| 10:47:11 |
    | 16 | INDEX FAST FULL SCAN | ACTION_ID_FK | 48714 | | | 22 (5)| 00:00
    | 17 | HASH GROUP BY | | 61M| 8165M| 16G| 5184K (1)| 17:16:55 |
    | 18 | MERGE JOIN CARTESIAN | | 61M| 8165M| | 28130 (6)| 00:05:38 |
    |* 19 | HASH JOIN | | 1255 | 171K| | 90 (5)| 00:00:02 |
    | 20 | NESTED LOOPS | | 82 | 10414 | | 71 (5)| 00:00:01 |
    |* 21 | HASH JOIN | | 82 | 8364 | | 67 (3)| 00:00:01 |
    |* 22 | HASH JOIN | | 148 | 11544 | | 62 (4)| 00:00:01 |
    |* 23 | TABLE ACCESS FULL | FLIGHT_SCHEDULE_PROCESING | 148 | 6808 | | 42 (3)| 00:00
    |* 24 | TABLE ACCESS FULL | PERMIT_LICENSE | 355 | 11360 | | 19 (0)| 00:00:01 |
    | 25 | TABLE ACCESS FULL | USER_DETAILS | 520 | 12480 | | 5 (0)| 00:00:01 |
    | 26 | TABLE ACCESS BY INDEX ROWID| AIRLINE_MASTER | 1 | 25 | | 1 (0)
    |* 27 | INDEX UNIQUE SCAN | SYS_C005605 | 1 | | | 0 (0)| 00:00:01 |
    | 28 | TABLE ACCESS FULL | MARKETING_FLIGHT_SCHEDULE | 8264 | 104K| | 19 (6)|
    | 29 | BUFFER SORT | | 48714 | | | 2606K (1)| 08:41:17 |
    | 30 | INDEX FAST FULL SCAN | ACTION_ID_FK | 48714 | | | 22 (5)| 00:00
    ----------------------------------------------------------------------------------------------------

    Predicate Information (identified by operation id):
    ---------------------------------------------------

    5 - access("OFS"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    7 - access("UD"."USER_ID"="PL"."ATMAN_USERID")
    8 - access("FSP"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    9 - filter("FSP"."SEASON_CODE"='NS0909')
    10 - filter("PL"."PERMIT_OR_LICENSE"='L' AND "PL"."DDGO"='1')
    13 - access("AM"."AIRLINE_ID"="FSP"."AIRLINE_ID")
    19 - access("OFS"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    21 - access("UD"."USER_ID"="PL"."ATMAN_USERID")
    22 - access("FSP"."SCHEDULE_NO"="PL"."SCHEDULE_NO")
    23 - filter("FSP"."SEASON_CODE"='NS0909')
    24 - filter("PL"."PERMIT_OR_LICENSE"='L' AND "PL"."DDGO"='1')
    27 - access("AM"."AIRLINE_ID"="FSP"."AIRLINE_ID")


    Statistics
    ----------------------------------------------------------
    0 recursive calls
    0 db block gets
    2007 consistent gets
    0 physical reads
    0 redo size
    2760 bytes sent via SQL*Net to client
    396 bytes received via SQL*Net from client
    3 SQL*Net roundtrips to/from client
    3 sorts (memory)
    0 sorts (disk)
    18 rows processed

    What's next after 10g?

  3. #3
    Join Date
    Apr 2001
    Posts
    110
    When the query is executed on Prod DB, I observed that the particular oracle unix session is taking up 1 CPU out of the 32 and is working 100% for the full 5+mins. If I kick off multiple SQLPLUS sessions running the same query, multiple CPUs will be working 100% each too.
    I observe this CPU info from unix command "mpstat 2 100".

    This Prod server had OS hardening done to it before.
    However, I could not determine if that is the root cause as there was not performance test run performed before and after hardening.

    Since the explain plan and stats are the same on both Prod and Dev DBs, I would assume we can rule out the Oracle optimizer and bad SQL on this 2 systems. The query uses a costly UNION. Even though it is recommended to use UNION ALL instead of UNION in the query, it did not improve the response time on Prod DB.

    Appreciate any advise as to how to narrow down the root cause of my performance issue.

    Cheers
    Orac
    Last edited by oracbase; 05-22-2009 at 07:53 AM.
    What's next after 10g?

  4. #4
    Join Date
    Mar 2007
    Location
    Ft. Lauderdale, FL
    Posts
    3,554
    Trace the query in both environments, compare wait events.
    Pablo (Paul) Berzukov

    Author of Understanding Database Administration available at amazon and other bookstores.

    Disclaimer: Advice is provided to the best of my knowledge but no implicit or explicit warranties are provided. Since the advisor explicitly encourages testing any and all suggestions on a test non-production environment advisor should not held liable or responsible for any actions taken based on the given advice.

  5. #5
    Join Date
    Apr 2001
    Posts
    110
    Tracing was already done with event 10046.
    On the Dev DB, the only wait events were "db file sequential read & db file scattered read" + the usual "SQL*Net message".
    On Prod DB, there wasn't any wait besides the usual "SQL*Net message".
    What's next after 10g?

  6. #6
    Join Date
    Nov 2002
    Location
    Mooresville, NC
    Posts
    349
    Can u answer below questions
    1. In prod is your file system in SAN and Dev file system is local?
    2. What abt data, are they same in prod and dev?
    http://www.perf-engg.com
    A performance engineering forum

  7. #7
    Join Date
    Mar 2007
    Location
    Ft. Lauderdale, FL
    Posts
    3,554
    Quote Originally Posted by oracbase View Post
    On the Dev DB, the only wait events were "db file sequential read & db file scattered read" + the usual "SQL*Net message".
    On Prod DB, there wasn't any wait besides the usual "SQL*Net message".
    Check again prod trace, no read wait events means query didn't even attempted to read.

    Please post tkprof of relevant section of both dev and prod traces.
    Pablo (Paul) Berzukov

    Author of Understanding Database Administration available at amazon and other bookstores.

    Disclaimer: Advice is provided to the best of my knowledge but no implicit or explicit warranties are provided. Since the advisor explicitly encourages testing any and all suggestions on a test non-production environment advisor should not held liable or responsible for any actions taken based on the given advice.

  8. #8
    Join Date
    Apr 2001
    Posts
    110
    Hi,

    Prod DB is using SUN storage and UFS filesystem with kaio. (i think this is not recommended disk config for Sun/Oracle right?)

    Dev DB is just a local disk on notebook.

    Data is the same on Prod and Dev DB. I imported them from the same source.
    From the source DB, the query only takes 2.5mins having same explain plan.
    Although the source DB is also SUN box(less powerful in terms of CPU and memory) and UFS filesystem, but I hear from my sysadmin that it is using Veritas Volume Manager to manage the source storage.

    I have been running the AWR report a few times with the same query execution.
    I noticed that there is significant "control file parallel write".
    When the query is running, iostat also shows that the disk where controlfiles and redo logfiles reside is having more I/O than the other disks with datafiles.

    I am suspecting it this performance issue is due to Sun async I/O on the filesystem.

    Can someone confirm that my suspicion is correct?

    Cheers
    Orac
    What's next after 10g?

  9. #9
    Join Date
    Apr 2001
    Posts
    110
    Here is the trace 10046 output for Prod DB.

    select /* 10046_prod */ am.airline_name,fsp.schedule_no,fsp.fs_serial_number,min(ofs.effective_period_from) Effective_period,fsp.created_date,
    (fsp.created_date+5) Date_To_Clear,pl.serial_number_document,ud.user_name,fsp.OPERATING_OR_MARKETING,fsp.airline_id
    from Airline_master am, flight_schedule_procesing fsp,action_table at,
    operating_flight_schedule ofs,permit_license pl,user_details ud where ofs.schedule_no = pl.schedule_no and
    fsp.schedule_no=pl.schedule_no and am.airline_id = fsp.airline_id and ud.user_id = pl.atman_userid
    and pl.ddgo='1' AND fsp.SEASON_CODE='NS0909' and pl.permit_or_license='L'
    group by am.airline_name,fsp.schedule_no,fsp.fs_serial_number,fsp.created_date,pl.serial_number_document,
    ud.user_name ,fsp.OPERATING_OR_MARKETING,fsp.airline_id
    UNION select am.airline_name,fsp.schedule_no,fsp.fs_serial_number,min(ofs.effective_period_from) Effective_period,
    fsp.created_date,(fsp.created_date+5) Date_To_Clear,pl.serial_number_document,ud.user_name ,
    fsp.OPERATING_OR_MARKETING,fsp.airline_id from Airline_master am, flight_schedule_procesing fsp,action_table at,
    MARKETING_FLIGHT_SCHEDULE ofs,permit_license pl,user_details ud
    where ofs.schedule_no = pl.schedule_no and fsp.schedule_no=pl.schedule_no
    and am.airline_id = fsp.airline_id and ud.user_id = pl.atman_userid and pl.ddgo='1'
    AND fsp.SEASON_CODE='NS0909' and pl.permit_or_license= 'L'
    group by am.airline_name,fsp.schedule_no,fsp.fs_serial_number,fsp.created_date,
    pl.serial_number_document,ud.user_name ,fsp.OPERATING_OR_MARKETING,fsp.airline_id
    order by Date_To_Clear desc,Effective_Period desc
    END OF STMT
    PARSE #2:c=0,e=545,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3592666218283
    EXEC #2:c=0,e=416,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=3592666219654
    WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3592666219788
    *** 2009-05-22 10:16:20.345
    FETCH #2:c=418000000,e=408203242,p=0,cr=2007,cu=0,mis=0,r=1,dep=0,og=1,tim=3593074423177
    WAIT #2: nam='SQL*Net message from client' ela= 1333 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3593074427198
    WAIT #2: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3593074427365
    FETCH #2:c=0,e=249,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=3593074427577
    WAIT #2: nam='SQL*Net message from client' ela= 9444 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3593074437142
    WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3593074437268
    FETCH #2:c=0,e=129,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=1,tim=3593074437374
    WAIT #2: nam='SQL*Net message from client' ela= 2446 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3593074440331
    STAT #2 id=1 cnt=18 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=2007 pr=0 pw=0 time=408203515 us)'
    STAT #2 id=2 cnt=18 pid=1 pos=1 obj=0 op='UNION-ALL (cr=2007 pr=0 pw=0 time=408203229 us)'
    STAT #2 id=3 cnt=16 pid=2 pos=1 obj=0 op='HASH GROUP BY (cr=1501 pr=0 pw=0 time=401507299 us)'
    STAT #2 id=4 cnt=40910398 pid=3 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=1501 pr=0 pw=0 time=41230056 us)'
    STAT #2 id=5 cnt=799 pid=4 pos=1 obj=0 op='HASH JOIN (cr=1388 pr=0 pw=0 time=279026 us)'
    STAT #2 id=6 cnt=18 pid=5 pos=1 obj=0 op='NESTED LOOPS (cr=317 pr=0 pw=0 time=24642 us)'
    STAT #2 id=7 cnt=18 pid=6 pos=1 obj=0 op='HASH JOIN (cr=297 pr=0 pw=0 time=24105 us)'
    STAT #2 id=8 cnt=18 pid=7 pos=1 obj=0 op='HASH JOIN (cr=281 pr=0 pw=0 time=20113 us)'
    STAT #2 id=9 cnt=349 pid=8 pos=1 obj=53959 op='TABLE ACCESS FULL FLIGHT_SCHEDULE_PROCESING (cr=189 pr=0 pw=0 time=11490 us)'
    STAT #2 id=10 cnt=362 pid=8 pos=2 obj=53995 op='TABLE ACCESS FULL PERMIT_LICENSE (cr=92 pr=0 pw=0 time=3385 us)'
    STAT #2 id=11 cnt=520 pid=7 pos=2 obj=54012 op='TABLE ACCESS FULL USER_DETAILS (cr=16 pr=0 pw=0 time=617 us)'
    STAT #2 id=12 cnt=18 pid=6 pos=2 obj=53934 op='TABLE ACCESS BY INDEX ROWID AIRLINE_MASTER (cr=20 pr=0 pw=0 time=485 us)'
    STAT #2 id=13 cnt=18 pid=12 pos=1 obj=53935 op='INDEX UNIQUE SCAN SYS_C006428 (cr=2 pr=0 pw=0 time=202 us)'
    STAT #2 id=14 cnt=91120 pid=5 pos=2 obj=53982 op='TABLE ACCESS FULL OPERATING_FLIGHT_SCHEDULE (cr=1071 pr=0 pw=0 time=92685 us)'
    STAT #2 id=15 cnt=40910398 pid=4 pos=2 obj=0 op='BUFFER SORT (cr=113 pr=0 pw=0 time=41018101 us)'
    STAT #2 id=16 cnt=51202 pid=15 pos=1 obj=53929 op='INDEX FAST FULL SCAN ACTION_ID_FK (cr=113 pr=0 pw=0 time=126 us)'
    STAT #2 id=17 cnt=2 pid=2 pos=2 obj=0 op='HASH GROUP BY (cr=506 pr=0 pw=0 time=6695159 us)'
    STAT #2 id=18 cnt=716828 pid=17 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=506 pr=0 pw=0 time=846405 us)'
    STAT #2 id=19 cnt=14 pid=18 pos=1 obj=0 op='HASH JOIN (cr=393 pr=0 pw=0 time=39909 us)'
    STAT #2 id=20 cnt=18 pid=19 pos=1 obj=0 op='NESTED LOOPS (cr=317 pr=0 pw=0 time=19998 us)'
    STAT #2 id=21 cnt=18 pid=20 pos=1 obj=0 op='HASH JOIN (cr=297 pr=0 pw=0 time=19481 us)'
    STAT #2 id=22 cnt=18 pid=21 pos=1 obj=0 op='HASH JOIN (cr=281 pr=0 pw=0 time=17258 us)'
    STAT #2 id=23 cnt=349 pid=22 pos=1 obj=53959 op='TABLE ACCESS FULL FLIGHT_SCHEDULE_PROCESING (cr=189 pr=0 pw=0 time=11286 us)'
    STAT #2 id=24 cnt=362 pid=22 pos=2 obj=53995 op='TABLE ACCESS FULL PERMIT_LICENSE (cr=92 pr=0 pw=0 time=3386 us)'
    STAT #2 id=25 cnt=520 pid=21 pos=2 obj=54012 op='TABLE ACCESS FULL USER_DETAILS (cr=16 pr=0 pw=0 time=623 us)'
    STAT #2 id=26 cnt=18 pid=20 pos=2 obj=53934 op='TABLE ACCESS BY INDEX ROWID AIRLINE_MASTER (cr=20 pr=0 pw=0 time=480 us)'
    STAT #2 id=27 cnt=18 pid=26 pos=1 obj=53935 op='INDEX UNIQUE SCAN SYS_C006428 (cr=2 pr=0 pw=0 time=201 us)'
    STAT #2 id=28 cnt=8297 pid=19 pos=2 obj=53975 op='TABLE ACCESS FULL MARKETING_FLIGHT_SCHEDULE (cr=76 pr=0 pw=0 time=8408 us)'
    STAT #2 id=29 cnt=716828 pid=18 pos=2 obj=0 op='BUFFER SORT (cr=113 pr=0 pw=0 time=808224 us)'
    STAT #2 id=30 cnt=51202 pid=29 pos=1 obj=53929 op='INDEX FAST FULL SCAN ACTION_ID_FK (cr=113 pr=0 pw=0 time=108 us)'
    WAIT #0: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3593074442812
    *** 2009-05-22 10:17:57.462
    WAIT #0: nam='SQL*Net message from client' ela= 94818409 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=3593169261305
    XCTEND rlbk=0, rd_only=1
    What's next after 10g?

  10. #10
    Join Date
    Apr 2001
    Posts
    110
    Here is the trace 10046 output for Dev DB.

    PARSING IN CURSOR #2 len=1585 dep=0 uid=60 oct=3 lid=60 tim=4844269580 hv=4130183277 ad='18e267a8'
    select /* 10046_dev */ am.airline_name,fsp.schedule_no,fsp.fs_serial_number,min(ofs.effective_period_from) Effective_period,fsp.created_date,
    (fsp.created_date+5) Date_To_Clear,pl.serial_number_document,ud.user_name,fsp.OPERATING_OR_MARKETING,fsp.airline_id
    from Airline_master am, flight_schedule_procesing fsp,action_table at,
    operating_flight_schedule ofs,permit_license pl,user_details ud where ofs.schedule_no = pl.schedule_no and
    fsp.schedule_no=pl.schedule_no and am.airline_id = fsp.airline_id and ud.user_id = pl.atman_userid
    and pl.ddgo='1' AND fsp.SEASON_CODE='NS0909' and pl.permit_or_license='L'
    group by am.airline_name,fsp.schedule_no,fsp.fs_serial_number,fsp.created_date,pl.serial_number_document,
    ud.user_name ,fsp.OPERATING_OR_MARKETING,fsp.airline_id
    UNION select am.airline_name,fsp.schedule_no,fsp.fs_serial_number,min(ofs.effective_period_from) Effective_period,
    fsp.created_date,(fsp.created_date+5) Date_To_Clear,pl.serial_number_document,ud.user_name ,
    fsp.OPERATING_OR_MARKETING,fsp.airline_id from Airline_master am, flight_schedule_procesing fsp,action_table at,
    MARKETING_FLIGHT_SCHEDULE ofs,permit_license pl,user_details ud
    where ofs.schedule_no = pl.schedule_no and fsp.schedule_no=pl.schedule_no
    and am.airline_id = fsp.airline_id and ud.user_id = pl.atman_userid and pl.ddgo='1'
    AND fsp.SEASON_CODE='NS0909' and pl.permit_or_license= 'L'
    group by am.airline_name,fsp.schedule_no,fsp.fs_serial_number,fsp.created_date,
    pl.serial_number_document,ud.user_name ,fsp.OPERATING_OR_MARKETING,fsp.airline_id
    order by Date_To_Clear desc,Effective_Period desc
    END OF STMT
    PARSE #2:c=843750,e=1233677,p=49,cr=1319,cu=0,mis=1,r=0,dep=0,og=1,tim=4844269569
    EXEC #2:c=0,e=354,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=4844270322
    WAIT #2: nam='SQL*Net message to client' ela= 8 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=4844270407
    WAIT #2: nam='db file sequential read' ela= 19146 file#=4 block#=12044 blocks=1 obj#=51959 tim=4844291907
    WAIT #2: nam='db file scattered read' ela= 3427 file#=4 block#=12045 blocks=16 obj#=51959 tim=4844295590
    WAIT #2: nam='db file scattered read' ela= 2932 file#=4 block#=12061 blocks=16 obj#=51959 tim=4844298999
    ....................
    .....................
    (lots of similar WAIT for 'db file scattered read' lines)
    ....................
    ....................
    WAIT #2: nam='db file scattered read' ela= 861 file#=4 block#=785 blocks=8 obj#=51929 tim=4848209699
    WAIT #2: nam='db file scattered read' ela= 832 file#=4 block#=794 blocks=7 obj#=51929 tim=4848269278
    WAIT #2: nam='db file scattered read' ela= 1096 file#=4 block#=801 blocks=8 obj#=51929 tim=4848321229
    WAIT #2: nam='db file scattered read' ela= 588 file#=4 block#=810 blocks=4 obj#=51929 tim=4848380713
    *** 2009-05-22 10:10:42.237
    WAIT #2: nam='db file scattered read' ela= 26178 file#=4 block#=13915 blocks=16 obj#=51982 tim=5305514047
    *** 2009-05-22 10:13:21.920
    WAIT #2: nam='db file scattered read' ela= 25565 file#=4 block#=13931 blocks=16 obj#=51982 tim=5465586645
    *** 2009-05-22 10:14:09.928
    WAIT #2: nam='db file scattered read' ela= 24855 file#=4 block#=13947 blocks=14 obj#=51982 tim=5513657089
    *** 2009-05-22 10:17:29.012
    WAIT #2: nam='db file scattered read' ela= 15669 file#=4 block#=13963 blocks=16 obj#=51982 tim=5712986353
    *** 2009-05-22 10:18:37.422
    WAIT #2: nam='db file scattered read' ela= 23656 file#=4 block#=13979 blocks=16 obj#=51982 tim=5781468584
    *** 2009-05-22 10:20:23.414
    WAIT #2: nam='db file scattered read' ela= 40395 file#=4 block#=13995 blocks=16 obj#=51982 tim=5887508279
    *** 2009-05-22 10:22:40.931
    WAIT #2: nam='db file scattered read' ela= 41340 file#=4 block#=14011 blocks=14 obj#=51982 tim=6025035684
    *** 2009-05-22 10:24:02.698
    WAIT #2: nam='db file sequential read' ela= 21001 file#=4 block#=12619 blocks=1 obj#=51975 tim=6106848462
    WAIT #2: nam='db file scattered read' ela= 792 file#=4 block#=12620 blocks=5 obj#=51975 tim=6106849532
    WAIT #2: nam='db file scattered read' ela= 784 file#=4 block#=12625 blocks=8 obj#=51975 tim=6106869092
    WAIT #2: nam='db file scattered read' ela= 1030 file#=4 block#=12634 blocks=7 obj#=51975 tim=6106900005
    WAIT #2: nam='db file scattered read' ela= 782 file#=4 block#=12641 blocks=8 obj#=51975 tim=6106926075
    WAIT #2: nam='db file scattered read' ela= 726 file#=4 block#=12650 blocks=7 obj#=51975 tim=6106955718
    WAIT #2: nam='db file scattered read' ela= 796 file#=4 block#=12657 blocks=8 obj#=51975 tim=6106982712
    WAIT #2: nam='db file scattered read' ela= 715 file#=4 block#=12666 blocks=7 obj#=51975 tim=6107011906
    WAIT #2: nam='db file scattered read' ela= 783 file#=4 block#=12673 blocks=8 obj#=51975 tim=6107037802
    WAIT #2: nam='db file scattered read' ela= 941 file#=4 block#=12682 blocks=7 obj#=51975 tim=6107067545
    *** 2009-05-22 10:24:26.841
    WAIT #2: nam='db file scattered read' ela= 31789 file#=4 block#=12689 blocks=8 obj#=51975 tim=6131010935
    FETCH #2:c=1274828125,e=1286758667,p=1547,cr=2007,cu=0,mis=0,r=1,dep=0,og=1,tim=6131029148
    WAIT #2: nam='SQL*Net message from client' ela= 34676 driver id=1413697536 #bytes=1 p3=0 obj#=51975 tim=6131064072
    WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=51975 tim=6131064203
    FETCH #2:c=0,e=368,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,tim=6131064529
    WAIT #2: nam='SQL*Net message from client' ela= 330776 driver id=1413697536 #bytes=1 p3=0 obj#=51975 tim=6131395398
    WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1413697536 #bytes=1 p3=0 obj#=51975 tim=6131395574
    FETCH #2:c=0,e=150,p=0,cr=0,cu=0,mis=0,r=2,dep=0,og=1,tim=6131395670
    WAIT #2: nam='SQL*Net message from client' ela= 60068 driver id=1413697536 #bytes=1 p3=0 obj#=51975 tim=6131456111
    STAT #2 id=1 cnt=18 pid=0 pos=1 obj=0 op='SORT UNIQUE (cr=2007 pr=1547 pw=0 time=1286759124 us)'
    STAT #2 id=2 cnt=18 pid=1 pos=1 obj=0 op='UNION-ALL (cr=2007 pr=1547 pw=0 time=1286758687 us)'
    STAT #2 id=3 cnt=16 pid=2 pos=1 obj=0 op='HASH GROUP BY (cr=1501 pr=1473 pw=0 time=1262504407 us)'
    STAT #2 id=4 cnt=40910398 pid=3 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=1501 pr=1473 pw=0 time=945084723 us)'
    STAT #2 id=5 cnt=799 pid=4 pos=1 obj=0 op='HASH JOIN (cr=1388 pr=1365 pw=0 time=3818244 us)'
    STAT #2 id=6 cnt=18 pid=5 pos=1 obj=0 op='NESTED LOOPS (cr=317 pr=296 pw=0 time=162166 us)'
    STAT #2 id=7 cnt=18 pid=6 pos=1 obj=0 op='HASH JOIN (cr=297 pr=290 pw=0 time=140385 us)'
    STAT #2 id=8 cnt=18 pid=7 pos=1 obj=0 op='HASH JOIN (cr=281 pr=276 pw=0 time=101273 us)'
    STAT #2 id=9 cnt=349 pid=8 pos=1 obj=51959 op='TABLE ACCESS FULL FLIGHT_SCHEDULE_PROCESING (cr=189 pr=187 pw=0 time=59551 us)'
    STAT #2 id=10 cnt=362 pid=8 pos=2 obj=51995 op='TABLE ACCESS FULL PERMIT_LICENSE (cr=92 pr=89 pw=0 time=23938 us)'
    STAT #2 id=11 cnt=520 pid=7 pos=2 obj=52012 op='TABLE ACCESS FULL USER_DETAILS (cr=16 pr=14 pw=0 time=25311 us)'
    STAT #2 id=12 cnt=18 pid=6 pos=2 obj=51934 op='TABLE ACCESS BY INDEX ROWID AIRLINE_MASTER (cr=20 pr=6 pw=0 time=21200 us)'
    STAT #2 id=13 cnt=18 pid=12 pos=1 obj=51935 op='INDEX UNIQUE SCAN SYS_C005605 (cr=2 pr=1 pw=0 time=18785 us)'
    STAT #2 id=14 cnt=91120 pid=5 pos=2 obj=51982 op='TABLE ACCESS FULL OPERATING_FLIGHT_SCHEDULE (cr=1071 pr=1069 pw=0 time=1756633 us)'
    STAT #2 id=15 cnt=40910398 pid=4 pos=2 obj=0 op='BUFFER SORT (cr=113 pr=108 pw=0 time=369042788 us)'
    STAT #2 id=16 cnt=51202 pid=15 pos=1 obj=51929 op='INDEX FAST FULL SCAN ACTION_ID_FK (cr=113 pr=108 pw=0 time=531161 us)'
    STAT #2 id=17 cnt=2 pid=2 pos=2 obj=0 op='HASH GROUP BY (cr=506 pr=74 pw=0 time=24251876 us)'
    STAT #2 id=18 cnt=716828 pid=17 pos=1 obj=0 op='MERGE JOIN CARTESIAN (cr=506 pr=74 pw=0 time=19063303 us)'
    STAT #2 id=19 cnt=14 pid=18 pos=1 obj=0 op='HASH JOIN (cr=393 pr=74 pw=0 time=365136 us)'
    STAT #2 id=20 cnt=18 pid=19 pos=1 obj=0 op='NESTED LOOPS (cr=317 pr=0 pw=0 time=49047 us)'
    STAT #2 id=21 cnt=18 pid=20 pos=1 obj=0 op='HASH JOIN (cr=297 pr=0 pw=0 time=46978 us)'
    STAT #2 id=22 cnt=18 pid=21 pos=1 obj=0 op='HASH JOIN (cr=281 pr=0 pw=0 time=28911 us)'
    STAT #2 id=23 cnt=349 pid=22 pos=1 obj=51959 op='TABLE ACCESS FULL FLIGHT_SCHEDULE_PROCESING (cr=189 pr=0 pw=0 time=6541 us)'
    STAT #2 id=24 cnt=362 pid=22 pos=2 obj=51995 op='TABLE ACCESS FULL PERMIT_LICENSE (cr=92 pr=0 pw=0 time=4419 us)'
    STAT #2 id=25 cnt=520 pid=21 pos=2 obj=52012 op='TABLE ACCESS FULL USER_DETAILS (cr=16 pr=0 pw=0 time=5327 us)'
    STAT #2 id=26 cnt=18 pid=20 pos=2 obj=51934 op='TABLE ACCESS BY INDEX ROWID AIRLINE_MASTER (cr=20 pr=0 pw=0 time=1465 us)'
    STAT #2 id=27 cnt=18 pid=26 pos=1 obj=51935 op='INDEX UNIQUE SCAN SYS_C005605 (cr=2 pr=0 pw=0 time=570 us)'
    STAT #2 id=28 cnt=8297 pid=19 pos=2 obj=51975 op='TABLE ACCESS FULL MARKETING_FLIGHT_SCHEDULE (cr=76 pr=74 pw=0 time=138494 us)'
    STAT #2 id=29 cnt=716828 pid=18 pos=2 obj=0 op='BUFFER SORT (cr=113 pr=0 pw=0 time=7234330 us)'
    STAT #2 id=30 cnt=51202 pid=29 pos=1 obj=51929 op='INDEX FAST FULL SCAN ACTION_ID_FK (cr=113 pr=0 pw=0 time=460892 us)'
    WAIT #0: nam='SQL*Net message to client' ela= 6 driver id=1413697536 #bytes=1 p3=0 obj#=51975 tim=6131457258
    *** 2009-05-22 10:30:36.465
    WAIT #0: nam='SQL*Net message from client' ela= 369383560 driver id=1413697536 #bytes=1 p3=0 obj#=51975 tim=6500840876
    XCTEND rlbk=0, rd_only=1
    What's next after 10g?

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •  



Click Here to Expand Forum to Full Width