Deadlock in SmartGWT v5.0 but not in v3.1

[andrerichards]

Hi

I am experiencing DB deadlocks since upgrading to v5.0. I have 2 tables, PendingReservation and PendingItinerary with a foreign key column in PendingItinerary called PendingReservationID. Like so:

| PendingReservation | | PendingItinerary |
| ID | <---------- --------- | PendingReservationID |

When inserting records I first insert a record into PendingReservation, and then pass on the generated ID to insert the foreign key record.

RPCManager rpcManager = dsRequest.getRPCManager();


/*insert*/
DSResponse pendingReservationResponse = DS.execute(DATASOURCE_NAME, DS.OperationType.ADD.getValue(), null, pendingReservationValues, rpcManager);


/* in PendingReservation datasource I override the default 'add' operation that will always first check if it doenst already exists before inserting a new record atherwise fetch existing */
public static DSResponse add(DSRequest request) throws Exception {		
		List<Map> fetch = DS.fetch(request.getDataSourceName(), DS.getCriteria("SessionID", request.getCriteria().get("SessionID")), request.getRPCManager(), ImmutableList.of("ID"));
		if(fetch.size() == 0) { //not exists
			return request.execute();
		}

		return DS.executeFetch(request.getDataSourceName(), DS.getCriteria("SessionID", request.getCriteria().get("SessionID")), request.getRPCManager());
	}

/* We then insert the foreign key record using the ID returned by PendingReservation insert*/

Map<String, Object> pendingItineraryValues = new HashMap<String, Object>();
pendingItineraryValues.put("PendingReservationID", pendingReservation.get("ID"));

DSResponse pendingInventoryResponse = DS.execute(DSPendingItinerary.DATASOURCE_NAME, DS.OperationType.ADD.getValue(), null, pendingItineraryValues, rpcManager);


/**
	 * Convenience method for executing a DSRequest.
	 */
	@NotNull
	public static DSResponse execute(@NotNull final String dataSourceName, @NotNull final String operationType, @Nullable final String operationId,
																				@Nullable final Object criteria, @Nullable final RPCManager rpcManager, @Nullable final List<String> outputs, final boolean allowMultiUpdate) throws Exception {
		final PerformanceSteps steps = new PerformanceSteps();
		final DSRequest dsRequest = new DSRequest(dataSourceName, operationType, rpcManager);
		dsRequest.setOperationId(operationId);
		dsRequest.setOutputs(outputs);
		dsRequest.setAllowMultiUpdate(allowMultiUpdate);
		if (operationType.equals("add")) {
			dsRequest.setValues(criteria);
		}
		else {
			dsRequest.setCriteria(criteria);
		}
		final DSResponse dsResponse = dsRequest.execute();
		if (!operationType.equals("fetch")) {
			Caches.update(dsRequest, dsResponse);
		}
		String perfCounterName = createPerformanceCounterName(dsRequest);
		PerformanceCounters.update(perfCounterName, steps);
		if (operationType.equals("fetch")) {
			PerformanceCounters.update(perfCounterName + ".size", dsResponse.getDataList().size());
		}
		return dsResponse;
	}

Looking at the logs, I can see that even though I do pass in the same RPCManager to all insert/fetch DSRequests SmartGWT does not excecute them in the same transaction like it did in version 3.1. See below for logs:

=== 2015-03-18 09:55:54,866 [ec-6] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLServer' using connection'1395419921'
=== 2015-03-18 09:55:54,866 [ec-6] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLServer' using connection'1395419921'
=== 2015-03-18 09:55:54,867 [ec-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLServer': INSERT INTO dbo.PendingReservation (AgentID, AllocationID, ChannelConfNo, ChannelID, ContactName, CreateDate, ResType, SessionID, UserID) VALUES (NULL, NULL, '457', 1, '', '2015-03-18T00:00:00', 1, 'C47EFC00EDB688A7F670', 1)
=== 2015-03-18 09:55:54,867 [ec-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLServer': INSERT INTO dbo.PendingReservation (AgentID, AllocationID, ChannelConfNo, ChannelID, ContactName, CreateDate, ResType, SessionID, UserID) VALUES (NULL, NULL, '457', 1, '', '2015-03-18T00:00:00', 1, 'C47EFC00EDB688A7F670', 1)
=== 2015-03-18 09:55:54,899 [ec-6] DEBUG SQLDriver - [builtinApplication.null] Found 1 sequence(s)/autoGenerated PK field(s): [ID]
=== 2015-03-18 09:55:54,899 [ec-6] DEBUG SQLDriver - [builtinApplication.null] Found 1 sequence(s)/autoGenerated PK field(s): [ID]
=== 2015-03-18 09:55:54,899 [ec-6] DEBUG SQLDriver - [builtinApplication.null] Discovered zero or one generated key via JDBC: {ID=520}
=== 2015-03-18 09:55:54,899 [ec-6] DEBUG SQLDriver - [builtinApplication.null] Discovered zero or one generated key via JDBC: {ID=520}
=== 2015-03-18 09:55:54,899 [ec-6] INFO  SQLDataSource - [builtinApplication.null] primaryKeys: {}
=== 2015-03-18 09:55:54,899 [ec-6] INFO  SQLDataSource - [builtinApplication.null] primaryKeys: {}
=== 2015-03-18 09:55:54,899 [ec-6] INFO  SQLDataSource - [builtinApplication.null, builtinApplication.null] Performing fetch operation with
	criteria: {ID:520}	values: {ID:520}
=== 2015-03-18 09:55:54,899 [ec-6] INFO  SQLDataSource - [builtinApplication.null, builtinApplication.null] Performing fetch operation with
	criteria: {ID:520}	values: {ID:520}
=== 2015-03-18 09:55:54,900 [ec-6] INFO  SQLDataSource - [builtinApplication.null, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2015-03-18 09:55:54,900 [ec-6] INFO  SQLDataSource - [builtinApplication.null, builtinApplication.null] derived query: SELECT $defaultSelectClause FROM $defaultTableClause WHERE $defaultWhereClause
=== 2015-03-18 09:55:54,900 [ec-6] INFO  SQLDataSource - [builtinApplication.null, builtinApplication.null] 890: Executing SQL query on 'SQLServer': SELECT PendingReservation.ID, PendingReservation.UserID, PendingReservation.SessionID, PendingReservation.Status, PendingReservation.BookingStatus, PendingReservation.CreateDate, PendingReservation.AmendDate, PendingReservation.ContactID, PendingReservation.ChannelID, PendingReservation.SourceID, PendingReservation.MarketID, PendingReservation.OriginID, PendingReservation.DepositPolicyID, PendingReservation.AgentID, PendingReservation.CompanyID, PendingReservation.WholesalerID, PendingReservation.AllocationID, PendingReservation.SeriesID, PendingReservation.ChannelConfNo, PendingReservation.ResType, PendingReservation.PaymentTypeID, PendingReservation.CredCardNo, PendingReservation.CredCardExp, PendingReservation.CredCardAuthID, PendingReservation.AccountNo, PendingReservation.DepositOverridden, PendingReservation.DepositPolicyOverridden, PendingReservation.PrePaid, PendingReservation.DepositDateOverridden, PendingReservation.PromotionCode, PendingReservation.MarketOverridden, PendingReservation.Memo, PendingReservation.ConfidentialMemo, PendingReservation.ContactName, PendingReservation.ContactFirstName, PendingReservation.ContactTitleID, PendingReservation.ContactTelNo, PendingReservation.ContactEmail, PendingReservation.ReservationNo, PendingReservation.VoucherNo FROM dbo.PendingReservation WHERE (PendingReservation.ID=520)
=== 2015-03-18 09:55:54,900 [ec-6] INFO  SQLDataSource - [builtinApplication.null, builtinApplication.null] 890: Executing SQL query on 'SQLServer': SELECT PendingReservation.ID, PendingReservation.UserID, PendingReservation.SessionID, PendingReservation.Status, PendingReservation.BookingStatus, PendingReservation.CreateDate, PendingReservation.AmendDate, PendingReservation.ContactID, PendingReservation.ChannelID, PendingReservation.SourceID, PendingReservation.MarketID, PendingReservation.OriginID, PendingReservation.DepositPolicyID, PendingReservation.AgentID, PendingReservation.CompanyID, PendingReservation.WholesalerID, PendingReservation.AllocationID, PendingReservation.SeriesID, PendingReservation.ChannelConfNo, PendingReservation.ResType, PendingReservation.PaymentTypeID, PendingReservation.CredCardNo, PendingReservation.CredCardExp, PendingReservation.CredCardAuthID, PendingReservation.AccountNo, PendingReservation.DepositOverridden, PendingReservation.DepositPolicyOverridden, PendingReservation.PrePaid, PendingReservation.DepositDateOverridden, PendingReservation.PromotionCode, PendingReservation.MarketOverridden, PendingReservation.Memo, PendingReservation.ConfidentialMemo, PendingReservation.ContactName, PendingReservation.ContactFirstName, PendingReservation.ContactTitleID, PendingReservation.ContactTelNo, PendingReservation.ContactEmail, PendingReservation.ReservationNo, PendingReservation.VoucherNo FROM dbo.PendingReservation WHERE (PendingReservation.ID=520)
=== 2015-03-18 09:55:54,903 [ec-6] DEBUG SQLDriver - [builtinApplication.null, builtinApplication.null] About to execute SQL query in 'SQLServer' using connection '1395419921'
=== 2015-03-18 09:55:54,903 [ec-6] DEBUG SQLDriver - [builtinApplication.null, builtinApplication.null] About to execute SQL query in 'SQLServer' using connection '1395419921'
=== 2015-03-18 09:55:54,903 [ec-6] INFO  SQLDriver - [builtinApplication.null, builtinApplication.null] Executing SQL query on 'SQLServer': SELECT PendingReservation.ID, PendingReservation.UserID, PendingReservation.SessionID, PendingReservation.Status, PendingReservation.BookingStatus, PendingReservation.CreateDate, PendingReservation.AmendDate, PendingReservation.ContactID, PendingReservation.ChannelID, PendingReservation.SourceID, PendingReservation.MarketID, PendingReservation.OriginID, PendingReservation.DepositPolicyID, PendingReservation.AgentID, PendingReservation.CompanyID, PendingReservation.WholesalerID, PendingReservation.AllocationID, PendingReservation.SeriesID, PendingReservation.ChannelConfNo, PendingReservation.ResType, PendingReservation.PaymentTypeID, PendingReservation.CredCardNo, PendingReservation.CredCardExp, PendingReservation.CredCardAuthID, PendingReservation.AccountNo, PendingReservation.DepositOverridden, PendingReservation.DepositPolicyOverridden, PendingReservation.PrePaid, PendingReservation.DepositDateOverridden, PendingReservation.PromotionCode, PendingReservation.MarketOverridden, PendingReservation.Memo, PendingReservation.ConfidentialMemo, PendingReservation.ContactName, PendingReservation.ContactFirstName, PendingReservation.ContactTitleID, PendingReservation.ContactTelNo, PendingReservation.ContactEmail, PendingReservation.ReservationNo, PendingReservation.VoucherNo FROM dbo.PendingReservation WHERE (PendingReservation.ID=520)
=== 2015-03-18 09:55:54,903 [ec-6] INFO  SQLDriver - [builtinApplication.null, builtinApplication.null] Executing SQL query on 'SQLServer': SELECT PendingReservation.ID, PendingReservation.UserID, PendingReservation.SessionID, PendingReservation.Status, PendingReservation.BookingStatus, PendingReservation.CreateDate, PendingReservation.AmendDate, PendingReservation.ContactID, PendingReservation.ChannelID, PendingReservation.SourceID, PendingReservation.MarketID, PendingReservation.OriginID, PendingReservation.DepositPolicyID, PendingReservation.AgentID, PendingReservation.CompanyID, PendingReservation.WholesalerID, PendingReservation.AllocationID, PendingReservation.SeriesID, PendingReservation.ChannelConfNo, PendingReservation.ResType, PendingReservation.PaymentTypeID, PendingReservation.CredCardNo, PendingReservation.CredCardExp, PendingReservation.CredCardAuthID, PendingReservation.AccountNo, PendingReservation.DepositOverridden, PendingReservation.DepositPolicyOverridden, PendingReservation.PrePaid, PendingReservation.DepositDateOverridden, PendingReservation.PromotionCode, PendingReservation.MarketOverridden, PendingReservation.Memo, PendingReservation.ConfidentialMemo, PendingReservation.ContactName, PendingReservation.ContactFirstName, PendingReservation.ContactTitleID, PendingReservation.ContactTelNo, PendingReservation.ContactEmail, PendingReservation.ReservationNo, PendingReservation.VoucherNo FROM dbo.PendingReservation WHERE (PendingReservation.ID=520)


=== 2015-03-18 09:55:54,928 [ec-6] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLServer' using connection'1831349195'
=== 2015-03-18 09:55:54,928 [ec-6] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLServer' using connection'1831349195'
=== 2015-03-18 09:55:54,928 [ec-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLServer': INSERT INTO dbo.PendingItinerary (AmountExclTax, AmountInclTax, ArrivalDate, CurrencyID, Duration, InventoryID, MealPlanID, NoOfRooms, PendingReservationID, PropertyID, RateCodeID, RatePerDay, ReserveType) VALUES (3000.0, 3420.0, '20150329', 1, 3, 70, 1, NULL, 520, 22, 1, 1000.0, 'Book')
=== 2015-03-18 09:55:54,928 [ec-6] INFO  SQLDriver - [builtinApplication.null] Executing SQL update on 'SQLServer': INSERT INTO dbo.PendingItinerary (AmountExclTax, AmountInclTax, ArrivalDate, CurrencyID, Duration, InventoryID, MealPlanID, NoOfRooms, PendingReservationID, PropertyID, RateCodeID, RatePerDay, ReserveType) VALUES (3000.0, 3420.0, '20150329', 1, 3, 70, 1, NULL, 520, 22, 1, 1000.0, 'Book')

You can see it is using a different connection when trying to insert into PendingItinerary.

SmartClient Version: v10.0p_2015-02-28/PowerEdition Deployment (built 2015-02-28)

[andrerichards]

I rolled back to 3.1 and the deadlock ceased to happen. The logs also showed that the RPCManager is correctly using the same transaction when inserting the records.

[edulid]

Do you also use Microsoft SQL Server?

[Blama]

Hi,

Do you also use Microsoft SQL Server?

"INSERT INTO dbo.PendingReservation", so most likely yes.

I find it strange that in the log all the entries are there twice, but with different timestamps. Does not seem normal.

What is "DS."? Also, the connection-numbers used for the two requests are different in the logs (already mentioned by OP) and there is not commit/rollback (or at least no messages, perhaps enable logging for RPCManager and SQLTransaction).

Don't know if this helps.

Best regards,
Blama

[andrerichards]

Do you also use Microsoft SQL Server?

Yes, sorry forgot to mention that.

I find it strange that in the log all the entries are there twice, but with different timestamps. Does not seem normal.

It does not seem normal yes, but I can assure you I only call ds.excecute() once. Must be a SmartGWT logging it twice?

What is "DS."? Also, the connection-numbers used for the two requests are different in the logs (already mentioned by OP) and there is not commit/rollback (or at least no messages, perhaps enable logging for RPCManager and SQLTransaction).

DS is just a class containing helper methods like the "execute()" method listed in the post I use to reduce duplicating code. DRY :)

I will enable logging for RPCManager as well and see thanks.

[edulid]

I can confirm that different DSRequests *that use the same RPCManager* are using different connections:

=== 2015-03-18 12:40:01,405 [ec-9] DEBUG SQLDriver - [builtinApplication.null] About to execute SQL update in 'SQLSERVER' using connection'970459789'
=== 2015-03-18 12:40:01,405 [ec-9] DEBUG SQLDriver - [builtinApplication.doUpdateAddresses] About to execute SQL query in 'SQLSERVER' using connection '300037323'

Further, I am getting a lot of these messages (I don't know if this is related):

=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed
=== 2015-03-18 12:40:01,561 [ec-9] DEBUG DSRequest - Ignoring freeResources call because they have already been freed

[andrerichards]

Found that by setting autoJoinTransactions in the server.properties to true fixes the issue.

sql.SQLServer.autoJoinTransactions: true

[edulid]

Looking at the logs, I can see that even though I do pass in the same RPCManager to all insert/fetch DSRequests SmartGWT does not excecute them in the same transaction like it did in version 3.1. See below for logs:

This seems to be by-design, since the fetch requests are not included in the transaction using the default settings (refer to http://forums.smartclient.com/showpo...6&postcount=12). If I understand correctly, this is why setting sql.SQLServer.autoJoinTransactions: to true solves the problem: the fetches are now included in the transaction.

@Isomorphic was this setting different in 3.1 ? This would explain andrerichards issue