This discussion is archived
1 2 Previous Next 20 Replies Latest reply: Jan 18, 2013 11:01 AM by jgarry RSS

What is my query doing??

967473 Newbie
Currently Being Moderated
Oracle Database 11g Release 11.2.0.1.0 - 64bit Production

CentOS kernel 2.6.18-274.17.1.el5

System:
4 Quad core CPU's, 144GB RAM, 15k RPM SAS Disks

Config:
AMM is used, SETALL for filesystemio_options, database is running in NOARCHIVELOG mode, sga_max_size is 70GB, sga_target is 41GB.

Here is my problem:
I have 200 million records in table A. I create an empty table (table B) using the NOLOGGING option. I aggregate the data from table A by a primary key to populate table B
(truncate table B; insert into table B select MIN/MAX <columns> from table A group by primary_key;) There are also a couple of left outer joins in this query.

I 'watch' the progress (table scans/joins) in the v$session_longops table.

I get to the point where all table scans and hash joins are finshed, but my query still shows in the v$session_longops table, even though it is not doing anything (that I can see).

I understand this is a bit vague, but I am really struggling with this one. The query would usually run in 90 minutes and be done. Now it runs the normal 90 minutes and sits idle another 90 minutes before finishing.

Can anyone shed some light as at least where to look in my database?

Thank you.
  • 1. Re: What is my query doing??
    sb92075 Guru
    Currently Being Moderated
    964470 wrote:

    Can anyone shed some light as at least where to look in my database?
    ALTER SESSION SET SQL_TRACE=TRUE;


    the resultant trace file will reveal where time is being spent.
  • 2. Re: What is my query doing??
    jgarry Guru
    Currently Being Moderated
    You can set tracing on in another session with oradebug. For example, find the sid in the other session, say it is 165:
    oradebug setorapid 165
    
    oradebug event 10046 trace name context forever, level 12;
    and to turn it off use:
    oradebug setorapid 165
    
    oradebug event 10046 trace name context off;
    For whatever tracing is appropriate.

    Edit: Twice as long, huh? Are you sure you didn't put a rollback in there?

    Edited by: jgarry on Jan 17, 2013 11:18 AM
  • 3. Re: What is my query doing??
    967473 Newbie
    Currently Being Moderated
    Thank you sb.

    This is a test DB (that will eventaully go into production). Is there anything wrong with setting the SQL_TRACE parameter using alter system instead of session? Do you know where the log file would be placed on the system?
  • 4. Re: What is my query doing??
    967473 Newbie
    Currently Being Moderated
    I will certainly test this. Thank you.

    I did nothing with rollback.
  • 5. Re: What is my query doing??
    sb92075 Guru
    Currently Being Moderated
    964470 wrote:
    Thank you sb.

    This is a test DB (that will eventaully go into production). Is there anything wrong with setting the SQL_TRACE parameter using alter system instead of session?
    doing so at the system level traces EVERY session in the DB.
    The only challenge then is finding which file contains what you desire.
    Do you know where the log file would be placed on the system?
    /adump DIRECTORY
  • 6. Re: What is my query doing??
    967473 Newbie
    Currently Being Moderated
    I am trying to use these commands for SID 100, and receive the following:

    SQL> oradebug setorapid 100
    ORA-00072: process "Unix process pid: 0, image: <none>" is not active

    Edited by: 964470 on Jan 17, 2013 11:48 AM
  • 7. Re: What is my query doing??
    sb92075 Guru
    Currently Being Moderated
    964470 wrote:
    I am trying to use these commands for SID 100, and receive the following:

    SQL> oradebug setorapid 100
    ORA-00072: process "Unix process pid: 0, image: <none>" is not active

    Edited by: 964470 on Jan 17, 2013 11:48 AM
    DBMS_MONITOR.SESSION_TRACE_ENABLE(
        session_id   IN  BINARY_INTEGER DEFAULT NULL,
        serial_num   IN  BINARY_INTEGER DEFAULT NULL,
        waits        IN  BOOLEAN DEFAULT TRUE,
        binds        IN  BOOLEAN DEFAULT FALSE,
        plan_stat    IN  VARCHAR2 DEFAULT NULL);
  • 8. Re: What is my query doing??
    967473 Newbie
    Currently Being Moderated
    Again, thanks a lot guys. I see in my alert.log:

    Thread 1 cannot allocate new log, sequence 33254
    Checkpoint not complete

    After I bounced the instance, I see:
    ORA-19815: WARNING: db_recovery_file_dest_size of 4194304000 bytes is 99.43% used, and has 23871488 remaining bytes available.

    I am not using RMAN or any other backup utility.
  • 9. Re: What is my query doing??
    Niket Kumar Pro
    Currently Being Moderated
    check your location from

    show parameter db_recovery_file_dest

    check on path what is actually utilizing your space....

    or increase the size of db recovery file dest

    Edited by: Niket Kumar on Jan 18, 2013 1:48 AM
  • 10. Re: What is my query doing??
    967473 Newbie
    Currently Being Moderated
    OK, from my trace file, there is a lot of information I don't quite understand. I see my SQL statement once, then a bunch of:

    PARSING IN CURSOR #3 len=36 dep=1 uid=0 oct=3 lid=0 tim=1358453881350242 hv=1570213724 ad='111fb74578' sqlid='bsa0wjtftg3uw'
    select file# from file$ where ts#=:1
    END OF STMT
    PARSE #3:c=0,e=19,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2020579421,tim=1358453881350241
    EXEC #3:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2020579421,tim=1358453881350384
    FETCH #3:c=0,e=25,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350427
    FETCH #3:c=0,e=6,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350449
    FETCH #3:c=0,e=6,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350467
    FETCH #3:c=0,e=5,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350483
    FETCH #3:c=0,e=5,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350499
    FETCH #3:c=0,e=4,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350514
    FETCH #3:c=0,e=5,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350530
    FETCH #3:c=0,e=4,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350545
    FETCH #3:c=0,e=4,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350561
    FETCH #3:c=0,e=4,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=2020579421,tim=1358453881350576
    FETCH #3:c=0,e=2,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=2020579421,tim=1358453881350590
    CLOSE #3:c=0,e=4,dep=1,type=3,tim=1358453881350617

    For what seems to be 6 cursors. Any thoughts?
  • 11. Re: What is my query doing??
    jgarry Guru
    Currently Being Moderated
    964470 wrote:
    Again, thanks a lot guys. I see in my alert.log:

    Thread 1 cannot allocate new log, sequence 33254
    Checkpoint not complete

    After I bounced the instance, I see:
    ORA-19815: WARNING: db_recovery_file_dest_size of 4194304000 bytes is 99.43% used, and has 23871488 remaining bytes available.

    I am not using RMAN or any other backup utility.
    The recovery file dest is a setting for when you want Oracle to handle some functions for you. If it is being filled up with archived logs, you should use rman to backup so the unneeded logs get deleted. This depends on various settings. Since you are running noarchivelog mode, that is probably not what is happening, so I wonder what else is going on there, maybe you were once archivelog and then changed without cleaning up. You might want to run rman crosscheck and delete obsolete commands in case there are old things there, so Oracle can match what it thinks with reality. Look at the directories nearby (like udump and cdump), perhaps you may be getting some other trace files that need to be cleaned up. Also check for adcri filling up stuff. http://gavinsoorma.com/2010/09/purging-trace-and-dump-files-with-11g-adrci/

    Whether the cannot allocate and not complete errors are meaningful depends on what surrounds them. In some cases, it can just be a minor performance annoyance. In others, your db stops (though that would normally be in archivelog mode). Post the 100 lines around the error so we can tell.

    Watch your disk space when tracing.

    See this for trace analyser: http://awads.net/wp/2006/07/18/oracle-trace-analyzer-is-tkprof-on-steroids/
  • 12. Re: What is my query doing??
    967473 Newbie
    Currently Being Moderated
    I've done some tracing on a questionable query. I've found the following errors after using tkprof to examine the trace file:

    error during execute of EXPLAIN PLAN statement
    ORA-00904: "SDO_GEOR_DEF"."GETSQLTEXT": invalid identifier

    error during execute of EXPLAIN PLAN statement
    ORA-00942: table or view does not exist

    error during execute of EXPLAIN PLAN statement
    ORA-00907: missing right parenthesis

    Does it seem odd that I would be getting explain plan errors while running an insert?
  • 13. Re: What is my query doing??
    967473 Newbie
    Currently Being Moderated
    From alert.log after I bounced the instance:

    Thu Jan 17 11:12:28 2013
    ALTER DATABASE OPEN
    Thread 1 opened at log sequence 33271
    Current log# 1 seq# 33271 mem# 0: /usr/local/oracle/oradata/ORA7/redo01.log
    Successful open of redo thread 1
    SMON: enabling cache recovery
    Successfully onlined Undo Tablespace 2.
    Verifying file header compatibility for 11g tablespace encryption..
    Verifying 11g file header compatibility for tablespace encryption completed
    SMON: enabling tx recovery
    Database Characterset is WE8MSWIN1252
    No Resource Manager plan active
    replication_dependency_tracking turned off (no async multimaster replication found)
    Starting background process QMNC
    Thu Jan 17 11:12:31 2013
    QMNC started with pid=21, OS id=5893
    Completed: ALTER DATABASE OPEN
    Thu Jan 17 11:12:33 2013
    Starting background process CJQ0
    Thu Jan 17 11:12:33 2013
    CJQ0 started with pid=27, OS id=5927
    Thu Jan 17 11:12:33 2013
    Errors in file /usr/local/oracle/diag/rdbms/ora7/ORA7/trace/ORA7_m000_5898.trc:
    ORA-19815: WARNING: db_recovery_file_dest_size of 4194304000 bytes is 99.43% used, and has 23871488 remaining bytes available.
    ************************************************************************
    You have following choices to free up space from recovery area:
    1. Consider changing RMAN RETENTION POLICY. If you are using Data Guard,
    then consider changing RMAN ARCHIVELOG DELETION POLICY.
    2. Back up files to tertiary device such as tape using RMAN
    BACKUP RECOVERY AREA command.
    3. Add disk space and increase db_recovery_file_dest_size parameter to
    reflect the new space.
    4. Delete unnecessary files using RMAN DELETE command. If an operating
    system command was used to delete files, then use RMAN CROSSCHECK and
    DELETE EXPIRED commands.
    ************************************************************************
    Thu Jan 17 11:18:16 2013
    Starting background process SMCO
    Thu Jan 17 11:18:16 2013
    SMCO started with pid=39, OS id=6978
    Thu Jan 17 12:57:29 2013
    Thu Jan 17 12:57:29 2013
    Thread 1 advanced to log sequence 33272 (LGWR switch)
    Current log# 2 seq# 33272 mem# 0: /usr/local/oracle/oradata/ORA7/redo02.log
    Thread 1 advanced to log sequence 33273 (LGWR switch)
    Current log# 3 seq# 33273 mem# 0: /usr/local/oracle/oradata/ORA7/redo03.log
    Thread 1 cannot allocate new log, sequence 33274
    Checkpoint not complete
    Current log# 3 seq# 33273 mem# 0: /usr/local/oracle/oradata/ORA7/redo03.log
    Thread 1 advanced to log sequence 33274 (LGWR switch)
    Current log# 1 seq# 33274 mem# 0: /usr/local/oracle/oradata/ORA7/redo01.log
    Thread 1 cannot allocate new log, sequence 33275
    Checkpoint not complete
    Current log# 1 seq# 33274 mem# 0: /usr/local/oracle/oradata/ORA7/redo01.log
    Thread 1 advanced to log sequence 33275 (LGWR switch)
    Current log# 2 seq# 33275 mem# 0: /usr/local/oracle/oradata/ORA7/redo02.log
    Thu Jan 17 12:57:41 2013
    Thread 1 cannot allocate new log, sequence 33276
    Checkpoint not complete
    Current log# 2 seq# 33275 mem# 0: /usr/local/oracle/oradata/ORA7/redo02.log
    Thread 1 advanced to log sequence 33276 (LGWR switch)
    Current log# 3 seq# 33276 mem# 0: /usr/local/oracle/oradata/ORA7/redo03.log
    Thread 1 cannot allocate new log, sequence 33277
    Checkpoint not complete
    Current log# 3 seq# 33276 mem# 0: /usr/local/oracle/oradata/ORA7/redo03.log
    Thread 1 advanced to log sequence 33277 (LGWR switch)
    Current log# 1 seq# 33277 mem# 0: /usr/local/oracle/oradata/ORA7/redo01.log
    Thread 1 cannot allocate new log, sequence 33278
    Checkpoint not complete
    Current log# 1 seq# 33277 mem# 0: /usr/local/oracle/oradata/ORA7/redo01.log
    Thread 1 advanced to log sequence 33278 (LGWR switch)
    Current log# 2 seq# 33278 mem# 0: /usr/local/oracle/oradata/ORA7/redo02.log
    Thread 1 cannot allocate new log, sequence 33279
    Checkpoint not complete

    Trace files were not filling it up too much. The db was running in archivelogmode at one point. I cleaned up old trace files and rman backups.

    Will setting the db_recovery_file_dest_size to something larger than 4000M help?
  • 14. Re: What is my query doing??
    Hemant K Chitale Oracle ACE
    Currently Being Moderated
    If your database is in NOARCHIVELOG mode, (quoting your first post "database is running in NOARCHIVELOG mode") the db_recovery_file_dest wouldn't have new archivelogs being written to it. I guess you have only Consistent (aka "cold") backups written to this location. Do you happen to have other files also written here ? Query V$RECOVERY_AREA_USAGE.
    I create an empty table (table B) using the NOLOGGING option
    truncate table B; insert into table B select
    You could convert that to a Direct Path INSERT with an APPEND Hint in the INSERT statement.
    my query still shows in the v$session_longops table
    If SOFAR = TOTALWORK, there is no longop in progress at that time.
    even though it is not doing anything (that I can see).
    Tracing the session would show what it is doing.
    Now it runs the normal 90 minutes and sits idle another 90 minutes before finishing.
    How do you verify that it is idle ? (only on the basis of querying v$session_longops ?). When is the COMMIT issued ?


    Hemant K Chitale
1 2 Previous Next

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points