Login Procedure Deadlock

[VolkerBarth]

SQLA 12.0.1

I was putting together a procedure to audit login events, the basic components are provided below. During testing, I found that the when dbRemote runs the database would deadlock, consistently. The fix was to add a commit statement on the line before CALL sp_login_environment in the procedure ECO.UsersLogin().

My question is..... Why?

Thanks

Jim

CREATE TABLE ECO.UsersLogins (
  LoginId         CHAR(128) NOT NULL,
  LoginTimestamp  TIMESTAMP NOT NULL,
  LoginLocation   INTEGER       NULL,
  PRIMARY KEY CLUSTERED ( LoginId, LoginTimestamp )
);

CREATE PROCEDURE ECO.UsersLogin()
BEGIN
  DECLARE @LoginId        CHAR(128);
  DECLARE @LoginTimestamp TIMESTAMP;
  DECLARE @LoginLocation  INTEGER;

  SET @LoginId        = CONNECTION_PROPERTY( 'Userid' );
  SET @LoginTimestamp = CURRENT UTC TIMESTAMP;
  SET @LoginLocation  = DBA.ReplicationIdentifier();  -- this provides unique database identifier

  INSERT INTO ECO.UsersLogins( LoginId, LoginTimestamp, LoginLocation ) ON EXISTING UPDATE VALUES ( @LoginId, @LoginTimestamp, @LoginLocation );

  CALL sp_login_environment;
END

[VolkerBarth]

Without knowing more details: Could the DBA.ReplicationIdentifier() stored function lead to any locks in conjunction with SQL Remote? (I.e. when omitting the COMMIT call, using sa_conn_info() and sa_locks() should help to identify locking issues.)

FWIW, another way to log connections is by use of the system events like Connect, ConnectFailed and Disconnect - by definition, they run on their own connection and may be more appropriate to log other connections...

[Breck_Carter]

If memory serves, SQL Remote establishes more than one connection, so they might be inserting and updating the same row in UsersLogins. IMO the primary key should be DEFAULT AUTOINCREMENT if you really want one one row per connection.

Are you positive it is a deadlock condition, or is it the simpler case of one connection being blocked by another?

[VolkerBarth]

Your memory is fine: SQL Remote does use more than one connection (separate ones for its worker threads, methinks), though I can't tell whether they all connect at exactly the same timestamp value - and that would decide whether they are logged as one or more logins here, I suspect.

Besides that, a timestamp as part of a primary key might lead to problems in general, as the resolution is dependent on database options like default_timestamp_increment... just a warning:)

[JimDiaz]

Breck/Volker DBA.ReplicationIdentifier() performs a simple select. Thanks much for the system events tip there is lots to learn. I assumed this was a deadlock but not identified as such see my post below. I'm going to look into the timestamp as well as the on existing update

[JimDiaz]

A bit more information this only occurs when -w > 1 or more precisely with -w 5. Below is what I am seeing. dbremote hangs when this occurs. No deadlocks are reported using SELECT * FROM sa_report_deadlocks () after setting LOG_DEADLOCKS.

My dbremote config is as follows -r -b -o "E:Application Log FilesSybase ASA 12.0XXXXX.log" -os 1M -c "eng=Emprise-DB7-ASA12; dbn=XXXXX; uid=dbRemote; pwd=XXXXX" -dl -k -w 5 -m 50M "E:Sybase ASA 12.0Database Mirror Log FilesXXXXX"

[JimDiaz]

I fairly sure this is a issue of poor table design. I changed the procedure to remove on existing update then changed the default for the timestamp column to default Current UTC Timestamp. I queried the table when dbremote hangs and got the following. The last two are identical values

LoginId,LoginTimestamp,LoginLocation 'dbRemote','2012-10-01 12:30:37.010',512 'dbRemote','2012-10-01 12:30:37.026',512 'dbRemote','2012-10-01 12:30:37.057',512 'dbRemote','2012-10-01 12:30:37.073',512 'dbRemote','2012-10-01 12:30:37.073',512

[JimDiaz]

Interesting I changed the procedure to

INSERT INTO ECO.UsersLogins( LoginId, LoginLocation ) VALUES ( @LoginId, @LoginLocation );

after setting the table default same issue. Maybe this is a bug

LoginId,LoginTimestamp,LoginLocation 'dbRemote','2012-10-01 12:38:19.032',512 'dbRemote','2012-10-01 12:38:19.047',512 'dbRemote','2012-10-01 12:38:19.079',512 'dbRemote','2012-10-01 12:38:19.094',512 'dbRemote','2012-10-01 12:38:19.094',512

ALTER PROCEDURE "ECO"."UsersLogin"() BEGIN DECLARE @LoginId CHAR(128); DECLARE @LoginTimestamp TIMESTAMP; DECLARE @LoginLocation INTEGER;

SET @LoginId        = CONNECTION_PROPERTY( 'Userid' );
SET @LoginTimestamp = CURRENT UTC TIMESTAMP;
SET @LoginLocation  = DBA.ReplicationIdentifier();

-- INSERT INTO ECO.UsersLogins( LoginId, LoginTimestamp, LoginLocation ) ON EXISTING UPDATE VALUES ( @LoginId, @LoginTimestamp, @LoginLocation ); INSERT INTO ECO.UsersLogins( LoginId, LoginLocation ) VALUES ( @LoginId, @LoginLocation ); -- COMMIT;

-- CALL dbo.sp_login_environment; CALL sp_login_environment; END

CREATE TABLE "ECO"."UsersLogins" ( "LoginId" CHAR(128) NOT NULL, "LoginTimestamp" TIMESTAMP NOT NULL DEFAULT CURRENT UTC TIMESTAMP, "LoginLocation" INTEGER NULL, PRIMARY KEY ( "LoginId" ASC, "LoginTimestamp" ASC ) ) IN "system";

[VolkerBarth]

Well, obviously the 5 worker threads (dbremote -w 5) start almost at the same time to do their work. This is surely expected behaviour.

The question that seems more interesting to me is: What exactly are you trying to log? Do you want to log how dbremote internally uses several connections, or are you interested in logging user activity and/or replication activity in general?

If the latter is true, I guess there will be better approaches than the one you're currently dealing with. One (besides system events) would be to use SQL Remote hook procedures like sp_hook_dbremote_begin to do whatever you want each time SQL Remote is started. That may be helpful to log when SQL Remote is running, how many messages it is receiving/sending, how long it took and so on...

[JimDiaz]

My intent was to log user activity, dbremote was a side effect. I will most likely change this to use the event however what interests me now is the behavior. Notice above the query returned two rows with the same primary key value.

Subsequently I changed the table to default timestamp rather than default current utc timestamp and eco.userlogins records only one connection.

As always thanks to everyone for the help.

[Breck_Carter]

"Notice above the query returned two rows with the same primary key value." - impossible, did not happen, can never happen, not ever, not in this life or the next 🙂

What you may be seeing is a lack of precision in the displayed value, perhaps governed by imprecise default value stored in the timestamp_format option... change that to YYYY-MM-DD HH:NN:SS.SSSSSS, or use SELECT DATEFORMAT ( ... ) with similar formatting.

[Breck_Carter]

"What exactly are you trying to log?" - that is the important question.

[VolkerBarth]

Couldn't agree more with Breck - though I'm sure the next life won't hurt us with valid or invalid PKs, thank God:)

As to DEFAULT TIMESTAMP: Note that this special value (at least when used as column default) is specified to deliver unique values, even if otherwise two rows would be inserted/modified at exactly the same fraction of time, so this is expected behaviour. Confine the quote from the docs on the TIMESTAMP special value:

Columns declared with DEFAULT TIMESTAMP contain unique values so that applications can detect near-simultaneous updates to the same row. If the current timestamp value is the same as the last value, it is incremented by the value of the default_timestamp_increment option.

The same is true for DEFAULT UTC TIMESTAMP, however, it is not true for the CURRENT variants:

Unlike DEFAULT TIMESTAMP, columns declared with DEFAULT CURRENT TIMESTAMP do not necessarily contain unique values. If uniqueness is required, consider using DEFAULT TIMESTAMP instead.