11 replies to this topic

[Marlon]

Running the same code with PROIV v8.3 and v9.5 connecting to SQL SERVER 2016, we are getting persistent write errors in the v9.5 system with just one user connected.  We suspect it's a setting that is in the .ini on v8 and isn't set in v9.

 

This is what our v8 ini looks like for SQL Server:

 

[ENVIRONMENT]

SQL_DBNAME=SVR04_DS

SQL_AGGREGATE_KEY=Y
SQL_CURSORS=AUTO
SQL_NOSIG=Y
SQL_TRANSACTION_ERROR=Y
SQLSERVE_SELECT_FOR_UPDATE=TRUE
TP_ROLLBACK=Y

 

[Database - SQLDEFAULT]
PRODB_CHARSET=7
FILETYPE=SQLSERVE
CONNECTION=patch_windows/patch_windows

 

we have no value for SQL_ADD_UPDLOCK (which appears to be required for 2008 only according to the PROIV v9 documentation)

 

and this is what we have in the dashboard on v9:

 

Database

  Default Database

    Enable Rollback - enabled

 

  Driver

    General Database Settings

      Display Lock Message - enabled

      Display Error Message - enabled

      Cursors: Auto

      Timeout: -1

    SQL Server Configuration

      Enable Table Locking - enabled

      Read Uncommitted - enabled

      Select For Update - enabled

      Insert UpdLock - NOT enabled

      Startup Arguments - blank

 

Logical Databases

  SQLDEFAULT

    Database Type SQLSERVE

    Connection String patch_windows/patch_windows/SVR04_DS

    Collation 7

    Honour Locks - enabled

 

Any suggestions as to what we should be setting differently or are missing would be much appreciated.

[Marlon]

Whilst a PROIV trace doesn't give any useful information, if the tracing is quite detailed, e.g. level 15, it slows the system enough that we don't get the write errors, whereas with the trace level at around 3 the errors still occur.

[Richard Bassett]

What are the write errors you're getting?

For example what is in @SYSERRTEXT?

 

(Caveat:  I've never used SQL Server but I'm assuming ProIV's behaviour is largely database-independent)

[Marlon]

This is what we get from PROIV:

Error - Text       Error writing file                      

         @ERR

         @ERRTEXT

 

 

and this is a PROIV level 5 SQL trace:

 

   0| 0|120231.460-==== OdbcBindParameter returned , sqllen = 6, field_len = 6

 

   0| 0|120231.460-==== << ODBCExtType: Mapped PRO-IV data type 1 to generic data type 1

 

   0| 0|120231.460-==== pVar->sqlscale = 0000 : col_scale = 00

 

   0| 0|120231.460-==== SQLSRVCmdIBindAux calling OdbcBindParameter: hstmt 117405600, col 51, cvtype 1, col_type 1, sqlprec 3, col_scale 0, value <   >, Bindoffset 0

 

   0| 0|120231.460-==== SQLBindParameter: StmtHandle = 0000000006FF77A0 : ParamNum = 51 : ParamType = SQL_PARAM_INPUT(1) : CDataType = SQL_C_CHAR(1) : SQLDataType = SQL_CHAR(1) : ValueSize = 3 : Decimals = 0 : ValueBufferSize = 3 : Ind = 3

   0| 0|120231.460-==== InputValue = '   '

   0| 0|120231.460-==== SQLBindParameter. : Return code = 0

   0| 0|120231.460-==== 0

 

   0| 0|120231.460-==== OdbcBindParameter returned , sqllen = 3, field_len = 3

 

   0| 0|120231.460-==== >> dbApiCurOpen hCmd(00000000063B9AA8)

   0| 0|120231.460-==== ODBCCmdXRowAlloc

   0| 0|120231.460-==== >> dbApiInitCurClose hCmd(00000000063B9AA8)

   0| 0|120231.460-==== SQLExecute. StmtHandle = 0000000006FF77A0

   0| 0|120231.461-==== SQLExecute : Return code = -1

   0| 0|120231.461-==== 0

 

   0| 0|120231.461-==== dbApiCmdGetDB

   0| 0|120231.461-==== SQLGetDiagRec. HandleType = 3 : Handle = 0000000006FF77A0 : RecNumber = 1 : MsgMaxSize = 511

   0| 0|120231.461-==== SQLGetDiagRec : Return code = 0. : HandleType = 3 : Handle = 0000000006FF77A0 : RecNumber = 1 : SQLSTATE = 42000 : NativeError = 1222 : ErrorMessage = [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Lock request time out period exceeded. : ErrorMsgmaxSize = 511 : ErrorMsgSize = 92

   0| 0|120231.461-==== 0

 

   0| 0|120231.461-==== OdbcError: MsgBuf = [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Lock request time out period exceeded.

 

   0| 0|120231.461-==== OdbcError: nat_err 1222, SqlState[0] 42000

 

   0| 0|120231.461-==== SQLGetDiagRec. HandleType = 3 : Handle = 0000000006FF77A0 : RecNumber = 2 : MsgMaxSize = 419

   0| 0|120231.461-==== SQLGetDiagRec : Return code = 0. : HandleType = 3 : Handle = 0000000006FF77A0 : RecNumber = 2 : SQLSTATE = 01000 : NativeError = 3621 : ErrorMessage = [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]The statement has been terminated. : ErrorMsgmaxSize = 419 : ErrorMsgSize = 88

   0| 0|120231.461-==== 0

 

   0| 0|120231.461-==== OdbcError: MsgBuf = [Microsoft][ODBC Driver 17 for SQL Server][SQL Server]Lock request time out period exceeded.[Microsoft][ODBC Driver 17 for SQL Server][SQL Server]The statement has been terminated.

 

   0| 0|120231.461-==== OdbcError: nat_err 3621, SqlState[0] 01000

 

   0| 0|120231.461-==== SQLGetDiagRec. HandleType = 3 : Handle = 0000000006FF77A0 : RecNumber = 3 : MsgMaxSize = 331

   0| 0|120231.461-==== SQLGetDiagRec : Return code = 100. : HandleType = 3 : Handle = 0000000006FF77A0 : RecNumber = 3 : SQLSTATE = 01000 : NativeError = 3621 : ErrorMessage =  : ErrorMsgmaxSize = 331 : ErrorMsgSize = 0

   0| 0|120231.461-==== 0

 

The relevant part seems to be the lock request time out exceeded.  This is probably why trace levels above level 5 stop the error from happening.

[Richard Bassett]

I'm not sure I can help much as several things here don't seem to make sense, at least not to me with my limited knowledge of SQL Server.  For what it's worth these are the things I found odd:

 

Are you saying you're getting lock timeouts with only one application/session process connected to the database (or at least using some part of the database nothing else is using) ?

Why would you have "Table Locking" and "Read Uncommitted" enabled?

Why are there timeouts at all if "Timeout" is configured to -1?

Why would slowing the system with more detailed tracing help?  (intuitively you might think it would make timeouts worse?)

[Richard Bassett]

ALTHOUGH... something I just noticed now..

 

..assuming those are timestamps on the left hand side of your trace above, there appears to be NO DELAY AT ALL before the database says you are timed out..

 

..which very strongly suggests that somehow the timeout is actually set to ZERO, which would mean a lock results in immeditate failure..

 

..and that certainly would explain the unexpected problems, and why detailed tracing makes the problem less likely..

 

(although it still wouldn't explain how a single application session/process could encounter a lock, if that's really the case)

Edited by Richard Bassett, 13 October 2020 - 06:06 PM.

[Marlon]

Richard,

Thanks for your analysis.

 

In answer to your questions.

 

"Are you saying you're getting lock timeouts with only one application/session process connected to the database (or at least using some part of the database nothing else is using) ?"

Yes, we are getting table locking with only one connection to the database.  It's a timing test so nothing else runs at the same time.

 

"Why would you have "Table Locking" and "Read Uncommitted" enabled?"

Are you saying having both of these enabled doesn't make sense?  I did retest with Red Uncommitted disabled and it didn't make any difference.

 

"Why are there timeouts at all if "Timeout" is configured to -1?"

According to the PROIV help, -1 means "Report record lock immediately the SQL command is issued to the database" so that is consistent with getting the timeout messages.  0 means "Block indefinitely until the database releases the record lock" which would be consistent with not getting an error reported, it just waits until the lock's cleared.

 

"Why would slowing the system with more detailed tracing help?  (intuitively you might think it would make timeouts worse?)"

Because PROIV is running more slowly so there's enough time for the lock to be released.  Of course, this still doesn't explain why a process is being locked out by itself.

 

"assuming those are timestamps on the left hand side of your trace above, there appears to be NO DELAY AT ALL before the database says you are timed out...which very strongly suggests that somehow the timeout is actually set to ZERO, which would mean a lock results in immeditate failure...and that certainly would explain the unexpected problems, and why detailed tracing makes the problem less likely."

A timeout value of  -1 means 'report immediately' so the behaviour is consistent with that.

 

Using a timeout of 0 has 'fixed' the problem, i.e. the write error is no longer reported but I'm not convinced this version of PROIV, v9.5, is actually behaving itself.

[Richard Bassett]

Hi Marlon,

 

OK, so if Timeout -1 in ProIV means "give up instantly on encountering a lock" then that makes sense of the observed behaviour.  However, that doesn't sound like a setting that is of very much use in the real world?  Also, I notice that ProIV's use of -1 and 0 here seems to be the exact opposite of SQL/Server - which seems to use -1 to mean indefinite wait and 0 to mean no wait (see e.g. https://docs.microso...ql-server-ver15 ).

 

Given that level of ambiguity, perhaps I should ask here what is really meant by "Table Locking" ?  For me, that would normally mean locking entire tables instead of only locking the records (rows) that you read and write.  Again, in my experience at least, that's an approach that isn't of much use in the real world.

 

Regarding "Table Locking" and read uncommitted, I was asking why one would want to set either of them, not suggesting the choices were connected.  In most circumstances I would consider both of them unhelpful.  Also, I don't see that read uncommitted offers any advantages (only disadvantages) in any database that has multiversioned concurrency control, which I thought SQL/Server had for a long time now?

 

It does seem dubious that a process is apparently able to lock against itself when then is an 'immediate' timeout but this problem disappears once you wait on locks.  I can only imagine something subtle and confusing is going on, such as the actual release of locks happening 'asynchronously' in the background and the process maybe impatiently tripping over locks from its own preceding transaction that haven't quite been released yet (this might be plausible if there is some kind of asynchronous commit being used for performance or as a default).  This hypothesis could also be consistent with the tracing slowing everything down causing the problem to be masked.

Edited by Richard Bassett, 14 October 2020 - 07:29 PM.

[Marlon]

Hi Richard,

This

"It does seem dubious that a process is apparently able to lock against itself when then is an 'immediate' timeout but this problem disappears once you wait on locks.  I can only imagine something subtle and confusing is going on, such as the actual release of locks happening 'asynchronously' in the background and the process maybe impatiently tripping over locks from its own preceding transaction that haven't quite been released yet (this might be plausible if there is some kind of asynchronous commit being used for performance or as a default).  This hypothesis could also be consistent with the tracing slowing everything down causing the problem to be masked."

is where I think we're going with our thinking, too.

[Marlon]

SQLSERVE_TABLE_LOCKING is the v8 .ini setting for the Enable Table Locking dasboard option.  According to PROIV help topic 720072, it's enabled by default from PROIV v6.1.57.0 release onwards so we've been using it in the past without knowing it.

[Neil Barber]

Hi Marlon

 

Is SQL_NOSIG enabled in your v9 configuration?

 

 

Regards

[Marlon]

Hi Marlon

 

Is SQL_NOSIG enabled in your v9 configuration?

 

 

Regards

Hi Neil,

I don't know.  The PROIV v9 help only tells you what the equivalent is, proiv.virtualMachine.database.driver.general.enableSQLAlarm, not where to set it so I don't know what we have. (To say I'm not enamoured with the v9 help would be an understatement).