Transaction issue with FireDAC

Data Abstract
1

I’ve been using the ADO driver up until this point without issues but I’ve just switched across to using FireDAC on XE6 and have hit a strange issue.

I have a Company and Contact table in a master-detail relationship. The SQL server has constraints on these tables to enforce referential integrity, i.e. a Contact record must have a parent Company record.

My client is attempting to add a new Company record with a single new Contact record. This is done via TDAMemDataTables in a master-detail hierarchy and the update is sent to the server as a single delta.

What I’m seeing is that, when the delta is applied, a transaction begins, then the company record is written, then the contact record is written.

The problem is that the contact insert is failing and the error is saying the foreign key constraint is being violated. This suggests to me that something is wrong with the transaction - i.e. the contact insert isn’t seeing the company insert which happened just before and is thus failing.

Can anyone shed any light on this? As I say, it was all working flawlessly with ADO, it’s just with FireDAC that it’s failing - not sure if there are some settings I need to change etc.

Thanks.

2

Bizarrely, I can’t get this to happen again, which is even more worrying/annoying as I know something went wrong but now I can’t find out what it was.

3

This could depend on whether both changes are sent as part of the same update, opposed top in separate calls to the server? Separate server calls will result in separate, independent transactions.

4

It’s a single update containing both new records to be inserted.

It’s actually just happened again. From my logging, I can see something very odd - the primary keys of both records are still negative (i.e. the temporary values assigned client-side) rather than being replaced by the IDENTITY column values from the server.

I need to try to get this reproducible I think, will dig a little more.

5

Hm, ok, that definitely sounds like something is going awry in DA then, yes.

6

Well I’ve found one issue - in the scenario I’m testing I’m running out of pool connections which is causing issues. This is fair enough and I just need to raise the pool size but I’m not sure if this is the cause of the above issue or just a coincidence and not related. I’ll fix this issue and do some more testing.

7

Ok this is getting weird. I upped the pool size but am still getting a problem.

Basically I have need to create databases on the SQL Server, which I’m doing with a separate ADO connection, i.e. not going through DA. This simply connects to the server and issues a CREATE DATABASE command.

When stress/load testing, this command is sometimes failing with the following error:

“Could not obtain exclusive lock on database ‘model’. Retry the operation later.”

Now the question is, what’s retaining a lock on the model database?

It’s hard to explain what’s going on in my code but basically my server can support multiple databases on an SQL server as clients may connect to different databases via a single DA server. What’s happening in this instance is I’m creating a new database, so I use the ADO connection to create the database on the server, then I create a new connection to it in the connection manager, then I use DA to throw a shedload of SQL at the database to create the structure (tables, views etc etc).

When this code executes, the process of creating all the tables, views and so forth creates a few connections in the pool, which is fine.

What’s happening is that, if I create a few such databases in succession, after four or five of them it fails to create the next database with the above error.

This process creates quite a few active connections in the pool, with a few new ones being created each time I add a database and the existing ones not yet timing out. This is fine and no problem, they’re all released correctly and will timeout eventually if I stop adding databases or making any other calls to the server.

The question is, what’s locking the model database? I can’t see any reason why any of the pooled DA connections would do this.

What’s interesting is that, if I reduce the connection timeout to a few seconds, so that all the pooled connections timeout between each database creation rather than mounting up, the problem never happens. This does suggest that it’s one of the pooled DA connections which is responsible for locking the model database but I have no idea why. It also doesn’t seem to happen on each database creation but only after I’ve done a few.

I realise I’m just thinking aloud here and will keep digging but if you have any ideas…

8

Ok I think all of the above might be a red herring as I’ve correct this and still have an issue - the model database problem was mine, nothing to do with DA.

I’ve been tracing through both my code and DA and have discovered something very odd.

I’m adding a record to a table and the generated INSERT command is working correctly, in that the record does appear in the table, but the records affected count is zero!

This is happening in TDABusinessProcessor.ProcessDelta. At line 1790 (in the latest DA8 release), the “rowsaffected := currcmd.Execute” is returning zero, even though the record is added. This then leads to the err_NoRowsWereAffectedByThisUpdate error being generated.

I could be wrong but right now it appears this is only happening with FireDAC. Is there a known issue here with the driver not returning the affected row count?

9

hmm, according to FireDAC documentation:

Returns the number of rows operated upon by the latest query execution.

Inspect RowsAffected to determine how many rows were inserted, updated, deleted or fetched by the last command operation. If no rows were processed, RowsAffected = 0. If the numbers of processed rows are not accessible, RowsAffected = –1.

For MS SQL Server, RowsAffected may be unexpectedly equal to -1, if the stored procedure or the table trigger omits SET NOCOUNT ON. Check BOL for more details.

we use RowAffected property, as they have suggested:

function TDAEFireDACQuery.DoExecute: integer;
begin
...
  TFDQuery(DataSet).ExecSQL;
  Result := TFDQuery(DataSet).RowsAffected;
end;

so it could be a bug in FireDAC…

10

That’s the exact code I traced through to.

The ExecSQL call goes through fine but then it reads back zero from RowsAffected. The row is added to the table just fine.

This doesn’t happen with ADO, only with FireDAC. I’ve just tried throwing together a small test app which literally uses a TFDConnection component and a TFDQuery component to replicate the exact INSERT command as closely as possible and it works fine with RowsAffected returning 1. Furthermore, this seems to be happening in one specific instance - there are loads of other INSERTS going on which work fine.

I guess it could be a bug in FireDAC but, if so, it’s some very specific circumstances which are causing it.

EDIT: Ideally I’d like to trace into the actual ExecSQL and RowsAffected functions to see what’s going on deeper but I can’t. I presume I’d have to recompile the Embarcardero sources in debug mode to achieve that but I’ve never tried that and don’t know how.

11

I’ve just enabled FireDAC tracing (the file is mahoosive!). Here’s the relevant section:

[quote]2028846118106 14:54:27.927 >> TFDCustomCommand.InternalExecute [Command=“INSERT INTO dbo.System (
[Id], [Type], [Description], [iValue], [sValue], [fValue], [bValue])
VALUES (:Id, :ItemType, :Description, :iValue, :sValue, :fValue, :bValue)
”, ATimes=0, AOffset=0, ABlocked=False]
2028846118266 14:54:27.927 >> Execute [Command=“INSERT INTO dbo.System (
[Id], [Type], [Description], [iValue], [sValue], [fValue], [bValue])
VALUES (:Id, :ItemType, :Description, :iValue, :sValue, :fValue, :bValue)
”, ATimes=0, AOffset=0]
2028846120785 14:54:27.928 . ENTER SQLGetStmtAttrW
SQLHSTMT 0x045843F0
SQLINTEGER 22 <SQL_ATTR_PARAMSET_SIZE>
SQLPOINTER 0x07FFF5C0
SQLINTEGER 0
SQLINTEGER * 0x07FFF5C4

2028846124078 14:54:27.929 . EXIT SQLGetStmtAttrW with return code 0 (SQL_SUCCESS)
SQLHSTMT 0x045843F0
SQLINTEGER 22 <SQL_ATTR_PARAMSET_SIZE>
SQLPOINTER 0x07FFF5C0 (1)
SQLINTEGER 0
SQLINTEGER * 0x07FFF5C4 (4)

2028846124456 14:54:27.929 . Param [N=1, Name=“ID”, Mode=INPUT, Type=SLONG, Size=0, Len=4, Data(0)=100]
2028846124495 14:54:27.929 . Param [N=2, Name=“ITEMTYPE”, Mode=INPUT, Type=SLONG, Size=0, Len=4, Data(0)=0]
2028846124523 14:54:27.929 . Param [N=3, Name=“DESCRIPTION”, Mode=INPUT, Type=WCHAR, Size=4000, Len=13, Data(0)=‘Serial Number’]
2028846124664 14:54:27.929 . Param [N=4, Name=“IVALUE”, Mode=INPUT, Type=SLONG, Size=0, Len=0, Data(0)=NULL]
2028846124686 14:54:27.929 . Param [N=5, Name=“SVALUE”, Mode=INPUT, Type=WCHAR, Size=4000, Len=0, Data(0)=NULL]
2028846124707 14:54:27.929 . Param [N=6, Name=“FVALUE”, Mode=INPUT, Type=DOUBLE, Size=0, Len=0, Data(0)=NULL]
2028846124731 14:54:27.929 . Param [N=7, Name=“BVALUE”, Mode=INPUT, Type=BINARY, Size=0, Len=0, Data(0)=NULL]
2028846127262 14:54:27.930 . ENTER SQLExecute
HSTMT 0x045843F0

2028846133699 14:54:27.932 . EXIT SQLExecute with return code 0 (SQL_SUCCESS)
HSTMT 0x045843F0

2028846136842 14:54:27.933 . ENTER SQLGetStmtAttrW
SQLHSTMT 0x045843F0
SQLINTEGER 1231
SQLPOINTER [Unknown attribute 1231]
SQLINTEGER 0
SQLINTEGER * 0x07FFF590

2028846140175 14:54:27.934 . EXIT SQLGetStmtAttrW with return code 0 (SQL_SUCCESS)
SQLHSTMT 0x045843F0
SQLINTEGER 1231
SQLPOINTER [Unknown attribute 1231]
SQLINTEGER 0
SQLINTEGER * 0x07FFF590 (4)

2028846143341 14:54:27.935 . ENTER SQLNumResultCols
HSTMT 0x045843F0
SWORD * 0x04CE5FFC

2028846146492 14:54:27.936 . EXIT SQLNumResultCols with return code 0 (SQL_SUCCESS)
HSTMT 0x045843F0
SWORD * 0x04CE5FFC (0)

2028846149794 14:54:27.937 . ENTER SQLGetStmtAttrW
SQLHSTMT 0x045843F0
SQLINTEGER 1231
SQLPOINTER [Unknown attribute 1231]
SQLINTEGER 0
SQLINTEGER * 0x07FFF5EC

2028846153018 14:54:27.938 . EXIT SQLGetStmtAttrW with return code 0 (SQL_SUCCESS)
SQLHSTMT 0x045843F0
SQLINTEGER 1231
SQLPOINTER [Unknown attribute 1231]
SQLINTEGER 0
SQLINTEGER * 0x07FFF5EC (4)

2028846156226 14:54:27.939 . ENTER SQLMoreResults
HSTMT 0x045843F0

2028846159378 14:54:27.940 . EXIT SQLMoreResults with return code 100 (SQL_NO_DATA_FOUND)
HSTMT 0x045843F0

2028846159731 14:54:27.940 << Execute [Command=“INSERT INTO dbo.System (
[Id], [Type], [Description], [iValue], [sValue], [fValue], [bValue])
VALUES (:Id, :ItemType, :Description, :iValue, :sValue, :fValue, :bValue)
”, ATimes=1, AOffset=0, RowsAffected=0, RowsAffectedReal=False, ErrorAction=5]
2028846159757 14:54:27.940 . TFDCustomCommand.InternalExecuteFinished [Command=“INSERT INTO dbo.System (
[Id], [Type], [Description], [iValue], [sValue], [fValue], [bValue])
VALUES (:Id, :ItemType, :Description, :iValue, :sValue, :fValue, :bValue)
”, AState=2, FRowsAffected=0]
2028846159784 14:54:27.940 << TFDCustomCommand.InternalExecute [Command=“INSERT INTO dbo.System (
[Id], [Type], [Description], [iValue], [sValue], [fValue], [bValue])
VALUES (:Id, :ItemType, :Description, :iValue, :sValue, :fValue, :bValue)
”, ATimes=0, AOffset=0, ABlocked=False]
2028846160040 14:54:27.940 >> TFDCustomCommand.Unprepare [Command=“INSERT INTO dbo.System (
[Id], [Type], [Description], [iValue], [sValue], [fValue], [bValue])
VALUES (:Id, :ItemType, :Description, :iValue, :sValue, :fValue, :bValue)
”]
2028846160066 14:54:27.940 >> Unprepare [Command=“INSERT INTO dbo.System (
[Id], [Type], [Description], [iValue], [sValue], [fValue], [bValue])
VALUES (:Id, :ItemType, :Description, :iValue, :sValue, :fValue, :bValue)
”]
[/quote]

You can see here that RowsAffected = 0 (and RowsAffectedReal = False, whatever that means).

12

@tobygroves how do you activate firedac tracing using datababstract? I try in the past without luck.

13

Sorry for all the spam in here but I figured the more info the better.

Just been comparing the above trace with that of the little test app I mentioned earlier and two things strike me.

Firstly, in my DA app, the whole statement seems to be created and prepared and then unprepared and destroyed before being created and prepared all over again - this doesn’t happen with my test app.

Secondly, and possibly critically, the sequence above is:

SQLExecute
SQLGetStmtAttrW
SQLNumResultCols

In my test app, there’s an extra one:

SQLExecute
SQLGetStmtAttrW
SQLRowCount
SQLNumResultCols

The SQLRowCount function isn’t present in the DA app trace but is in my test app. This looks to me like the function which retrieves the count of affected rows and the lack of it in the DA app is what’s causing the problem.

14

@DonaldShimoda I dropped a TFDMoniFlatFileClientLink component on my main data module which contains the TDAConnectionManager. I then set the Tracing property to True and added “MonitorBy=FlatFile” to the FireDAC connection string.

As long as the trace component is instantiated before the connection is activated it should work :slight_smile:

15

I don’t know about the need of dropping that component, as anydac don’t need it. Thanks for the tip!

16

No probs, more info here: http://docwiki.embarcadero.com/RADStudio/XE5/en/Tracing_and_Monitoring_(FireDAC)

17

Think I may have found it!

NOCOUNT was being set to ON by a previous query and not set back to OFF again.

It seems the FireDAC driver explicitly checks whether NOCOUNT is ON and, if so, doesn’t even bother trying to retrieve the count of affected rows.