tags:

views:

205

answers:

1

I'm using aspect-oriented programming techniques to create very fine-grained logging for a class library. Each method call will be logged.

I'm trying to develop a stacked bar chart with each call that comes from an instance of a class, with each sub-call occupying space in between the start and finish of the outer call to visually represent the time taken and aid in performance tuning. In order to do this, I need to identify which calls came from the same instance as a given call and lie between its start and end date, provided the CallGUID (primary key for the table). I know I need to double-reference the table, but I've been trying and the result set has the same Ticks for all the calls.


Schema:

USE [Skunkworks]
GO
/****** Object:  Table [dbo].[ClassMemberCall]    Script Date: 06/09/2009 15:38:45 ******/
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE TABLE [dbo].[ClassMemberCall](
    [CallGUID] [uniqueidentifier] NOT NULL,
    [InstanceGUID] [uniqueidentifier] NOT NULL,
    [MemberGUID] [uniqueidentifier] NOT NULL,
    [StartedOn] [datetime] NOT NULL,
    [FinishedOn] [datetime] NULL,
    [SerializedResult] [text] COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
    [ExceptionGUID] [uniqueidentifier] NULL,
    [SerializedException] [text] COLLATE SQL_Latin1_General_CP1_CI_AS NULL,
    [StartedOnTick] [bigint] NOT NULL,
    [FinishedOnTick] [bigint] NULL

Data:

INSERT INTO [ClassMemberCall] ([CallGUID],[InstanceGUID],[MemberGUID],[StartedOn],[FinishedOn],[SerializedResult],
[ExceptionGUID],[SerializedException],
[StartedOnTick],[FinishedOnTick])
VALUES('1F45C171-910B-4F17-9286-3D8CDEB7A0C4','B1AE1340-1ED7-4C69-A964-49429D3F81B8','AF1249C9-7DE7-46BD-8042-9AFBD2DFAC15',
'Jun  9 2009  3:23:00:790PM','Jun  9 2009  3:23:00:837PM',NULL,'A4252B69-99FF-43F9-AA33-E8704478CD3E',
'Logging.Entities.ExceptionResult',633801577807903192,633801577808371951)
INSERT INTO [ClassMemberCall] ([CallGUID],[InstanceGUID],[MemberGUID],[StartedOn],
[FinishedOn],[SerializedResult],[ExceptionGUID],[SerializedException],
[StartedOnTick],[FinishedOnTick])VALUES('82989F3F-56F9-4F0A-9CBF-752FC07BA110','EBDF2013-6858-4DBB-AA8A-D1931FAF0BF8','55FE8E6C-9694-4DD1-9152-DD492102C00C','Jun  9 2009  3:23:00:713PM','Jun  9 2009  3:23:00:713PM',NULL,NULL,NULL,633801577807121927,633801577807121927)
INSERT INTO [ClassMemberCall] ([CallGUID],[InstanceGUID],[MemberGUID],[StartedOn],[FinishedOn],[SerializedResult],[ExceptionGUID],[SerializedException],[StartedOnTick],[FinishedOnTick])VALUES('B9779849-4815-4C92-8F2E-A29CB307B925',
'17D4C08C-1DCD-4CBA-97A4-BE7A2DFF1DAB','8AC8D865-DEB2-4858-ACE5-A9252F484350','Jun  9 2009  3:23:00:790PM','Jun  9 2009  3:23:00:790PM',NULL,NULL,NULL,633801577807903192,633801577807903192)
INSERT INTO [ClassMemberCall] ([CallGUID],[InstanceGUID],[MemberGUID],[StartedOn],[FinishedOn],[SerializedResult],
[ExceptionGUID],[SerializedException],
[StartedOnTick],[FinishedOnTick])VALUES('CAE8210C-617A-49F4-A739-E442F39B55B0',
'D46CFBF8-5DC0-437B-AE58-A9237BF8E1A0','108BC581-A5BA-402C-BA15-B8D1EB0C03F1','Jun  9 2009  3:23:00:650PM','Jun  9 2009  3:23:00:837PM',NULL,NULL,NULL,633801577806496915,633801577808371951)
+2  A: 

I'm not sure I get you right, but if I do, something like that seems to do the trick:

select RESULT.* from classmembercall as RESULT 
inner join classmembercall as INPUT 
    ON RESULT.startedontick BETWEEN INPUT.startedontick and INPUT.finishedontick 
    AND RESULT.finishedontick BETWEEN INPUT.startedontick and INPUT.finishedontick
where INPUT.CallGUID = 'CAE8210C-617A-49F4-A739-E442F39B55B0'

it should give you all calls between start and end tick of given log entry

if you need to filter it additionally by the same InstanceGUID, then:

select RESULT.* from classmembercall as RESULT 
inner join classmembercall as INPUT 
    ON RESULT.startedontick BETWEEN INPUT.startedontick and INPUT.finishedontick 
    AND RESULT.finishedontick BETWEEN INPUT.startedontick and INPUT.finishedontick
    AND RESULT.InstanceGUID = INPUT.InstanceGUID
where INPUT.CallGUID = 'CAE8210C-617A-49F4-A739-E442F39B55B0'

note that given your sample data, you'll always get only the item with provided CallGuild - because all of the rows have different InstanceGUIDs...

Good luck :)

Michał Chaniewski
Thanks a bunch. I used a very limited resultset on purpose, those GUIDS aren't going to paste themselves :)I've got a lot more data now and will give you credit in a second when I test it out.
Chris McCall
This is returning only one row with each column represented twice!CallGUID InstanceGUID MemberGUID StartedOn FinishedOn SerializedResult ExceptionGUID SerializedException StartedOnTick FinishedOnTick CallGUID InstanceGUID MemberGUID StartedOn FinishedOn SerializedResult ExceptionGUID SerializedException StartedOnTick FinishedOnTick82989F3F-... EBDF2013-... 55FE8E6C-... 2009-06-09 15:23:00.713 2009-06-09 15:23:00.713 NULL NULL NULL 6338...1927 6338... 82989F3F-... EBDF2013-... 55FE8E6C-... 2009-06-09 15:23:00.713 2009-06-09 15:23:00.713 NULL NULL NULL 633801577807121927 633801577807121927
Chris McCall
Ran out of characters above... is that expected behavior?Maybe I wasn't specific enough on the resultset format... I'm looking for one row for each call that falls between the begin and end time of the target call
Chris McCall
yeah, see my edit - change select * to select RESULT.*one row - are sure you have more than one row item with the same InstanceGUID?
Michał Chaniewski
Good catch! Not only did you get the query right for me, you also detected a bug in my code. A+++ would click again.
Chris McCall