Return-Path: Delivered-To: 2-oracle-l@orafaq.com Received: (qmail 6500 invoked from network); 8 Aug 2008 21:09:48 -0500 Received: from freelists-180.iquest.net (HELO turing.freelists.org) (206.53.239.180) by air964.startdedicated.com with SMTP; 8 Aug 2008 21:09:42 -0500 Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 2F8A38DFDA6; Fri, 8 Aug 2008 22:09:34 -0400 (EDT) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing.freelists.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 17838-01-20; Fri, 8 Aug 2008 22:09:34 -0400 (EDT) Received: from turing.freelists.org (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 82E6C8E15AA; Fri, 8 Aug 2008 22:09:33 -0400 (EDT) Received: with ECARTIS (v1.0.0; list oracle-l); Fri, 08 Aug 2008 22:07:33 -0400 (EDT) Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 19EF68E45FB for ; Fri, 8 Aug 2008 22:07:33 -0400 (EDT) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing.freelists.org [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 16704-01-2 for ; Fri, 8 Aug 2008 22:07:32 -0400 (EDT) Received: from n4.bullet.mail.re4.yahoo.com (n4.bullet.mail.re4.yahoo.com [206.190.56.23]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with SMTP id 5F5478E45E6 for ; Fri, 8 Aug 2008 22:07:30 -0400 (EDT) Received: from [68.142.230.29] by n4.bullet.re4.yahoo.com with NNFMP; 09 Aug 2008 02:07:30 -0000 Received: from [66.196.97.135] by t2.bullet.re2.yahoo.com with NNFMP; 09 Aug 2008 02:07:30 -0000 Received: from [127.0.0.1] by omp108.mail.re3.yahoo.com with NNFMP; 09 Aug 2008 02:07:30 -0000 X-Yahoo-Newman-Property: ymail-5 X-Yahoo-Newman-Id: 264230.13124.bm@omp108.mail.re3.yahoo.com Received: (qmail 95793 invoked by uid 60001); 9 Aug 2008 01:40:50 -0000 DomainKey-Signature: a=rsa-sha1; q=dns; c=nofws; s=s1024; d=yahoo.com; h=Received:X-Mailer:Date:From:Reply-To:Subject:To:Cc:In-Reply-To:MIME-Version:Content-Type:Message-ID; b=w4Elk3bkEsxNlpgY9nJinQOQPx9vdrxBnB05Q7a4Bwgg3qUqBwLR8FpdS1lDsk8NppGvytE56F9CJq/g/onhTfwBe3w1hEG0d/plBsUL84AlIGF1RNK7JSO0FFDqJpW5qvycdgxB43xWACMc5m1U/SDkA71xoejfM8ZXM6HhpWk=; Received: from [69.124.238.241] by web57512.mail.re1.yahoo.com via HTTP; Fri, 08 Aug 2008 18:40:50 PDT Date: Fri, 8 Aug 2008 18:40:50 -0700 (PDT) From: Ajay Thotangare Subject: Re: SQL*Net message from client - But very high CPU To: oracle-l@freelists.org Cc: ajayoraclel@yahoo.com In-Reply-To: <445091.91077.qm@web57507.mail.re1.yahoo.com> MIME-Version: 1.0 Content-Type: multipart/alternative; boundary="0-219321677-1218246050=:93125" Message-ID: <780209.93125.qm@web57512.mail.re1.yahoo.com> X-archive-position: 10023 X-ecartis-version: Ecartis v1.0.0 Sender: oracle-l-bounce@freelists.org Errors-to: oracle-l-bounce@freelists.org X-original-sender: ajayoraclel@yahoo.com Precedence: normal Reply-to: ajayoraclel@yahoo.com List-help: List-unsubscribe: List-software: Ecartis version 1.0.0 List-Id: oracle-l X-List-ID: oracle-l List-subscribe: List-owner: List-post: List-archive: X-list: oracle-l X-Virus-Scanned: Debian amavisd-new at localhost.localdomain --0-219321677-1218246050=:93125 Content-Type: text/plain; charset=iso-8859-1 Content-Transfer-Encoding: quoted-printable More info from trace Rows=A0=A0=A0=A0 Row Source Operation -------=A0 --------------------------------------------------- =A0 25840=A0 SORT UNIQUE (cr=3D73249464 pr=3D47 pw=3D0 time=3D2031803917 us= ) =A0 43371=A0=A0 UNION-ALL=A0 (cr=3D73249464 pr=3D47 pw=3D0 time=3D315497151= 6 us) =A0 14457=A0=A0=A0 SORT AGGREGATE (cr=3D35410991 pr=3D0 pw=3D0 time=3D90411= 6332 us) =A0 29960=A0=A0=A0=A0 TABLE ACCESS BY GLOBAL INDEX ROWID GROUP_BLK_INV PART= ITION: ROW LOCATION ROW LOCATION (cr=3D35410991 pr=3D0 pw=3D0 time=3D720613= 921 us) 13128002=A0=A0=A0=A0=A0 NESTED LOOPS=A0 (cr=3D35381236 pr=3D0 pw=3D0 time= =3D630270143 us) 13083585=A0=A0=A0=A0=A0=A0 TABLE ACCESS BY INDEX ROWID GROUP_BLK (cr=3D8833= 254 pr=3D0 pw=3D0 time=3D86857291 us) 14977452=A0=A0=A0=A0=A0=A0=A0 INDEX RANGE SCAN UK_GROUP_BLK_01 (cr=3D115656= pr=3D0 pw=3D0 time=3D17299887 us)(object id 1003269) =A0 29960=A0=A0=A0=A0=A0=A0 INDEX RANGE SCAN PK_GROUP_BLK_INV (cr=3D2654798= 2 pr=3D0 pw=3D0 time=3D776521765 us)(object id 1187554) =A0 14457=A0=A0=A0 SORT AGGREGATE (cr=3D37795102 pr=3D47 pw=3D0 time=3D1125= 139872 us) =A0=A0 1867=A0=A0=A0=A0 PARTITION RANGE ALL PARTITION: 1 74 (cr=3D37795102 = pr=3D47 pw=3D0 time=3D1115949417 us) =A0=A0 1867=A0=A0=A0=A0=A0 TABLE ACCESS BY LOCAL INDEX ROWID WHLSLR_INV PAR= TITION: 1 74 (cr=3D37795102 pr=3D47 pw=3D0 time=3D1121998442 us) 70665816=A0=A0=A0=A0=A0=A0 INDEX SKIP SCAN X_WHLSLR_INV_01 PARTITION: 1 74 = (cr=3D20716900 pr=3D47 pw=3D0 time=3D1561699110 us)(object id 1189978) =A0 14457=A0=A0=A0 SORT AGGREGATE (cr=3D43371 pr=3D0 pw=3D0 time=3D1325795 = us) =A0=A0=A0=A0=A0 0=A0=A0=A0=A0 TABLE ACCESS BY GLOBAL INDEX ROWID FREESALE_I= NV PARTITION: ROW LOCATION ROW LOCATION (cr=3D43371 pr=3D0 pw=3D0 time=3D95= 8358 us) =A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0 INDEX RANGE SCAN PK_FREESALE_INV (cr=3D433= 71 pr=3D0 pw=3D0 time=3D852273 us)(object id 1187547) Elapsed times include waiting on following events: =A0 Event waited on=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 Times=A0=A0 Max. Wait=A0 Total Waited =A0 ----------------------------------------=A0=A0 Waited=A0 ----------=A0 = ------------ =A0 SQL*Net message to client=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0 13267=A0=A0=A0=A0=A0=A0=A0 0.03=A0=A0=A0=A0=A0=A0=A0=A0=A0 0.15 =A0 gc cr block 2-way=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0 1895=A0=A0=A0=A0=A0=A0=A0 0.01=A0=A0=A0=A0=A0= =A0=A0=A0=A0 1.35 =A0 gc current block 2-way=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0 521=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0= =A0 0.40 =A0 db file sequential read=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0 47=A0=A0=A0=A0=A0=A0=A0 0.02=A0=A0=A0=A0=A0=A0=A0=A0= =A0 0.50 =A0 gc cr grant 2-way=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 24=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0= =A0=A0=A0=A0=A0 0.00 =A0 gc cr block 3-way=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 967=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0= =A0=A0=A0=A0 1.10 =A0 gc current block 3-way=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0 250=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0= =A0 0.28 =A0 SQL*Net message from client=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0 13267=A0=A0=A0=A0=A0=A0=A0 1.73=A0=A0=A0=A0=A0=A0=A0 148.81 =A0 latch: KCL gc element parent latch=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 = 12=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0=A0 0.00 =A0 latch free=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 344=A0=A0=A0=A0=A0=A0=A0 0.02= =A0=A0=A0=A0=A0=A0=A0=A0=A0 0.19 =A0 latch: cache buffers chains=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0 16=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0=A0 0.0= 0 =A0 gc cr block busy=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 6644=A0=A0=A0=A0=A0=A0=A0 0.10=A0=A0=A0=A0= =A0=A0=A0=A0 21.89 =A0 buffer busy waits=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0= =A0=A0=A0=A0=A0=A0 0.00 =A0 latch: enqueue hash chains=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0=A0 0= ..00 =A0 gc cr block congested=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0 13=A0=A0=A0=A0=A0=A0=A0 0.05=A0=A0=A0=A0=A0=A0= =A0=A0=A0 0.08 =A0 gc current block congested=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0 5=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0=A0=A0 0= ..02 =A0 latch: undo global data=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0= =A0=A0 0.00 =A0 latch: gcs resource hash=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0=A0= =A0=A0 0.00 =A0 gc current grant busy=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 1=A0=A0=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0= =A0=A0=A0=A0 0.00 ***************************************************************************= ***** --- On Sat, 8/9/08, Ajay Thotangare wrote: From: Ajay Thotangare Subject: SQL*Net message from client - But very high CPU To: oracle-l@freelists.org Cc: ajayoraclel@yahoo.com Date: Saturday, August 9, 2008, 1:36 AM Hi List, I need help in solving performance problem of a query. My database is 10.2.= 0.3 on HP-UX Itanium. I traced the session during the run and noticed the session is using very h= igh CPU but the wait event in v$session shows "SQL*Net message from client"= ..=20 In top(UNIX command) this session is the top most. Not able to interpret wh= ats happening. Below is the trace details call=A0=A0=A0=A0 count=A0=A0=A0=A0=A0=A0 cpu=A0=A0=A0 elapsed=A0=A0=A0=A0= =A0=A0 disk=A0=A0=A0=A0=A0 query=A0=A0=A0 current=A0=A0=A0=A0=A0=A0=A0 rows ------- ------=A0 -------- ---------- ---------- ---------- ----------=A0 -= --------- Parse=A0=A0=A0=A0=A0=A0=A0 1=A0=A0=A0=A0=A0 0.00=A0=A0=A0=A0=A0=A0 0.00=A0= =A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0= =A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0 Execute=A0 13266=A0=A0=A0=A0 25.92=A0=A0=A0=A0=A0 28.85=A0=A0=A0=A0=A0=A0= =A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0= =A0=A0=A0=A0=A0=A0=A0=A0 0 Fetch=A0=A0=A0 13267=A0=A0 1768.47=A0=A0=A0 1875.36=A0=A0=A0=A0=A0=A0=A0=A0= 47=A0=A0 67207044=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0 23592 ------- ------=A0 -------- ---------- ---------- ---------- ----------=A0 -= --------- total=A0=A0=A0 26534=A0=A0 1794.39=A0=A0=A0 1904.21=A0=A0=A0=A0=A0=A0=A0=A0= 47=A0=A0 67207044=A0=A0=A0=A0=A0=A0=A0=A0=A0 0=A0=A0=A0=A0=A0=A0 23592 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 998=A0=20 Noticed fetch is using 1768.47 CPU of the elapsed time 1875.36. Any help appreciated. --regards, Ajay =0A=0A=0A --0-219321677-1218246050=:93125 Content-Type: text/html; charset=us-ascii
More info from trace
Rows     Row Source Operation
-------  ---------------------------------------------------
  25840  SORT UNIQUE (cr=73249464 pr=47 pw=0 time=2031803917 us)
  43371   UNION-ALL  (cr=73249464 pr=47 pw=0 time=3154971516 us)
  14457    SORT AGGREGATE (cr=35410991 pr=0 pw=0 time=904116332 us)
  29960     TABLE ACCESS BY GLOBAL INDEX ROWID GROUP_BLK_INV PARTITION: ROW LOCATION ROW LOCATION (cr=35410991 pr=0 pw=0 time=720613921 us)
13128002      NESTED LOOPS  (cr=35381236 pr=0 pw=0 time=630270143 us)
13083585       TABLE ACCESS BY INDEX ROWID GROUP_BLK (cr=8833254 pr=0 pw=0 time=86857291 us)
14977452        INDEX RANGE SCAN UK_GROUP_BLK_01 (cr=115656 pr=0 pw=0 time=17299887 us)(object id 1003269)
  29960       INDEX RANGE SCAN PK_GROUP_BLK_INV (cr=26547982 pr=0 pw=0 time=776521765 us)(object id 1187554)
  14457    SORT AGGREGATE (cr=37795102 pr=47 pw=0 time=1125139872 us)
   1867     PARTITION RANGE ALL PARTITION: 1 74 (cr=37795102 pr=47 pw=0 time=1115949417 us)
   1867      TABLE ACCESS BY LOCAL INDEX ROWID WHLSLR_INV PARTITION: 1 74 (cr=37795102 pr=47 pw=0 time=1121998442 us)
70665816       INDEX SKIP SCAN X_WHLSLR_INV_01 PARTITION: 1 74 (cr=20716900 pr=47 pw=0 time=1561699110 us)(object id 1189978)
  14457    SORT AGGREGATE (cr=43371 pr=0 pw=0 time=1325795 us)
      0     TABLE ACCESS BY GLOBAL INDEX ROWID FREESALE_INV PARTITION: ROW LOCATION ROW LOCATION (cr=43371 pr=0 pw=0 time=958358 us)
      0      INDEX RANGE SCAN PK_FREESALE_INV (cr=43371 pr=0 pw=0 time=852273 us)(object id 1187547)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                   13267        0.03          0.15
  gc cr block 2-way                            1895        0.01          1.35
  gc current block 2-way                        521        0.00          0.40
  db file sequential read                        47        0.02          0.50
  gc cr grant 2-way                              24        0.00          0.00
  gc cr block 3-way                             967        0.00          1.10
  gc current block 3-way                        250        0.00          0.28
  SQL*Net message from client                 13267        1.73        148.81
  latch: KCL gc element parent latch             12        0.00          0.00
  latch free                                    344        0.02          0.19
  latch: cache buffers chains                    16        0.00          0.00
  gc cr block busy                             6644        0.10         21.89
  buffer busy waits                               1        0.00          0.00
  latch: enqueue hash chains                      1        0.00          0.00
  gc cr block congested                          13        0.05          0.08
  gc current block congested                      5        0.00          0.02
  latch: undo global data                         1        0.00          0.00
  latch: gcs resource hash                        1        0.00          0.00
  gc current grant busy                           1        0.00          0.00
********************************************************************************


--- On Sat, 8/9/08, Ajay Thotangare <ajayoraclel@yahoo.com> wrote:
From: Ajay Thotangare <ajayoraclel@yahoo.com>
Subject: SQL*Net message from client - But very high CPU
To: oracle-l@freelists.org
Cc: ajayoraclel@yahoo.com
Date: Saturday, August 9, 2008, 1:36 AM

Hi List,
I need help in solving performance problem of a query. My database is 10.2.0.3 on HP-UX Itanium.
I traced the session during the run and noticed the session is using very high CPU but the wait event in v$session shows "SQL*Net message from client".
In top(UNIX command) this session is the top most. Not able to interpret whats happening.
Below is the trace details
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute  13266     25.92      28.85          0          0          0           0
Fetch    13267   1768.47    1875.36         47   67207044          0       23592
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    26534   1794.39    1904.21         47   67207044          0       23592
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 998 
Noticed fetch is using 1768.47 CPU of the elapsed time 1875.36.
Any help appreciated.
--regards,
Ajay


--0-219321677-1218246050=:93125-- -- http://www.freelists.org/webpage/oracle-l