Re: Process consuming a lot of CPU, UTL_FILE and WAIT EVENTS relationship
- From: "Jonathan Lewis" <jonathan@xxxxxxxxxxxxxxxxxx>
- To: <oracle-l@xxxxxxxxxxxxx>
- Date: Thu, 24 Jun 2004 14:09:35 +0100
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
----- Original Message -----
From: "Diego Cutrone" <diegocutrone@xxxxxxxxxxxx>
To: "Oracle List" <oracle-l@xxxxxxxxxxxxx>
Sent: Wednesday, June 23, 2004 8:51 PM
Subject: Process consuming a lot of CPU, UTL_FILE and WAIT EVENTS
relationship
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:
*** 10046 trace event
*** SESSION ID:(196.28282) 2004-06-23 10:15:56.166
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1952673792 p2=1 p3=0
APPNAME mod='WSCMTI' mh=1720951941 act='Concurrent Request' ah=1021472160
=====================
PARSING IN CURSOR #1 len=48 dep=0 uid=183 oct=47 lid=183 tim=1425833216
hv=3412908754 ad='190e52e8'
begin fnd_file_private.logfile_get(:s, :b); end;
END OF STMT
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833216
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1952673792 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1952673792 p2=1 p3=0
EXEC #1:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1952673792 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1952673792 p2=1 p3=0
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1952673792 p2=1
p3=0=1952673792 p2=1 p3=0
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1952673792 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1952673792 p2=1 p3=0
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1952673792 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1952673792 p2=1 p3=0
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1952673792 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1952673792 p2=1 p3=0
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217
WAIT #1: nam='SQL*Net message from client' ela= 0 p1=1952673792 p2=1 p3=0
WAIT #1: nam='SQL*Net message to client' ela= 0 p1=1952673792 p2=1 p3=0
EXEC #1:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=4,tim=1425833217
and keeps going on like this.
*** Then checked the fnd_file_private.logfile_get procedure:
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;
...
*** And the session wait events are:
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@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //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@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------
Other related posts:
