Re: Unexplained session Trace Messages...

The trace sample is Oracle's recursive SQL for allocating space to an extent - in order:

    find the files in a tablespace
    find free extent larger than X for a tablespace and file     check the length of the free extent found     find details of a given used extent.

Your suggestion that this may be due to BLOB handling is sound.- if you are updating a BLOB from jserver, you may be forcing Oracle to rewrite the entire BLOB, rather than simply creating a few blocks for the changed parts.

Depending on the storage definitions you have used for the BLOB, and for the tablespace that it is in, this could result in a very large number of such calls for free space being executed. (I am assuming that the bit you sent was just a very small fraction of the problem, as the total elapsed time for the code was just 1/100 sec according to the (lack of) change in the 'tim=' entry.

Of course, it is possible that the problem is simply the time taken to copy the entire LOB, rather then time spent on doing lots of fet/uet transfers in the data dictionary.

Thoughts:

    Check the CHUNKSIZE of the LOB
    Check tablespace and LOB storage values     Rebuild the LOB tablespace as 'locally managed' with     a suitable UNIFORM size.

--

Jonathan Lewis
Yet another Oracle-related web site:  http://www.jlcomp.demon.co.uk

Tim Johnston wrote in message
<972050443.27326.0.nnrp-08.d4f028a1_at_news.demon.co.uk>...


>Hi there - A quick question, hopefully a simple answer...

>

>We are currently using Oracle 8.1.7 running on Solaris 7, using JServer.

>Within the session trace file, we keep getting a time stamp appearing, in

>the following format, but no other information:

>

>*** YYYY-MM-DD HH24:MI:SS.SS

>

>When these timestamps appear, the session seems to be pausing for up to two

>minutes. The message appear frequently when we update BLOBs, but also occur

>ocassionally when not connected to the database.

>

>This is when both sql-trace and timed-statistics are turned off. When these

>parameters are turned on, we get, for example:

>

>=====================

>PARSING IN CURSOR #10 len=36 dep=1 uid=0 oct=3 lid=0 tim=2714521761

>hv=1705880752 ad='881ae19c'

>select file# from file$ where ts#=:1

>END OF STMT

>PARSE #10:c=0,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>EXEC #10:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>FETCH #10:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=2714521761

>FETCH #10:c=0,e=0,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>STAT #10 id=1 cnt=1 pid=0 pos=0 obj=17 op='TABLE ACCESS BY INDEX ROWID

 FILE$


>'

>STAT #10 id=2 cnt=2 pid=1 pos=1 obj=39 op='INDEX RANGE SCAN '

>=====================

>PARSING IN CURSOR #10 len=84 dep=1 uid=0 oct=3 lid=0 tim=2714521761

>hv=904892542 ad='881abe48'

>select file#,block#,length from fet$ where length>=:1 and ts#=:2 and

>file#=:3

>END OF STMT

>PARSE #10:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>EXEC #10:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>FETCH #10:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=2714521761

>=====================

>PARSING IN CURSOR #11 len=63 dep=1 uid=0 oct=3 lid=0 tim=2714521761

>hv=2913840444 ad='88733988'

>select length from fet$ where file#=:1 and block#=:2 and ts#=:3

>END OF STMT

>PARSE #11:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>EXEC #11:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>FETCH #11:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,tim=2714521761

>STAT #11 id=1 cnt=1 pid=0 pos=0 obj=12 op='TABLE ACCESS CLUSTER FET$ '

>STAT #11 id=2 cnt=1 pid=1 pos=1 obj=7 op='INDEX UNIQUE SCAN '

>STAT #10 id=1 cnt=1 pid=0 pos=0 obj=12 op='TABLE ACCESS CLUSTER FET$ '

>STAT #10 id=2 cnt=1 pid=1 pos=1 obj=7 op='INDEX UNIQUE SCAN '

>=====================

>PARSING IN CURSOR #10 len=94 dep=1 uid=0 oct=3 lid=0 tim=2714521761

>hv=1839874543 ad='88736618'

>select file#,block#,length from uet$ where ts#=:1 and segfile#=:2 and

>segblock#=:3 and ext#=:4

>END OF STMT

>PARSE #10:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>EXEC #10:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>FETCH #10:c=0,e=0,p=0,cr=4,cu=0,mis=0,r=0,dep=1,og=4,tim=2714521761

>STAT #10 id=1 cnt=0 pid=0 pos=0 obj=13 op='TABLE ACCESS CLUSTER UET$ '

>STAT #10 id=2 cnt=2 pid=1 pos=1 obj=9 op='INDEX UNIQUE SCAN '

>

>The question is, what's going on when these timestamps appear, or what

>causes them (if anything in particular)??

>

>Thanks in advance...

>

>Cheers

>Tim

>

>