Hi guys, I am trying to get a quicker alert to myself when a connection is being blocked. To figure out how long it has been blocked for I was using the connection property WaitStartTime. However I have a minor issue, it seems like the time is in the future. I put a lock on a table then ran my query. The WaitStartTime gave the following timestamp: 2012-03-28 10:39:57.675 The current timestamp gave the following timestamp: 2012-03-28 10:32:58.714 Do note that the connection property LastReqTime matched the WaitStartTime and the connection property TransactionStartTime was an empty string. Can someone please tell me why my WaitStartTime is in the future? FWIW I am running on a ASA12 engine. Thanks! |
IMO BlockedOn would be the property of choice to test... the description of WaitStartTime does not mention blocking, and there are other reasons for a connection to wait (like no available thread).
FWIW Foxhound can send you an Alert when a connection is blocked, and the next release will allow you to AutoDrop either blocker or blockee.
BlockedOn gives me the connection of what is blocking it (and is working good), but I only need to be concerned if the connection has been blocked for more then a minute or so, which is why I need to know how long it has been blocked for.
I will look into Foxhound, thanks for the tip.
"how long it has been blocked"... that would be LastReqTime, since by definition the victim became blocked at the point the last request was made, at least from the client-request point of view. That's the property Foxhound uses to calculate the blocked connection Waiting Time value.
The LastReqTime always matches (at least on all of my tests) the WaitStartTime, which is, again, in the future. And the most annoying part is it is always a different amount of time in the future, sometimes over 350 seconds, sometimes under 60 seconds. I'm wondering what clock it is going based on, and why it's using a different clock then current timestamp to record the time.
Sounds like a bug... what build of V12 are you using? Can you try a more recent EBF?
Looks like I am using 12.0.1.3298 - I will grab the newest EBF and see when I can install it. Thanks.
In my current tests, the time values for "current timestamp" and the "LastReqTime" seem very different: Current timestamp fits the client's and server's time (both are synchronized regularly), whereas the "LastReqTime" is about 50 minutes behind... (15:34 vs. 14:43). This may be due to the lately switch to CEST here - the server has not booted since then.
So I would suggest that you compare the "LastReqTime" of the blocked and the current (diagnosing) connection to calculate the timespan.
I'm using 12.0.1.3324...
FWIW, the 12.0.1.3554 readme doesn't list any such fix.
He is reporting that LastReqTime > CURRENT TIMESTAMP which is "impossible"
Yep, I'm aware of that. However, I'm reporting that on my servers (another one on 12.0.1.3298 shows the same behaviour but with a different time lag), LastReqTime << CURRENT TIMESTAMP even for freshly done queries, so I would suspect that these timings have different time sources - and if that is true (and not a bug), then why shouldn't be LastReqTime be "in front"...?
In other words: In case they do have different time sources (which I cannot know, for obvious reasons), then it would seem reasonable to compare just values from the same source, therefore my suggestion to compare LastRegTime from different connections (where one is known to be "current") with each other...
Ok testing this on my local test bed, I found that restarting the database engine seems to pull the two timestamps back in sync. I guess my next question is, is there a way I can run a command that will re-sync them or is restarting the database engine really the only way?
CURRENT TIMESTAMP and LastReqTime both come from the server.
The LastReqTime value doesn't change for either connection (the one blocking or the one being blocked) so the only thing that would give me is the amount of time the blocking query has ran before the query being blocked started, which isn't what I need. I need how long the query being blocked has been blocked for.
It might be possible that the system clock is very unstable, and CURRENT TIMESTAMP may have drifted into the future at the point LastReqTime was recorded, then it was pulled back into reality by the regular time synchronization process.
I have seen such instability before, and investigated it with a scheduled EVENT that inserted rows with DEFAULT AUTOINCREMENT and DEFAULT CURRENT TIMESTAMP columns into a table every second or so, then did queries to look for (and find!) regular trips into the future and back.
Yes, I remember - one of the OLAP quiz questions I recently re-read...
Still, I do think that
And now SQL Anywhere Engineering might give insights into REAL CODE:)
Compare these values with the connection that is about to report the problem. That connection will by design run "currently" - even if its "LastReqTime" is inaccurate as well. So the time difference ought to be the real blocking time.
That's a Catch 22 isn't it? :)... "diagnosing connection" implies running a request on that connection, which would... change the LastReqTime... :)
No, I had expected that there is some diagnosing connection (possibly an scheduled event) that has the task to detect and alert when any other connection is blocked - how would you otherwise take notice of that blocking?
And that "diagnosing" connection surely has a current "LastReqTime" - if it would not run "currently" (ro be blocked) - how would it be able to send an alert?
It would be a Catch 22 if the blocked connection would be asked to self-document - but that's not my level of engineering, I leave that to the SQL Anywhere "Zero Administration experts", and for a reason, apparently:)
And it won't take long until there's a "Comment 22" here, I fear...