| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Mailing Lists -> Oracle-L -> Re: Process consuming a lot of CPU, UTL_FILE and WAIT EVENTS relationship
Hi Diego, Hi ALL
I would like to pay your attention to the aspect of measuring CPU time
from OS point of view.
A totally agree with list members who responded to you (Jonathan, John)
that CPU time can be unaccounted within SQL Trace file because of
granularity and other time accounting effect in oracle code.
But it also can appear, that OS lying to you regarding CPU consumption by
this process and it actually doesn’t consume CPU continuously.
It can be that problem in your case not DB tier, but application tier or
even network.
Seams there no absolute truth on this planet ;)
Some time ago, I ran into situation like you described. After investigation it is appears that most of OS utils like “ps”, “top” etc. don’t show current situation of CPU consumption ;)
As we can see from your output, it is seams that process pid=17676 consumes 55% of CPU time.
Solaris "man ps"
pcpu The ratio of CPU time used recently to CPU time avail-
able in the same period, expressed as a percentage.
The meaning of ``recently'' in this context is
unspecified. The CPU time available is determined in
an unspecified manner.
=======================================
Possibly your process actually wait on SQL*Net event (application tier) for longer time periods (as it is appears in the SQL Trace file) and consume 100% of CPU time for short time intervals. For such process OS will show you continuously 20-80% CPU consumption.
"ps" as well as "top" command show misleading information on HPUX,
Solaris, Tru64 and some others platforms.
Truth is - there is not so easy to get correct information for CPU
consumption by process.
On HPUX glance utility can be used so see correct ONLINE information about
CPU utilization on HPUX (there diffrent utils on dffrent platforms).
I have created TESTCASE for checking lie of OS utilities (source of test is attached at the end):
Take a look on the output below:
Till row “-==< SLEEP >==-“ process which CPU utilization (second column)
monitored by “ps” command actually consuming 100% of CPU, because it
running loop. As you can see “ps’ command doesn’t show 100%, but show
progressively CPU time increasing.
After “-==< SLEEP >==-“ row, mentioned process actually doesn’t consume
any CPU (wait on .sleep call) but “ps” shows decreasing of CPU
consummation.
If your process time to time consumes 100% of CPU for short periods then
OS will sow you CPU utilization continuously.
It can appear that OS show you CPU utilization on database tier, but actual bottle neck is application server or network, as was in my case. Any comments?
Best regards,
Jurijs
TESTCASE output
20040627_134840 0.00 20040627_134841 4.69 20040627_134842 9.29 20040627_134843 13.62 20040627_134844 17.79 20040627_134845 21.76 20040627_134847 25.53 20040627_134848 29.12 20040627_134849 32.48 20040627_134850 35.73 20040627_134851 38.82 20040627_134852 41.76 20040627_134853 44.50 20040627_134854 47.16
20040627_134855 49.69 20040627_134856 49.71 20040627_134857 47.28 20040627_134858 44.97 20040627_134859 42.78 20040627_134900 40.69 20040627_134901 36.81 20040627_134902 35.06 20040627_134903 33.35 20040627_134904 31.72
=======================================
Source of TESTCASE:
test.sh
C.java
"Diego Cutrone" <diegocutrone_at_yahoo.com.ar>
Sent by: oracle-l-bounce_at_freelists.org
23.06.2004 22:51
Please respond to oracle-l
To: "Oracle List" <oracle-l_at_freelists.org>
cc:
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:
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
-- 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 Sun Jun 27 2004 - 07:39:29 CDT
 |
 |