EventSequence in Trace using profiler

Question

We have a stored procedure sp_foo that contains dynamic sql and at the end of sp_foo the dynamic sql is executed using EXECUTE (@query)

While analyzing a trace profile i noticed that the Eventsquence (ES), the start and end time do not match my expectation.

Row   EC   ES     Start_Time    End_Time    D_ms  SQL
C     45   1293   44.240        45.603      1363  Select ...
D     45   1294   43.737        45.603      1866  execute (@query)
E     12   1296   43.730        45.600      1871  execute sp_foo @id=34

Questions

• Why has E the highest EventSequence (ES=1296), is started first and finishes first?
• Why has C the latest start_time, but the lowest EventSequence (ES=1293)

I used this query

Select EventClass as EC, EventSequence as ES
    , Duration/1000 as duration_ms
    , convert(time, StartTime) as [Start_Time]
    , convert(time, EndTime) as [End_Time]       
    ....
From TraceImport
WHERE EventClass in (10, 12, 45)

Update to comment on first answer

Gareth points out that my Eventsequence might be running from high to low. I believe that this is not the case yet

• my Eventsequence values are ascending (later start_time == higher ES value)
• My ES numbers are in the 2.73E7 range; According to SQL Server Planet Bigint Max Value the maximum value for an Bigint in SQL Server is 8 bytes big from: -9223372036854775808 through 9223372036854775807 If i am not mistaken this would mean that my ES values had to be in the range of 9.2E17 or 9.2E18

Therefore i assume that bigint was not reached yet. We are using 2008R2 Version 10.50.4339.0

Answer 1

According to Importance of the Trace Event Sequence Column and SQL Server 2005 SP2 Changes

SQL Server 2005 shipped with an Event Sequence stored in a LONG. [The MSFT] Support has seen a few traces where the bounds of the signed long are exceeded and the Event Sequence becomes negative.

Event Sequence in SQL Server 2005 counts up from 0 to the max of bigint long, and then down from there to 0 again.

"Step 1:  Count up from 0 to 0x7FFFFFFFF
Step 2:  Count down from 0x7FFFFFFF to 0

Start at step 1 again."

SQL Server 2005 SP2 expands the column to a LONGLONG (signed 64 bit integer)

So I guess you're currently in step 2.

Answer 2

Since the three operations ended within 3 miliseconds of each other, it looks to me like the first two simply were able to wrap up and report their completion just that little bit faster than the third. (Note the End_Time is the end time of the operation, not the time the operation was logged, which would be slightly later.)

Note row E is the only stored proc call. It's possible there's slightly more overhead in wrapping up such a call.