Issues with TM1RunTI and different user accounts

[PavoGa]

Our master process reads from a cube that contains the sub-process to execute along with its parameter values being passed. It writes a batch file that is then called through EXECUTECOMMAND. The batch file is executed under different TM1 credentials, a Process Admin account we'll call it. This is the first batch file:

Code: Select all

tm1runti -i "E:\Scripts\tm1RunTI_Config.cfg" -process "Pool - Update Pool Dimension" pDebug=1 pParameters="" pParameterValues="" pParameterLimit=0 -connect "FY2017_DEV_01" -user "FPRP Process Admin" -passwordfile "\\usher6114\e$\scripts\tm1cipher_FPRP_Process_admin.dat" -passwordkeyfile "\\usher6114\e$\scripts\tm1key_FPRP_Process_admin.dat"

When the master process is executed by a client with admin rights, it runs fine. IF we login to Architect as the process admin client, which does not have admin rights, the process hangs. Here are the lines from the server log:

21164 [1dc] INFO 2016-02-29 18:11:26.972 TM1.Process Process "Pool - Ctrl" executed by user "FPRP Process Admin"
21164 [1dc] INFO 2016-02-29 18:11:26.972 TM1.Process Process "adm_Version Validation" run from process "Pool - Ctrl" by user "FPRP Process Admin"
21164 [1dc] INFO 2016-02-29 18:11:26.972 TM1.Process Process "System - Process Stats Update" run from process "adm_Version Validation" by user "FPRP Process Admin"
21164 [1dc] INFO 2016-02-29 18:11:26.988 TM1.Process Process "System - Process Stats Update": finished executing normally, elapsed time 0.02 seconds
21164 [1dc] INFO 2016-02-29 18:11:26.988 TM1.Process Process "adm_Version Validation": finished executing normally, elapsed time 0.02 seconds
17736 [1de] INFO 2016-02-29 18:11:27.378 TM1.Process Process "Pool - Update Pool Dimension" executed by user "FPRP Process Admin"
17736 [1de] INFO 2016-02-29 18:11:27.596 TM1.SQLAPI Checking Driver Capabilities for database "DTCPSR"
17736 [1de] INFO 2016-02-29 18:11:27.596 TM1.SQLAPI Driver supports SQLFetchScroll
17736 [1de] INFO 2016-02-29 18:11:27.690 TM1.Process Process "System - Process Stats Update" run from process "Pool - Update Pool Dimension" by user "FPRP Process Admin"
17736 [1de] INFO 2016-02-29 18:11:27.706 TM1.Process Process "System - Process Stats Update": finished executing normally, elapsed time 0.02 seconds
17736 [1de] INFO 2016-02-29 18:11:27.706 TM1.Process Process "Pool - Update Pool Dimension": finished executing normally, elapsed time 0.33 seconds

The problem is the master process just sits there at this point. It is like the batch file does not complete and return.

However, if I call the same batchfile created above with a one-off TI process that only runs the EXECUTECOMMAND function, it runs fine, the bath file terminates and here is the server log:

21164 [1dc] INFO 2016-02-29 18:19:53.685 TM1.Process Process "tmp_Ty" executed by user "FPRP Process Admin"
5056 [1e4] INFO 2016-02-29 18:19:54.091 TM1.Process Process "Pool - Update Pool Dimension" executed by user "FPRP Process Admin"
5056 [1e4] INFO 2016-02-29 18:19:54.294 TM1.SQLAPI Checking Driver Capabilities for database "DTCPSR"
5056 [1e4] INFO 2016-02-29 18:19:54.294 TM1.SQLAPI Driver supports SQLFetchScroll
5056 [1e4] INFO 2016-02-29 18:19:54.372 TM1.Process Process "System - Process Stats Update" run from process "Pool - Update Pool Dimension" by user "FPRP Process Admin"
5056 [1e4] INFO 2016-02-29 18:19:54.387 TM1.Process Process "System - Process Stats Update": finished executing normally, elapsed time 0.02 seconds
5056 [1e4] INFO 2016-02-29 18:19:54.387 TM1.Process Process "Pool - Update Pool Dimension": finished executing normally, elapsed time 0.30 seconds
21164 [1dc] INFO 2016-02-29 18:19:54.434 TM1.Process Process "tmp_Ty": finished executing normally, elapsed time 0.75 seconds

[qml]

To get a more complete picture please get tm1top (or Operations Console) logs or screenshots and start logging lock exceptions (add log4j.logger.TM1.Lock=DEBUG in tm1s-log.properties). It looks to me like you could be experiencing lock contention. For example, the logoff action of the subprocess thread could be in a wait state leading to the parent thread never receiving a return value. BTW, what value do you put as the Wait parameter of the ExecuteCommand function?

Also, why are you using tm1runti to run the subprocess? It makes sense in certain circumstances like running TIs in parallel, but from what I see you're just executing that one instance of the subprocess, so unless you have a good reason for doing it like that you might instead just use ExecuteProcess and avoid nasty locking altogether. With tm1runti you need to be very careful and make sure you understand how TM1 locking works.

[PavoGa]

To get a more complete picture please get tm1top (or Operations Console) logs or screenshots and start logging lock exceptions (add log4j.logger.TM1.Lock=DEBUG in tm1s-log.properties). It looks to me like you could be experiencing lock contention. For example, the logoff action of the subprocess thread could be in a wait state leading to the parent thread never receiving a return value. BTW, what value do you put as the Wait parameter of the ExecuteCommand function?

Also, why are you using tm1runti to run the subprocess? It makes sense in certain circumstances like running TIs in parallel, but from what I see you're just executing that one instance of the subprocess, so unless you have a good reason for doing it like that you might instead just use ExecuteProcess and avoid nasty locking altogether. With tm1runti you need to be very careful and make sure you understand how TM1 locking works.

I tried to attach screen shots of tm1top yesterday, but ran out of time and was having trouble doing so. I'll capture the log.

With regards to the second question, it is because we are isolating (per recommendations on this forum) the metadata updates within the first few seconds of the overall processing. What was happening before was once the master process kicked off and the dimensions started getting updated, users were locked out from logging in until the entire process completed. We have reduced that window to just a few seconds. In that respect, the strategy, as recommended, seems valid.

I'll get those logs and attach. Thank you. This is the first time I've run into this.

[PavoGa]

Well I'll be. There is a lock contention. Log when bat file is executed from "Pool - Ctrl":

13056 [1ff] INFO 2016-03-01 08:15:00.769 TM1.Process Process "Pool - Ctrl" executed by user "FPRP Process Admin"
13056 [1ff] INFO 2016-03-01 08:15:00.769 TM1.Process Process "adm_Version Validation" run from process "Pool - Ctrl" by user "FPRP Process Admin"
13056 [1ff] INFO 2016-03-01 08:15:00.769 TM1.Process Process "System - Process Stats Update" run from process "adm_Version Validation" by user "FPRP Process Admin"
13056 [1ff] INFO 2016-03-01 08:15:00.769 TM1.Process Process "System - Process Stats Update": finished executing normally, elapsed time 0.00 seconds
13056 [1ff] INFO 2016-03-01 08:15:00.785 TM1.Process Process "adm_Version Validation": finished executing normally, elapsed time 0.02 seconds
21028 [201] INFO 2016-03-01 08:15:01.237 TM1.Process Process "Pool - Update Pool Dimension" executed by user "FPRP Process Admin"
21028 [201] INFO 2016-03-01 08:15:01.533 TM1.SQLAPI Checking Driver Capabilities for database "DTCPSR"
21028 [201] INFO 2016-03-01 08:15:01.533 TM1.SQLAPI Driver supports SQLFetchScroll
21028 [201] INFO 2016-03-01 08:15:01.643 TM1.Process Process "System - Process Stats Update" run from process "Pool - Update Pool Dimension" by user "FPRP Process Admin"
21028 [201] INFO 2016-03-01 08:15:01.658 TM1.Process Process "System - Process Stats Update": finished executing normally, elapsed time 0.02 seconds
21028 [201] INFO 2016-03-01 08:15:01.658 TM1.Process Process "Pool - Update Pool Dimension": finished executing normally, elapsed time 0.42 seconds
21028 [201] DEBUG 2016-03-01 08:15:01.736 TM1.Lock.Exception Contention encountered attempting to acquire lock (0x000000007C624810) on object [Client "FPRP Process Admin", addr=0x000000007C63C810, index=R-2462] in IX mode at ..\tm1_r7s\TM1Thread.cpp:1332 during function 'Unknown'.
Entering wait state 'IXCur'.
Blocked by the following 0 threads:

16420 [203] DEBUG 2016-03-01 08:15:02.126 TM1.Lock.Exception Contention encountered attempting to acquire lock (0x000000007C624810) on object [Client "FPRP Process Admin", addr=0x000000007C63C810, index=R-2462] in READONLY mode at ..\tm1_r7s\TM1ClientImpl.cpp:780 during function 'SystemServerConnect'.
Entering wait state 'IXC'.
Blocked by the following 1 thread:
Thread 21028 holds the lock in IX mode

16420 [203] DEBUG 2016-03-01 08:15:02.126 TM1.Lock.Exception CommitActionLog::Rollback: Called for thread '16420' of user '<UNKNOWN>' executing function code '1'.
13056 [1ff] DEBUG 2016-03-01 08:16:15.929 TM1.Process ExecuteProcedures: Cancel request received.
13056 [1ff] DEBUG 2016-03-01 08:16:15.929 TM1.Lock.Exception CommitActionLog::Rollback: Called for thread '13056' of user 'FPRP Process Admin' executing function code '196'.

Log from when running just the batch file from "tmp_Ty":

13056 [1ff] INFO 2016-03-01 08:42:51.586 TM1.Process Process "tmp_Ty" executed by user "FPRP Process Admin"
22828 [206] INFO 2016-03-01 08:42:51.991 TM1.Process Process "Pool - Update Pool Dimension" executed by user "FPRP Process Admin"
22828 [206] INFO 2016-03-01 08:42:52.210 TM1.SQLAPI Checking Driver Capabilities for database "DTCPSR"
22828 [206] INFO 2016-03-01 08:42:52.210 TM1.SQLAPI Driver supports SQLFetchScroll
22828 [206] INFO 2016-03-01 08:42:52.319 TM1.Process Process "System - Process Stats Update" run from process "Pool - Update Pool Dimension" by user "FPRP Process Admin"
22828 [206] INFO 2016-03-01 08:42:52.334 TM1.Process Process "System - Process Stats Update": finished executing normally, elapsed time 0.02 seconds
22828 [206] INFO 2016-03-01 08:42:52.334 TM1.Process Process "Pool - Update Pool Dimension": finished executing normally, elapsed time 0.34 seconds
13056 [1ff] INFO 2016-03-01 08:42:52.412 TM1.Process Process "tmp_Ty": finished executing normally, elapsed time 0.83 seconds

Here is the code for Pool Ctrl:

Code: Select all

###################
# parameters
# pDebug = debug flag  DEFAULT to 0
# pLoadFilter = what will be loaded.  1 = ALL, 2 = Actuals Only, 3 = Plan Only (anything other than 2 or 3 will treated as a 1.
# pExecutionMode = what portion will execute.  1 = ALL, 2 = Load Matrix Only, 3 = Load Actuals Only, 4 = Waterfall Only, 5 = All except Load Matrix
# pProcessExecutionCube = the source cube that determines what subprocesses to call. DEFAULT = }System - Process Execution.
####################

NumericGlobalVariable('ProcessReturnCode');
NumericGlobalVariable('DataMinorErrorCount');

### Inititalize standard variables
strProcessName = GetProcessName();
tNow = NOW;
strNow = TIMST(NOW, '\Y\m\d\h\i\s');
strEnvironment = '';
strErrLogFolder = CELLGETS('Control Globals', 'Value', 'OutputPath');
strPrologErrLogFile = strErrLogFolder | strProcessName | '_PRO_err.log';
strMetaErrLogFile = strErrLogFolder | strProcessName | '_MET_err.log';
strDataErrLogFile = strErrLogFolder | strProcessName | '_DAT_err.log';
strEpilogErrLogFile = strErrLogFolder | strProcessName | '_EPI_err.log';
strDataFolder = CELLGETS('Control Globals', 'Value', 'TestOutputPath');
strTmp = 'tmp_' | strProcessName | strNow;
strEmailProcess = 'eMail - Ctrl';
cubEmail = 'eMail - Configuration';
nErrorFlag = 0;
nRecordsProcessed = 0;
nDataSourceCount = 0;

### Inititalize Other variables
 cubProcessExecution = pProcessExecutionCube;
 
 vwProcessExecution = strTmp;
 
 
dimVersions = 'Versions';
dimProcesses = '}Processes';
dimCounter = 'Counter';
dimProcessExecMeasure = '}System - Process Execution Measure';

subProcesses = strTmp;
subCounter = strTmp;
subProcessExecMeasure = strTmp;
subParameterList = strTmp | 'b';

strProcessToRunMeasure = 'Process To Run';
strParameterDelimiter = '|';
strScriptFolder = CELLGETS('Control Globals', 'Value', 'ScriptPath');
strEnvironment = '"' | CELLGETS('}System - Environment', '0', 'Text') | '"';
strTM1RunTI_ConfigFile = '"E:\Scripts\tm1RunTI_Config.cfg"';
strTM1RunTI_User = '"FPRP Process Admin"';
strTM1RunTI_PasswordFile = '"' | strScriptFolder | 'tm1cipher_FPRP_Process_admin.dat"';
strTM1RunTI_KeyFile = '"' | strScriptFolder | 'tm1key_FPRP_Process_admin.dat"';


# 12/4/15 Ty: add version validation to this process.
strVersion = DimensionElementPrincipalName(dimVersions, CELLGETS('Control Globals', 'Value', 'Pool Adjustments Source Version'));

EXECUTEPROCESS('adm_Version Validation',
	'pDebug', pDebug,
	'pVersion', strVersion);

IF (ProcessReturnCode <> ProcessExitNormal());
	ASCIIOUTPUT(strPrologErrLogFile, NumberToString(ProcessReturnCode));
	PROCESSERROR;
ENDIF;

# validate pExecutionMode.  Any value other than 1 through 4 result in a 1.
IF (pExecutionMode < 1 % pExecutionMode > 5);
	pExecutionMode = 1;
ENDIF;

### Main
strMDX = 'UNION( 
	{[}System - Process Execution Measure].currentmember}
	, EXCEPT(
		TM1FILTERBYPATTERN( TM1SUBSETALL([}System - Process Execution Measure]), ''sParam*'')
		, TM1FILTERBYPATTERN( TM1SUBSETALL([ }System - Process Execution Measure]), ''sParamName*''))
	, ALL)';
ASCIIOUTPUT(strPrologErrLogFile,strMDX);
SubsetCreateByMDX(subParameterList, strMDX);
SubsetElementDelete(dimProcessExecMeasure, subParameterList, 1);
nParameterListSize = SubsetGetSize(dimProcessExecMeasure, subParameterList);

SubsetCreate(dimProcesses, subProcesses);
SubsetElementInsert(dimProcesses, subProcesses, strProcessName, 1);

strMDX = 'UNION(
	{[Counter].currentmember}
	, TM1FILTERBYLEVEL( TM1SUBSETALL( [Counter] ), 0)
	, ALL)';
SubsetCreateByMDX(subCounter, strMDX);
SubsetElementDelete(dimCounter, subCounter, 1);

SubsetCreate(dimProcessExecMeasure, subProcessExecMeasure);
SubsetElementInsert(dimProcessExecMeasure, subProcessExecMeasure, strProcessToRunMeasure, 1);

ViewCreate(cubProcessExecution, vwProcessExecution);

ViewSubsetAssign(cubProcessExecution, vwProcessExecution, dimProcesses, subProcesses);
ViewSubsetAssign(cubProcessExecution, vwProcessExecution, dimCounter, subCounter);
ViewSubsetAssign(cubProcessExecution, vwProcessExecution, dimProcessExecMeasure, subProcessExecMeasure);

DataSourceNameForServer = cubProcessExecution;
DataSourceType = 'VIEW';
DataSourceCubeView = vwProcessExecution;
DataSourceASCIIQuoteCharacter = '';

ViewExtractSkipZeroesSet(cubProcessExecution, vwProcessExecution, 1);



IF(pDebug = 1);
	ASCIIOUTPUT(strPrologErrLogFile, 'Version: ' | strVersion);
	ASCIIOUTPUT(strPrologErrLogFile, 'Filter.: ' | NumberToString(pLoadFilter));
ENDIF;

DATA section:

Code: Select all

nDataSourceCount = nDataSourceCount + 1;
strSubProcess = SValue;

# IF the execution flag is "N" then ITEMSKIP.
# IF the execution mode does not contain the pExecutionMode value, then ITEMSKIP
strExecuteFlag = CELLGETS(cubProcessExecution, vControlName, vCounter, 'Execute Flag');
strExecutionMode = CELLGETS(cubProcessExecution, vControlName, vCounter, 'sParam10');
IF (strExecuteFlag @<> 'Y' % SCAN(NumberToString(pExecutionMode), strExecutionMode) = 0);
	ASCIIOUTPUT(strDataErrLogFile, 'Skipped......: ' | strSubProcess);
	ASCIIOUTPUT(strDataErrLogFile, 'ExecuteFlag..: ' | strExecuteFlag);
	ASCIIOUTPUT(strDataErrLogFile, 'ExecutionMode: ' | strExecutionMode);
	ITEMSKIP;
ENDIF;

# Special Handling
# Pool - Load Actuals requires the pLoadFilter parameter based on the Entry to this process.
IF (strSubProcess @= 'Pool - Load Actuals' % 
		strSubProcess @= 'Pool - Waterfall 1 Ctrl');
	CELLPUTS(NumberToString(pLoadFilter), cubProcessExecution, vControlName, vCounter, 'sParam1');
ENDIF;

# retrieve parameter values from cube 
# string 
# String Parameter 1 is reserved and used above to determine if the process should be run according to the execution mode flag.
# String parameter values are used to pass values to the subprocesses.  If a value will be used as numeric, the subprocess will convert it.
# the nParametersToPass is used to count the number of parameters being passed to the sub process.
# Parameter names must be populated in order, or parameters can be ignored and skipped.
nSParamCnt = 1;
nNParamCnt = 1;
strParameterValues = '';
nDebugOverride = CELLGETN(cubProcessExecution, vControlName, vCounter, 'Debug Override');
strVersionFlag = CELLGETS(cubProcessExecution, vControlName, vCounter, 'Version Flag');
strVersionOverride = CELLGETS(cubProcessExecution, vControlName, vCounter, 'Version Override');
strTM1RunFlag = CELLGETS(cubProcessExecution, vControlName, vCounter, 'TM1RunTI_Flag');
nParametersToPass = 0;

# loops through the subset of the process execution measure and builds a string of parameter values and names to pass to a called process.
i = 1;
nFirstParameter = 1;
strParameterNames = '';
strParameterValues = '';
nParametersToPass = 0;
WHILE (i <= nParameterListSize);
	strParamEL = SubsetGetElementName(dimProcessExecMeasure, subParameterList, i);
	strParamNameEL = 'sParamName' | SUBST(strParamEL, 7, LONG(strParamEL) - 6);
	IF (pDebug=1);
		ASCIIOUTPUT(strDataErrLogFile, strParamEL, strParamNameEL);
	ENDIF;
	strParamName = CELLGETS(cubProcessExecution, vControlName, vCounter, strParamNameEL);
	IF (strParamName @<> '');
		strParameterNames = IF(nFirstParameter = 1, strParamName, strParameterNames | '|' | strParamName);
		strParameterValues = IF(nFirstParameter = 1, CELLGETS(cubProcessExecution, vControlName, vCounter, strParamEL), strParameterValues | '|' | CELLGETS(cubProcessExecution, vControlName, vCounter, 'sParam2'));
		nParametersToPass = nParametersToPass + 1;
		nFirstParameter = 0;
	ENDIF;
	i = i + 1;
END;

# If the subprocess is flagged to take the version dimension, then pass along strVersion or the strVersionOverride if the override is valid.  Else run the sub without a version parameter.
# an override is provided, it is validated ONLY that it exists in the versions dimension.  Version override in the cube skips normal validations.	
### 02/25/16 TFS842395 Ty: Using a value from Process Execution, determine whether to run the process through TM1RunTI or just as a subprocess here.
# ASCIIOUTPUT(strDataErrLogFile, strSubProcess, NumberToString(pDebug), IF(strVersionOverride @= '', strVersion, strVersionOverride), strParameterNames, strParameterValues);
strCommand = '';
IF (strVersionFlag @= 'Y');
	IF (strTM1RunFlag @= 'Y');
		strCommand = 'tm1runti -i '| strTM1RunTI_ConfigFile |' -process "'| strSubProcess |'" pDebug=' | NumberToString(pDebug);
		strCommand = strCommand | ' pVersion="' | IF(strVersionOverride @= '', strVersion, strVersionOverride) | '"';
		strCommand = strCommand | ' pParameters="' | strParameterNames |'"';
		strCommand = strCommand | ' pParameterValues="' | strParameterValues | '"';
		strCommand = strCommand | ' pParameterLimit=' | NumberToString(nParametersToPass);
		strCommand = strCommand | ' -connect ' | strEnvironment;
		strCommand = strCommand | ' -user ' | strTM1RunTI_User;
		strCommand = strCommand | ' -passwordfile ' | strTM1RunTI_PasswordFile;
		strCommand = strCommand | ' -passwordkeyfile ' | strTM1RunTI_KeyFile;

		strTM1RunTI_BatchFile =  strScriptFolder | 'tm1runti_' | strSubProcess | '.bat';
		ExecuteCommand(strTM1RunTI_BatchFile, 1);
	
	ELSE;
		IF (DIMIX(dimVersions,  IF(strVersionOverride @= '', strVersion, strVersionOverride)) > 0);
			ExecuteProcess(strSubProcess,
				'pDebug', IF(nDebugOverride = 0, pDebug, nDebugOverride),
				'pVersion', IF(strVersionOverride @= '', strVersion, strVersionOverride),
				'pParameters', strParameterNames,
				'pParameterValues', strParameterValues,
				'pParameterLimit', nParametersToPass);
		ELSE;
			ASCIIOUTPUT(strDataErrLogFile, 'Invalid Version: ' | strVersionOverride | ' for process: '| strSubProcess);
		ENDIF;
	ENDIF;
ELSE;
	IF (strTM1RunFlag @= 'Y');
		strCommand = 'tm1runti -i '| strTM1RunTI_ConfigFile |' -process "'| strSubProcess |'" pDebug=' | NumberToString(pDebug);
		strCommand = strCommand | ' pParameters="' | strParameterNames |'"';
		strCommand = strCommand | ' pParameterValues="' | strParameterValues | '"';
		strCommand = strCommand | ' pParameterLimit=' | NumberToString(nParametersToPass);
		strCommand = strCommand | ' -connect ' | strEnvironment;
		strCommand = strCommand | ' -user ' | strTM1RunTI_User;
		strCommand = strCommand | ' -passwordfile ' | strTM1RunTI_PasswordFile;
		strCommand = strCommand | ' -passwordkeyfile ' | strTM1RunTI_KeyFile;
		
		strTM1RunTI_BatchFile =  strScriptFolder | 'tm1runti_' | strSubProcess | '.bat';
		ASCIIOUTPUT(strTM1RunTI_BatchFile, strCommand);

		ExecuteCommand(strTM1RunTI_BatchFile, 1);
	ELSE;
		ExecuteProcess(strSubProcess,
			'pDebug', IF(nDebugOverride = 0, pDebug, nDebugOverride),
			'pParameters', strParameterNames,
			'pParameterValues', strParameterValues);
	ENDIF;
ENDIF;


IF (ProcessReturnCode = ProcessExitByQuit %
	ProcessReturnCode = ProcessExitSeriousError %
	ProcessReturnCode = ProcessExitOnInit);
	ASCIIOUTPUT(strPrologErrLogFile, 'Process ' | strSubProcess | ' terminated with error: ' | STR(ProcessReturnCode, 2, 0));
	EXECUTEPROCESS(strEmailProcess,
		'pDebug', pDebug,
		'pCallingProcess', strProcessName,
		'pSubject', 'Process ' | strSubProcess | ' Failed',
		'pBody', 'Process failed with Error: ' | STR(ProcessReturnCode, 2, 0));

	nErrorFlag = nErrorFlag + ProcessReturnCode;
ENDIF;

nRecordsProcessed = nRecordsProcessed + 1;

One other note. The process "Pool - Ctrl" cannot be opened by any client that is not an admin. It crashes Architect with an error. I'll capture and try to load those images as well.

[PavoGa]

See attached error message when non-admin client tries to open the master process.

[qml]

Ok, I now understand your reasons for doing it that way.

Clearly Architect should not crash when opening a TI process. Likely something is corrupted. I would try and recreate the master process from scratch and check if the issue persists. I would also try and open the process using another non-admin client account (but from what you are saying you have already tried that). And lastly, I would also try with a different version of TM1 (both server and client).

The below log entry is quite interesting:

Code: Select all

21028 [201] DEBUG 2016-03-01 08:15:01.736 TM1.Lock.Exception Contention encountered attempting to acquire lock (0x000000007C624810) on object [Client "FPRP Process Admin", addr=0x000000007C63C810, index=R-2462] in IX mode at ..\tm1_r7s\TM1Thread.cpp:1332 during function 'Unknown'.
Entering wait state 'IXCur'.
Blocked by the following 0 threads:

It looks like the master thread is clashing with nothing in particular and for no obvious reason (>>function 'Unknown'<<, >>blocked by 0 threads<<). It would be very helpful to know what tm1top is showing at that point. I expect tm1top to show that the lock contention on the client object is in fact between "Pool - Update Pool Dimension" (thread 21028) and "Pool - Ctrl" (thread 13056), even though the log entry does not explicitly say that. I would also like to know what thread 16420 is as I don't suppose you have another tm1runti in there.

[BrianL]

The below log entry is quite interesting:

Code: Select all

21028 [201] DEBUG 2016-03-01 08:15:01.736 TM1.Lock.Exception Contention encountered attempting to acquire lock (0x000000007C624810) on object [Client "FPRP Process Admin", addr=0x000000007C63C810, index=R-2462] in IX mode at ..\tm1_r7s\TM1Thread.cpp:1332 during function 'Unknown'.
Entering wait state 'IXCur'.
Blocked by the following 0 threads:

It looks like the master thread is clashing with nothing in particular and for no obvious reason (>>function 'Unknown'<<, >>blocked by 0 threads<<).

This is a bug I've encountered before. According to IBM the bug is not reporting a blocking thread id and it should be fixed in 10.2.2 FP5 (which was just released).