Getting a timeout on a Masking set

dprince

My rule runs for about 12 mins and then times out.  Is there a setting I can change in Data Masker?  Or is this something that needs to be changed in SQL Server itself?

PlantBasedSQL

Hi @dprince Thank you very much for your question!

When you say "times out" could you let me know a bit more information please? (the exact error message, the type of rule you're running, how many rows in the table and how many columns you're trying to mask etc. would be super helpful!)
Also if you could share the version of Data Masker you're working with, that would be great please!

Just as a 'starter-for-10' - the most often timeout issues we see relate largely to rules trying to commit too many changes at once. The logic within Data Masker for SQL Server means it tries to dynamically calculate the maximum number of rows it can update in each batch, which as you can imagine, sometimes it thinks a bit much of itself!

The easiest way to fix this, for instance in an timing out Substitution rule, would be to:
1) Add an Index refresh rule and a Row Count refresh rule to rule block 00 (dependent on the trigger manager) - just so that DMS is always up to date on what it's running against!
2) Open the problematic rule and go to the Errors & Options tab, and where it specifies the Commit Frequency as 'Default' change this to user specified. About 100,000 I often feel does pretty well, and you can tweak it either side as neccessary!

If the above doesn't help, please feel free to confirm the above information and we'll do all we can to help out

Thank you very much!

dprince

Data Masker Version 6.2.4.1985.  I will try the commit frequency change and let you know the results.  Here is the segment from my error log file.  It looks like the number of rows attempting to be updated is 121,752.  Thanks!

07/01/2020 04:19:59 DMS_Common.RuleWorker: Exception in ProcessSubstitutionRule, Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding., trace=   at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)

   at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)

   at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)

   at System.Data.SqlClient.TdsParser.Run(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj)

   at System.Data.SqlClient.TdsParser.TdsExecuteTransactionManagerRequest(Byte[] buffer, TransactionManagerRequestType request, String transactionName, TransactionManagerIsolationLevel isoLevel, Int32 timeout, SqlInternalTransaction transaction, TdsParserStateObject stateObj, Boolean isDelegateControlRequest)

   at System.Data.SqlClient.SqlInternalConnectionTds.ExecuteTransactionYukon(TransactionRequest transactionRequest, String transactionName, IsolationLevel iso, SqlInternalTransaction internalTransaction, Boolean isDelegateControlRequest)

   at System.Data.SqlClient.SqlInternalTransaction.Commit()

   at System.Data.SqlClient.SqlTransaction.Commit()

   at DMS_Common.RuleWorker.ProcessSubstitutionRule(DMSRule_Controller controllerObj, DMSRule_Substitution subRuleObj)

07/01/2020 04:19:59 DMS_Common.RuleWorker: RuleWorkerLoop runID=underwriting.dbo.tables::202007010418321402268, workerID=1, Exception occurred, now handling

07/01/2020 04:19:59 DMS_Common.DMSRule_Substitution: Substitution Rule, RuleID=01-0005, RowsToProcess=17687, ColsToProcess=0, Total Rows/Second=0, RowOperations=0, Total Cols/Second=0, ColOperations=0, TotalProcessingTimeInSeconds=82

07/01/2020 04:19:59 DMS_Common.RuleWorker: HandleRuleWorkerLoopException: runID=underwriting.dbo.tables::202007010418321402268, workerID=1, rule=01-0005, SQL Server exception happened. Checking for ERRTRAP

07/01/2020 04:19:59 DMS_Common.RuleWorker: HandleRuleWorkerLoopException: runID=underwriting.dbo.tables::202007010418321402268, workerID=1, rule=01-0005, ENDING on SQL Server error

07/01/2020 04:19:59 DMS_Common.RuleWorker: HandleRuleWorkerLoopException runID=underwriting.dbo.tables::202007010418321402268, workerID=1, Rule 01-0005, exception=Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.

07/01/2020 04:19:59 DMS_Common.RuleWorker: ##########

07/01/2020 04:19:59 DMS_Common.RuleWorker: SQL Code for Rule 01-0005:UPDATE [underwriting_TMP].[dbo].[TblRequestToBind] set [Address]=CASE WHEN [Address] IS NULL THEN cast(NULL as nvarchar(150)) WHEN [Address] = '' THEN '' ELSE @u_Address END, [Phone]=CASE WHEN [Phone] IS NULL THEN cast(NULL as nvarchar(50)) WHEN [Phone] = '' THEN '' ELSE @u_Phone END, [Fax]=CASE WHEN [Fax] IS NULL THEN cast(NULL as nvarchar(50)) WHEN [Fax] = '' THEN '' ELSE @u_Fax END, [InsuredName]=CASE WHEN [InsuredName] IS NULL THEN cast(NULL as nvarchar(250)) WHEN [InsuredName] = '' THEN '' ELSE @u_InsuredName END, [DBA]=CASE WHEN [DBA] IS NULL THEN cast(NULL as nvarchar(250)) WHEN [DBA] = '' THEN '' ELSE @u_DBA END, [E-Mail]=CASE WHEN [E-Mail] IS NULL THEN cast(NULL as nvarchar(255)) WHEN [E-Mail] = '' THEN '' ELSE @u_EÄDMÅMail END where [AutoID] = @r_AutoID

07/01/2020 04:19:59 DMS_Common.RuleWorker: ##########

07/01/2020 04:19:59 DMS_Common.RuleWorker: 

07/01/2020 04:19:59 DMS_Common.DMSRuleSchedulingEngine: ProcessAllControllersAllRules RunID=underwriting.dbo.tables::202007010418321402268, Controller 01-0001, Rule block 01, Rule 01-0005, ERRORED, now dequeueing

07/01/2020 04:30:27 DMS_Common.DMSRule_Substitution: Substitution Rule, RuleID=01-0004, RowsToProcess=121752, ColsToProcess=0, Total Rows/Second=171, RowOperations=121752, Total Cols/Second=1371, ColOperations=974016, TotalProcessingTimeInSeconds=710

07/01/2020 04:30:27 DMS_Common.RuleWorker: ProcessSubstitutionRule: runID=underwriting.dbo.tables::202007010418321402268, workerID=0, rule=01-0004, COMPLETE. Total rows substituted=121752

07/01/2020 04:30:27 DMS_Common.RuleWorker: RunTheRule runID=underwriting.dbo.tables::202007010418321402268, workerID=0, rule execution ends SUCCESS

07/01/2020 04:30:27 DMS_Common.RuleWorker: ExecuteRule runID=underwriting.dbo.tables::202007010418321402268, workerID=0, Rule 01-0004, COMPLETED, Success

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: ProcessAllControllersAllRules RunID=underwriting.dbo.tables::202007010418321402268, Controller 01-0001, Rule block 01, Rule 01-0004, COMPLETE, now dequeueing

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: ProcessAllControllersAllRules(stop C) RunID=underwriting.dbo.tables::202007010418321402268, Controller 01-0001, Rule block 01. Rule processing stopped due to an error in rule 01-0005

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: HandleWorkerManagerLoopException runID=underwriting.dbo.tables::202007010418321402268, StackTrace=   at DMS_Common.DMSRuleSchedulingEngine.ProcessAllControllersAllRules(RuleStageEnum currentStage)

   at DMS_Common.DMSRuleSchedulingEngine.WorkerManagerLoop()

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: Memory Diagnostics:

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: Memory Diagnostics: nonpagedSystemMemorySize=47Kb, pagedMemorySize=109520Kb, pagedSystemMemorySize=533Kb, peakPagedMemorySize=113480Kb, VirtualMemorySize64=695656Kb, peakVirtualMemorySize=711548Kb, peakWorkingSet=129976Kb, workingSet=126556Kb, maxWorkingSet = 1380Kb, minWorkingSet =200Kb

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: HandleWorkerManagerLoopException runID=underwriting.dbo.tables::202007010418321402268, Rule run failed

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: HandleWorkerManagerLoopException runID=underwriting.dbo.tables::202007010418321402268, Error=Rule execution stopped due to error in rule 01-0005

07/01/2020 04:30:27 DMS_CmdLine.CmdLineMain: WorkerManagerReport for RunID=underwriting.dbo.tables::202007010418321402268, Status=RULERUN_FAILED

07/01/2020 04:30:27 N2KCommon.MaskingRunStateMachine: RunStateMachineBase: state change. Old=SETRUNSTATE_RUNNING new=SETRUNSTATE_FAILED

07/01/2020 04:30:27 DMS_CmdLine.CmdLineMain: Rule Run FAILED, please see the log file, now closing

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: WorkerManagerLoop:, Processing stopped due to failure, now resetting worker manager

07/01/2020 04:30:27 DMS_Common.DMSRuleSchedulingEngine: ResetWorkerSlotList called, wantThreadRestart=False

PlantBasedSQL

Thanks for sending this across @dprince - this does look like something that could be improved with a manual commit frequency, let me know how you get on!

dprince

I see the "Commit Frequency", but there is not place for "default".  It is already set to 1000 by default in each of the rules.  Do I need a newer version of Data Masker?

PlantBasedSQL

Aha @dprince apologies I completely missed where you mentioned your version!!
Yes please, the latest version of DMS is significantly further ahead! Please feel free to upgrade first and THEN give this a go!