SDEINTERCEPT logs

[DahaeHwang]

I am running SDEINTERCEPT utility from my client machine to identify slow performance.
First I closed all ArcGIS Product on my machine, enabled logging, opened one of my heavy loading map documents from ArcMap. When loading's complete I checked the logs and there was no delay between Command-Executed-Time and Result-Returned-Time but I found most time consumtion was beteen 'NextBuffer completed time' and the next command executed time like:
========================================
[W 15:39:45] Command: NextBuffer
[W 15:39:45] Long: 1
[R 15:39:46] Long: 0
[R 15:39:46] Long: 999944
[R 15:39:46] Long: 5247
[R 15:39:46] Short: -1
[R 15:39:46] Long: 0
[R 15:39:46] Long: 0
[R 15:39:46] Block:
BufferInfo: [25/999944] Address@0x21ad0000
BufferInHex: "00000002000000020000000200013D06000000050000000800..."
========================================
[W 15:39:52] Command: NextBuffer
[W 15:39:52] Long: 1
[R 15:39:52] Long: 0
[R 15:39:52] Long: 999972
[R 15:39:52] Long: 5329
[R 15:39:52] Short: -1
[R 15:39:52] Long: 0
[R 15:39:52] Long: 0
[R 15:39:52] Block:
BufferInfo: [25/999972] Address@0x21ad0000
BufferInHex: "0000000200000002000000020003F43E000000050000000800..."
========================================
[W 15:39:57] Command: SendBlob
[W 15:39:57] Long: 1
[W 15:39:57] Short: 1
[R 15:39:57] Blob_Segment:
BufferInfo: [25/111] Address@0xf00d008
BufferInHex: "FFFFF9FF0200A0707D64D3616641B0F37D115E8F5A41608F02..."
Last Seg.: Yes
[R 15:39:57] Blob End: [111]
Flush: Yes
========================================
[W 15:39:57] Command: NextBuffer
[W 15:39:57] Long: 1
[R 15:39:57] Long: 0
[R 15:39:57] Long: 999932
[R 15:39:57] Long: 5378
[R 15:39:57] Short: -1
[R 15:39:57] Long: 0
[R 15:39:57] Long: 0
[R 15:39:58] Block:
BufferInfo: [25/999932] Address@0x21ad0000
BufferInHex: "0000000200000002000000020003F86C000000050000000800..."
========================================
[W 15:40:03] Command: NextBuffer
[W 15:40:03] Long: 1
[R 15:40:03] Long: 0
[R 15:40:03] Long: 999960
[R 15:40:03] Long: 5343
[R 15:40:03] Short: -1
[R 15:40:03] Long: 0
[R 15:40:03] Long: 0
[R 15:40:03] Block:
BufferInfo: [25/999960] Address@0x21ad0000
BufferInHex: "0000000200000002000000020001ECD6000000050000000800..."
========================================
In this case, Is it reasonable to understand that most time intervals are coming from DBMS machine's disk i/o or something? Or can this be a delay by client issues? I refered with Article#35704 (Diagnose ArcSDE connection and performance issues using SDEINTERCEPT) and thought this is not caused by bad spatial index at least since there is no missing time between the Query Start and Stop Time. Am I correct?
I know this might not be not time lag but still want to understand why this happens...
Can anybody explain what these logs exactly mean?
Thanks in advance.

SDE 9.3.1/ Oracle 10.2.0.1.0

[VinceAngelo]

If you're really using Oracle 10.2.0.1, then that's the problem.  ArcSDE 9.3.1 requires
at least 10.2.0.3, and functions best with the terminal CPU applied. 10.2.0.1 had a
number of quirks that made it very difficult to use reliably.

- V

[DahaeHwang]

Hi Vince,
Sorry. It is 10.2.0.3.

Still looking for ideas to point me in right direction..

[TravisVal]

To me this looks like the majority of time is being spent on the client side.  I would look for ways to speed up the client operations.  If this time was being spent in the database, then the times would increase more within the next buffer commands, and not between them.

If you want to be sure, you can run a database trace and see where the time is being spent.

Is the data you are accessing very detailed?  If this is, I would look at simplifying the data and adding scale dependency to the layer.  Even if you can't make them out on the screen, ArcMap still draws every vertex and shape that it pulls back from the database.

[DahaeHwang]

Thanks, Travis.
Before I try a db trace, I have another question related. I also ran the mxdPerfStat tool with the same map document and that gave me the time spent in 3 different phases- Geographic, Graphics, and Cursor phase. I understand that Cursor phase is the elapsed time of executing spatial query using iFeatureCursor to fetch data from DBMS, but I am sure if this Cursor phase includes some processing time from a local client too not only from DBMS. I can also see the Refresh Time in an xml result is the sum of Geography + Graphic phase excluding the Cursor phase then does this mean that it is independant from Geography Phase time?
Can you give me more details on how to distinguish the Cursor Phase from Geography Phase?
My understanding is that the Geography phase is the rendering time for fetched data, and the Cursor phase is not included in the Refresh time because it is not associated with Active View's refresh...But even though it is not part of refresh time, client processing is still associated with this Cursor time so I can't eliminate the client as suspect. Is this right?

Thanks for your help.