Showing posts with label weird. Show all posts
Showing posts with label weird. Show all posts

Wednesday, March 28, 2012

Received message constantly processed.

Hello,

when is seemd that everything works some weird behaviours comes out.

I try to summarize the problem without to post the complete code.

Service Broker is set to have a dialog between two databases on the same SQL Server instance.

The Initiator queue has retention=on and there is an activation SP to handle errors and Target's end dialog message.

The Target queue has retention=off, MAX_READER =1 and there is an activation SP to receive the message (WAIT FOR (RECEIVE (1) ...), TIMEOUT 30000 and do something with this message (sample insert into a DB).

The conversation has a Timeout Dialog to end the dialog after a while.

The problem that the message is constantly processed. The Process doens't stop is I end the dialof after the processing either.

n.b.the Receive is within a Transation that I commit at the end.

some other informations that in the meanwhile I found out :

This was my complete WAIT FOR(RECEIVE :

WAITFOR ( RECEIVE top(1) -- just handle one message at a time
@.message_type=message_type_id, --the type of message received
@.messagetypename=message_type_name,
@.message_body=message_body, -- the message contents
@.dialog = conversation_handle -- the identifier of the dialog this message was received on
FROM [TargetQueue]
), timeout 1000;

if (@.@.ROWCOUNT = 0)
BEGIN
COMMIT;
BREAK;
END

IF I delet TIMEOUT 1000, everything works as expected ...
Inside if (@.@.ROWCOUNT = 0)BEGIN..END I wrote also an Insert into a table to see wheter the end of the queue was reached but this insert never occurs (neither with not without timeout)
I'm happy that it works what if this is the solution, it make no sense to me!

Any ideas?
Thank you!

M.B.

Thank you very much

M.B.

This sounds like there are messages constantly comming and causing the WAITOFR(RECEIVE...) to get another message while is waiting. Is this the case?|||

Hi,

it shouldn't be!!

I suppose that the only way to understand what is going on is to use the SQL Profiler.

Isn't?

Thank you

|||

Hi,

I tried to use the SQL server Profiler to understand what is going on when I send/receive the message.

First at all on both queues(initiator and target) I have RETENTION = OFF so the check if @.@.ROWCOUNT = 0 will be never true because the message stays in the queue till the END of the CONVERSATION and in my case the conversation will end when there is an error or when the conversation timeout expires; otherwise I send/receive using the same conversation handle.

If I write:

WAITFOR (

RECEIVE top(1) ...

), TIMEOUT 5000;

In the SQL Server Profiler I seen that the SP that is called after the receive statement and that processes the message is constantly executed.

If I write:

WAITFOR (

RECEIVE top(1) ...

)

In the SQL Server Profiler I seen that the SP that is called after the receive statement and that processes the message is executed only ONCE.

I'm quite confuse ... I thought that is better to use a timeout but if I use I have that strange behaviour!!

Any helps/advices?
Thankx

Marina B.

|||

@.@.ROWCOUNT is set by RECEIVE to the number of rows (messages) actually returned, so it doesn't matter if RETENTION is ON or OFF.

From your description of the problem is clear that your procedured does not correctly detect when RECEIVE returned no rows, so it continues to spin on empty RECEIVEs that timeout. Can you post the actual code of the procedure?

|||

Hi Remus,

thank you very much for your answer...

Maybe it is not necessarely but this is the SP wuch start the conversation (activated by a trigger on a insert )

PROCEDURE [dbo].[sp_sendInserted]

@.MessageXML nvarchar(max)

AS

BEGIN

DECLARE @.dialog_handle uniqueidentifier;

DECLARE @.dialog_id uniqueidentifier;

DECLARE @.msg XML;

DECLARE @.Error INT;

SET NOCOUNT OFF;

BEGIN TRY

BEGIN TRANSACTION;

set @.msg = Convert(xml,@.MessageXML);

WHILE (1=1)

BEGIN

set @.dialog_handle = (select conversation_handle from sys.conversation_endpoints where far_service='ReceivedService');

if @.dialog_handle is null

--Begin new dialog

BEGIN

BEGIN DIALOG CONVERSATION @.dialog_handle

FROM SERVICE [SendService]

TO SERVICE 'ReceivedService'

ON CONTRACT [MainContract]

WITH ENCRYPTION = OFF;

BEGIN CONVERSATION TIMER (@.dialog_handle) TIMEOUT = 600;

END;

SEND ON CONVERSATION @.dialog_handle

MESSAGE TYPE MyMessage (@.msg); END

COMMIT TRANSACTION;

END TRY

BEGIN CATCH

IF XACT_STATE() = -1

BEGIN

ROLLBACK TRANSACTION;

END

Insert into [dbo].[tblErrorXMLMessages] values(@.MessageXML,@.dialog_handle,@.dialog_id,null,null,ERROR_NUMBER(),ERROR_MESSAGE(),ERROR_PROCEDURE(),getdate());

END CATCH

END

And this is the SP activated on the ReceiveQueue:

PROCEDURE [dbo].[OnReceivedMessage]

AS

DECLARE @.message_type INT;

DECLARE @.messagetypename NVARCHAR(1000);

DECLARE @.XMLmessage_body XML;

DECLARE @.dialog UNIQUEIDENTIFIER;

DECLARE @.dialog_id UNIQUEIDENTIFIER;

DECLARE @.ErrorSave INT;

DECLARE @.ErrorDesc NVARCHAR(100);

SET NOCOUNT ON;

WHILE (1 = 1)

BEGIN

BEGIN TRY

BEGIN TRANSACTION;

WAITFOR (

RECEIVE top(1) -- just handle one message at a time

@.message_type=message_type_id, --the type of message received

@.messagetypename=message_type_name,

@.XMLmessage_body=message_body, -- the message contents

@.dialog = conversation_handle -- the identifier of the dialog this message was received on

FROM [ReceivedQueue]

)--, timeout 5000; -- if the queue is empty for three second

--Before to close the conversation I get the Conversation ID to be stored in the tblErrorXMLMessages

set @.dialog_id = (select conversation_id from sys.Conversation_endpoints where conversation_handle = @.dialog);

-- If we didn't get anything, bail out

if (@.@.ROWCOUNT = 0)

BEGIN

INSERT INTO [TestReceiver].[dbo].[tblReceived] VALUES('Received SP','<ReceivedQueue>NO more messages in the queue</ReceivedQueue>');

COMMIT;

BREAK;

END

If (@.messagetypeName = N'MyMessage')

BEGIN

DECLARE @.ret integer;

EXECUTE @.ret = [TestReceiver].[dbo].[sp_ShredXMLMessageToRelationalData] @.XMLmessage_body; --SP that PROCESSES THE MESSAGE RECEIVED ON THE QUEUE

if (@.ret <> 0)

INSERT INTO [TestSender].[dbo].[tblErrorXMLMessages] VALUES

(cast(@.XMLmessage_body as nvarchar(max)),@.dialog,@.dialog_id,null,null,0,null,null,getdate());

END

ELSE IF (@.messagetypeName = N'EndOfStream')

BEGIN

END CONVERSATION @.dialog;

END

-- Check for the Error Dialog message.

ELSE IF(@.messagetypeName=N'http://schemas.microsoft.com/SQL/ServiceBroker/Error')

BEGIN

DECLARE @.WrongXMLMessage NVARCHAR(max);

set @.WrongXMLMessage = (Select message_body FROM dbo.TradeReceivedQueue WITH (NOLOCK) where Message_type_name = 'MyMessage' and status = 3 and conversation_handle=@.dialog);

DECLARE @.Error int;

DECLARE @.ErrorDescription nvarchar(4000);

WITH XMLNAMESPACES

('http://schemas.microsoft.com/SQL/ServiceBroker/Error' as ssb)

SELECT @.Error = cast(@.XMLMessage_Body as XML).value('(//ssb:Error/ssb:Code)[1]','INT'),

@.ErrorDescription = cast(@.XMLMessage_Body as XML).value('(//ssb:Error/ssbBig Smileescription)[1]','nvarchar(4000)')

IF @.WrongXMLMessage is null

BEGIN

SET @.WrongXMLMessage = N'<Error>Error retrieving the wrong XML message from the sender queue</Error>';

END

Insert into [TestSender].[dbo].[tblErrorXMLMessages] values(@.WrongXMLMessage,@.dialog,@.dialog_id,'MArina','ReceivedQueue',@.Error,@.ErrorDescription,ERROR_PROCEDURE(),getdate());

--After the End Conversation all messages from the queue are deleted

END CONVERSATION @.dialog;

END

COMMIT TRANSACTION;

END TRY

BEGIN CATCH

insert into [testReceiver].[dbo].[tblReceived] values('Error','<Marina>Error in SP Traget QUEUE</Marina>');

END CATCH

END

Let me know whether you need more info regarding contract, queues etc..etc..

Thank you very much!

Marina B.

|||

marina B. wrote:

WAITFOR (

RECEIVE top(1) -- just handle one message at a time

@.message_type=message_type_id, --the type of message received

@.messagetypename=message_type_name,

@.XMLmessage_body=message_body, -- the message contents

@.dialog = conversation_handle -- the identifier of the dialog this message was received on

FROM [ReceivedQueue]

)--, timeout 5000; -- if the queue is empty for three second

--Before to close the conversation I get the Conversation ID to be stored in the tblErrorXMLMessages

set @.dialog_id = (select conversation_id from sys.Conversation_endpoints where conversation_handle = @.dialog);

-- If we didn't get anything, bail out

if (@.@.ROWCOUNT = 0)

BEGIN

INSERT INTO [TestReceiver].[dbo].[tblReceived] VALUES('Received SP','<ReceivedQueue>NO more messages in the queue</ReceivedQueue>');

COMMIT;

BREAK;

END

SQL Server 2005 Books Online wrote:

@.@.ROWCOUNT (Transact-SQL)

Returns the number of rows affected by the last statement

RECEIVE is not the last statement before you check @.@.ROWCOUNT.

|||

As always,

my stupid mistake.

I thought that I was making a mess with the transaction!!

I moved the @.@.Rowcount check after the RECEIVE statement and it worked..

I should read more CAREFULLY the BOL !!

Thankx!!

Marina B.

Wednesday, March 7, 2012

Really weird problems

Hi

Quite recently we have moved ourdatabase from SQL 6.5 to SQL2k. Since then we are experiencing very rare but extremely weird problems -- typically they are look like at one point zero appears instead of valid value. So far I have caught 4 such cases.
Here is the configuration:
- access -- through DBLib (ntwdblib.dll v2000.80.2039.0)
- connection string is DBMSSOCN,address,port
- server/client is Win2003 Server SP1 (server and client are different boxes)
- 2-processor systems with HT enabled

Case #1:
we have a C appliation that recalculates some data and updates two different tables simultaneously with almost the same set of data. It looks like this:

// prepare three data structures
...
// send data to DB
swInsFxSumPlTable(pData, 3, pDbProc);
swInsFxTradeExpoTable(pData, 3, pDbProc);

every function looks like:

for ( usCount=0; usCount<3; usCount++ )
{
sprintf (
szQuery+strlen(szQuery),
"exec sp_swFxedrq_Add_fx_sum_pl \n"
"'%s', '%s', '%s', \n"
"%f, %f, %f, %f \n",
pData[usCount].szPcId,
pData[usCount].szCcyPairId,
pData[usCount].szCcyLen,
pData[usCount].rfNpvTodPl,
pData[usCount].rfMtdPl,
pData[usCount].rfNomPos,
pData[usCount].rfShaPipHdg
);
}

fReturn = imExecMultiQuery (pDbproc, szQuery);

(no buffer overruns happen). The only difference between them is the name of called procedure and set of parameters. Both stored procedures are simple inserts, both tables are truncated beforehand. imExecMultiQuery is equivalent to:

dbcancel( dbproc );
dbfcmd ( dbproc, "%s", pszQuery );
dbsqlexec ( dbproc )
while ( dbresults ( dbproc ) != NO_MORE_RESULTS ) dbcanquery(dbproc);

(error handling is omitted for clarity). Problem: rfNomPos is different in only one row in resulting tables. I could not believe my eyes, I have checked extract from transaction log:

"INSERT","pc_id","ccy_pair_id","ccy_code_len","npv_tod_pl","mtd_pl","nom_nop","sha_plp_hdg"
"INSERTED","CRINST"," FJD ","3","0","0","0","0"
"INSERT","pc_id","ccy_pair_id","npv_tod_pl","mtd_pl","nom_nop","sha_plp_hdg","usd_eq_nop"
"INSERTED","CRINST","FJD ","0","0","-1.38099e+008","0","-7.92688e+007"

Red-marked values should be the same, I simply can't see any way for them to be different (except of bugs in ntwdblib.dll or SQL2k). Table and stored procedure uses type float, C code uses DBFLT8. Repeated execution produces correct results.

Case #2:
we have SQR report running every day (this is script language for report generation). It uses ODBC to connect to DB. It simply reads the table and dumps all values to text file. One row has value 0 instead of correct value. Happened only once, repeated calls produced correct results. No comments, I simply dropped my jaw when I saw it. We have zillions of SQR scripts running every day, we never had such problem before. I have checked this specific row -- nobody was touching it for ages.

Bad thing that this happens randomly in various parts of our (quite big) system, and every time we find the 'magic' place after costly and time consuming reconciliation process. Every time (whether it is reading or writing) we have similar behavior -- one column's value was replaced by 0.

I do really appreciate any suggestions, because I ran out of ideas. I do suspect bug in ntwdblib.dll related to multithreading. It is impossible to reproduce it so far... I'll try to get most fresh ntwdblib.dll, if it won't help -- I'll try one shipped with SQL6.5.

Bye.
Sincerely yours, Michael.

P.S. Sorry for font size -- looks like forum is buggy too... It looks fine in editor
Update. Problem happened again :-( . Here is the excerpt from DB tranlog (altered for readability):

"fxed_sum_pl_report","CRINST|XAUD/DEM|7","INSERT","pc_id","ccy_pair_id","ccy_code_len","npv_tod_pl","mtd_pl","nom_nop","sha_plp_hdg"
"INSERTED","CRINST","XAUD/DEM","7","249051","2.64878e+006","0","0"
"fxed_sum_pl_report","CRINST| DEM |3", "INSERT","pc_id","ccy_pair_id","ccy_code_len","npv_tod_pl","mtd_pl","nom_nop","sha_plp_hdg"
"INSERTED","CRINST"," DEM ","3","0","0","-1.59396e+008","0"
"fxed_trade_expo_report","CRINST|AUD/DEM","INSERT","pc_id","ccy_pair_id","npv_tod_pl","mtd_pl","nom_nop","sha_plp_hdg","usd_eq_nop"
"INSERTED","CRINST","AUD/DEM","249051","2.64878e+006","0","0","0"
"fxed_trade_expo_report","CRINST|AUD ","UPDATE","nom_nop","usd_eq_nop"
"UPDATED FROM","4.22946e+008","3.25015e+008"
"UPDATED TO","5.40672e+008","4.14675e+008"
"fxed_trade_expo_report","CRINST|DEM ","INSERT","pc_id","ccy_pair_id","npv_tod_pl","mtd_pl","nom_nop","sha_plp_hdg","usd_eq_nop"
"INSERTED","CRINST","DEM ","0","0","-1.59396e+008","0","-1.02418e+008"

There is no update for "fxed_sum_pl_report","CRINST| AUD |3". It is simply not there. Program is supposed to do 3 updates to fxed_sum_pl_report table and then almost the same updates are going to fxed_trade_expo_report table. Thje same data is used for both calls. Each call looks like:

dbfcmd("exec sp_swFxedrq_Add_fx_sum_pl <par1>, ... \n"
"exec sp_swFxedrq_Add_fx_sum_pl <par1>, ... \n"
"exec sp_swFxedrq_Add_fx_sum_pl <par1>, ... \n"

);

dbsqlexec ( dbproc );
while ( dbresults ( dbproc ) != NO_MORE_RESULTS ) dbcanquery(dbproc);

Somehow, middle 'exec' call did not leave any trace in the transaction log... no errors or messages were produced. :-(

Here is the code of sp_swFxedrq_Add_fx_sum_pl:

/****************************************************************************/

create procedure sp_swFxedrq_Add_fx_sum_pl
@.pc_id char(6),
@.ccy_pair_id char(8),
@.ccy_code_len char(1),
@.npv_tod_pl float,
@.mtd_pl float,
@.nom_nop float,
@.sha_plp_hdg float

as
if (@.ccy_code_len = '7')
begin
select @.ccy_pair_id = 'X'+@.ccy_pair_id
end
else
begin
select @.ccy_pair_id = ' '+@.ccy_pair_id
end

if (( select count(*)
from fxed_sum_pl_report
where pc_id = @.pc_id
and ccy_pair_id = @.ccy_pair_id
and ccy_code_len = @.ccy_code_len ) > 0 )
begin
update fxed_sum_pl_report
set npv_tod_pl = npv_tod_pl + @.npv_tod_pl,
mtd_pl = mtd_pl + @.mtd_pl,
nom_nop = nom_nop + @.nom_nop,
sha_plp_hdg = sha_plp_hdg+ @.sha_plp_hdg
where pc_id = @.pc_id
and ccy_pair_id = @.ccy_pair_id
and ccy_code_len = @.ccy_code_len
end
else
begin
insert into fxed_sum_pl_report
values(
@.pc_id,
@.ccy_pair_id,
@.ccy_code_len,
@.npv_tod_pl,
@.mtd_pl,
@.nom_nop,
@.sha_plp_hdg
)
end

So, possible ways to get this behaviour:
1. DBLib somehow lost middle 'exec' call and did not transfer it to SQL server
2. select count(*) returned smth >0 (as it should be -- insert happened quite a while before), but update fxed_sum_pl_report failed to update
3. Due to mysterious error in sprintf every float argument was 0 and update did not produce any entry in tranlog. Which is strange because I have quite a lot of entries in tranlog that state: "UPDATE","NO CHANGES DETECTED"
4. tranlog extraction utility is buggy and generates ***.

Any ideas? I am really stuck.
I am going to downgrade ntwdblib.dll soon, we'll see if it will help.

Bye.
Sincerely yours, Michael.