Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Mailing Lists -> Oracle-L -> Re: Process consuming a lot of CPU, UTL_FILE and WAIT EVENTS relationship

Re: Process consuming a lot of CPU, UTL_FILE and WAIT EVENTS relationship

From: Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk>
Date: Thu, 24 Jun 2004 14:09:35 +0100
Message-ID: <001601c459ec$81478b40$7102a8c0@Primary>

Looking at the TIM= stamps, you are getting through calls at a rate which is far too rapid for the granularity of the Oracle timer to notice anything happening - which may be why the CPU from Oracle's perspective is recording zero activity.

Looking at the 20 million round-trips you've recorded in 4,000 seconds, you would appear to have processed 640GB (32K x 20M) of data - which seems unlikely, so I suspect that an unexpected error is occurring which is cycling the calls at an impossibly rapid speed - perhaps something like end-of-file not being found.

Regards

Jonathan Lewis

http://www.jlcomp.demon.co.uk

http://www.jlcomp.demon.co.uk/faq/ind_faq.html The Co-operative Oracle Users' FAQ

http://www.jlcomp.demon.co.uk/seminar.html Optimising Oracle Seminar - schedule updated May 1st

Hi List,

I have a process that has been consuming a lot of CPU time in out HP server. As you can see below, at the moment I took the snapshot it had already been executing for 55 minutes.

CPU TTY PID USERNAME PRI NI SIZE RES STATE TIME %WCPU %CPU COMMAND  1 ? 17676 erp 216 20 33984K 2912K run 55:14 51.29 51.20 oracleERP

This is what I've got so far:

and keeps going on like this.

package body APPS.FND_FILE_PRIVATE as
/* $Header: AFCPPPRB.pls 115.5 2001/06/16 09:40:34 pkm ship $ */

LOG utl_file.file_type;
OUT utl_file.file_type;

BUFFER_SIZE constant number := 32500;

LOG_FNAME varchar2(255);
OUT_FNAME varchar2(255);
TEMP_DIR varchar2(255);

NEXT_LOG_LINE varchar2(32767);
NEXT_OUT_LINE varchar2(32767);

procedure LOGFILE_GET(STATUS in out varchar2, TEXT in out varchar2) is CR varchar2(2);
begin

 CR := '
';
 TEXT := '';
 while nvl(lengthb(TEXT), 0) + nvl(lengthb(NEXT_LOG_LINE), 0) < BUFFER_SIZE loop
  TEXT := concat(TEXT, NEXT_LOG_LINE);
  NEXT_LOG_LINE := '';
  utl_file.get_line(LOG, NEXT_LOG_LINE);   NEXT_LOG_LINE := concat(NEXT_LOG_LINE, CR);  end loop;

 STATUS := 'OK';  exception
 when NO_DATA_FOUND then
  if nvl(length(TEXT), 0) > 0 then
   STATUS := 'OK';
   return;
  else
   STATUS := 'EOF';
   return;
  end if;

 when UTL_FILE.INVALID_FILEHANDLE then
  fnd_message.set_name('FND', 'CONC-TEMPFILE_INVALID_HANDLE');   fnd_message.set_token('TEMP_FILE', LOG_FNAME, FALSE);

         raise_application_error(-20104, fnd_message.get);

 when UTL_FILE.INVALID_OPERATION then
  fnd_message.set_name('FND', 'CONC-TEMPFILE_INVALID_OPERATN');   fnd_message.set_token('TEMP_FILE', LOG_FNAME, FALSE);

         raise_application_error(-20105, fnd_message.get);

 when UTL_FILE.READ_ERROR then
  fnd_message.set_name('FND', 'CONC-TEMPFILE_READ_ERROR');   fnd_message.set_token('TEMP_FILE', LOG_FNAME, FALSE);   raise_application_error(-20106, fnd_message.get);

 when OTHERS then
  raise;

end LOGFILE_GET;
...

EVENT                                    TOTAL_WAITS TIME_WAITED
---------------------------------------- ----------- -----------
SQL*Net message from client                 20045610      409293
SQL*Net message to client                     20045610        8731
latch free                                                    79711
4083
SQL*Net more data from client                            2           6
db file scattered read                                        80           2
buffer busy waits                                               2
0
file open                                                           1
0
SQL*Net more data to client                               5           0



My guess is that the session is performing many utl_file.get_line as seen before, and that's why it's taking so much CPU time. But what it's not clear to me is why Oracle does not show that in the wait events......

Why is the EXEC showing up in the 10046? "EXEC #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217"

Can anybody elaborate on this?
Any opinions?

Thanks,
Diego



Please see the official ORACLE-L FAQ: http://www.orafaq.com

To unsubscribe send email to: oracle-l-request_at_freelists.org put 'unsubscribe' in the subject line.
--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------


----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to:  oracle-l-request_at_freelists.org
put 'unsubscribe' in the subject line.
--
Archives are at http://www.freelists.org/archives/oracle-l/
FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------
Received on Thu Jun 24 2004 - 08:06:50 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US