Re: A request for input to a personal puzzle

use tkprof on the trace file and post the last few lines to the group.

I can't see a fetch on the last of the trace but the sqlnet waits would seem to indicate it's waiting for the

fetch cycle from the application cursor..... "Kevin Counts" <kcounts_at_helios.acomp.usf.edu> wrote in message news:f2ac0433.0207151732.56936b7d_at_posting.google.com...
> I am performing an upgrade of a help desk package called RightNow Web.
>
> The upgrade of the oracle database takes several days to complete > 36
> hours.
> I finally moved every portion of the database into a ramdisk (tmpfs)
> on
> a Solaris E280 (2 x 750MHz USIII w/ 4GB of RAM) and I'm running into
> the same slow upgrade time.
>
> What is bugging me is I can't figure out what is going on behind the
> scenes.
>
> The only active process on this test database is a pro*c program
> called dbaudit which logs into oracle as user 'RNW'
>
> I turned on timed_statistics and sql_trace in the init.ora.
>
> I verify that the process is still running (run at 21:12) :
>
> Oracle8i Enterprise Edition Release 8.1.7.3.0 - Production
> With the Partitioning option
> JServer Release 8.1.7.3.0 - Production
>
> SQL> select username,sid,serial# from v$session;
>
> USERNAME SID SERIAL#
> ------------------------------ ---------- ----------
> 1 1
> 2 1
> 3 1
> 4 1
> 5 1
> 6 1
> RNW 7 16
> SYS 8 7981
>
> Then I look at the tracefile which hasn't been updated since
> 17:58:
>
> -rw-rw---- 1 oracle dba 75858207 Jul 15 17:58
> acomp_ora_22573.trc
>
> (its huge because they didn't use bind variables and hard parse
> a reference number for each help desk incident refno)
>
> Here are the last lines of acomp_ora_22573.trc:
>
> *** SESSION ID:(7.16) 2002-07-15 17:39:36.765
> (snip)
>
> $ tail acomp_ora_22573.trc
> FETCH #15:c=0,e=0,p=0,cr=21,cu=0,mis=0,r=201,dep=0,og=4,tim=3892781236
> FETCH #15:c=0,e=0,p=0,cr=30,cu=0,mis=0,r=201,dep=0,og=4,tim=3892781243
> FETCH #15:c=0,e=0,p=0,cr=33,cu=0,mis=0,r=169,dep=0,og=4,tim=3892781251
> STAT #15 id=1 cnt=18459 pid=0 pos=0 obj=3055 op='TABLE ACCESS FULL
> INCIDENTS '
> =====================
> PARSING IN CURSOR #15 len=297 dep=0 uid=18 oct=3 lid=18 tim=3892781257
> hv=3196652292 ad='9107b610'
> SELECT count(*), stat_date FROM incidents inc, stats WHERE
> stats.interface_id = inc.interface_id AND time_created < stat_date AND
> (time_closed >= stat_date OR time_closed IS NULL) AND (stat_date
> BETWEEN '1999-06-24 14:52:09' AND '2002-07-15 00:00:00') AND
> stats.interface_id = 3 GROUP BY stat_date
> END OF STMT
> PARSE #15:c=0,e=0,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=3892781257
> EXEC #15:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3892781257
>
> --
>
> Let me mention that eventually this finishes -- but at this point
> I'm wondering how to find out what oracle is waiting on.
>
> The oracle process shows up in top consuming close to 50% of the cpu:
>
> $ top
> CPU states: 46.4% idle, 51.2% user, 2.4% kernel, 0.0% iowait, 0.0%
> swap
> Memory: 4096M real, 3130M swap in use, 2137M swap free
>
> PID USERNAME THR PRI NICE SIZE RES STATE TIME CPU COMMAND
> 22573 daemon 11 10 0 391M 371M cpu1 212:30 50.00% oracle
> 71 root 11 59 0 2984K 2792K sleep 39:05 1.31% picld
> 4310 oracle 1 52 0 2560K 1640K cpu0 0:00 0.33% top
> 3378 root 1 58 0 3680K 2872K sleep 0:00 0.02% sshd
> 22572 root 4 58 0 55M 49M sleep 3:20 0.00% dbaudit
> 21445 oracle 258 59 0 387M 360M sleep 1:30 0.00% oracle
> 21447 oracle 11 59 0 384M 355M sleep 0:54 0.00% oracle
> 1 root 1 58 0 808K 392K sleep 0:39 0.00% init
> 379 root 1 48 0 2672K 1528K sleep 0:30 0.00% sshd
> 21449 oracle 11 59 0 382M 354M sleep 0:12 0.00% oracle
> 519 bb 1 12 0 1040K 872K sleep 0:04 0.00% bbrun
> 21451 oracle 1 58 0 381M 356M sleep 0:04 0.00% oracle
> 23912 root 1 58 0 3680K 2872K sleep 0:04 0.00% sshd
> 522 bb 1 12 0 1040K 872K sleep 0:03 0.00% bbrun
> 16246 root 1 58 0 3680K 2872K sleep 0:03 0.00% sshd
>
> I truss -p dbaudit and its in a wait state:
>
> (root_at_beetle)--(/)
> # truss -p 22572
> read(18, 0x01749466, 2064) (sleeping...)
> signotifywait() (sleeping...)
> door_return(0x00000000, 0, 0x00000000, 0) (sleeping...)
> lwp_cond_wait(0xFE7F55A0, 0xFE7F55B0, 0xFE6C3C48) (sleeping...)
>
> I truss -p oracle and its yielding to another thread:
>
> # truss -p 22573
> *** SUID: ruid/euid/suid = 1 / 400 / 400 ***
> *** SGID: rgid/egid/sgid = 1 / 400 / 400 ***
> yield() = 0
> yield() = 0
> yield() = 0
> yield() = 0
> yield() = 0
>
>
> Then I check v$session_wait on sid #7 to see whats going on and
> it looks like it sent what it needs to the client and is waiting:
>
> SQL> select event,wait_time,seconds_in_wait,state from v$session_wait
> where sid='7'; (edited for readability)
>
> EVENT WAIT_TIME SECONDS_IN_WAIT STATE
> -------------------- --------- ---------------
> ---------------
> SQL*Net message to Client -1 12334 WAITED SHORT
> TIME
>
> I ran this multiple times and the seq# didn't change.
>
>
> --
>
> Any ideas appreciated -- I'll check out whatever else seems
> appropriate --
> Outside input would help!
>
> Thanks
>
> Kevin Counts -- http://www.digicat.org
Received on Tue Jul 16 2002 - 05:06:46 CDT