Unexplained session Trace Messages...

From: Tim Johnston <flii_at_zoom.co.uk>
Date: Fri, 20 Oct 2000 14:56:31 +0100
Message-ID: <972050443.27326.0.nnrp-08.d4f028a1@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 Received on Fri Oct 20 2000 - 08:56:31 CDT