I am trying to log TI process run times in such a way, that I only need to specify some code at the top of the Prolog tab,
followed by very minimal code further on in the process. If we can get this working, generic processes like Bedrock will be able to benefit too.
The cases is as follows. I have a master process that can complete a number of tasks. These tasks are numbered 0, 1, 2, ..., 9. The user executes the mother process by specifying a string parameter: pMode = '1489' which means: execute subparts 1, then 4, then 8, then 9. The process uses recursion, hence, the same process calls itself but then pMode = 1, then pMode = 4, then pMode = 8, then pMode = 9.
For each of the 10 subparts, I want to track the runtime, so I need to log (with LogOutput) the START, the END, and calculate the difference in seconds. This is not that difficult, in fact, this works fine (all Prolog tab code):
Code: Select all
cINFO_Mask_Process_Start = GetProcessName | ' START';
cINFO_Mask_Process_End = GetProcessName | ' END ( after %sSec% sec.)';
cMask_Sec = '#,##0.00';
# start logging
nStart = Now;
LogOutput( 'INFO', Expand( '%cINFO_Mask_Process_Start%' ));
# some code
# wait 2 seconds
Sleep( 2000 );
# some more code
# calculate the time
sSec = NumberToStringEx( 86400 * ( Now - nStart ), cMask_Sec , '.', ',' );
LogOutput( 'INFO', Expand( Expand( '%cINFO_Mask_Process_End%' )));
But I hope to get rid of the line sSec = ..... (the last but one line). I prefer to "calculate"/define sSec at the top of the Prolog tab, containing the variable nStart, with is populated when the subprocess takes off.
With the use of Expand, I had hoped to get this working. But it does not. Here's the code, which you can just copy/paste to replicate:
Code: Select all
cINFO_Mask_Process_Start = GetProcessName | ' START';
cINFO_Mask_Process_End = GetProcessName | ' END ( after %sSec% sec.)';
nStart = 0;
sSec = NumberToStringEx( 86400 * ( Now - nStart ), '#,##0.00' , '.', ',' );
# start logging
nStart = Now;
LogOutput( 'INFO', Expand( '%cINFO_Mask_Process_Start%' ));
# some code
# wait 2 seconds
Sleep( 2000 );
# some more code
# calculate the time
LogOutput( 'INFO', Expand( Expand( '%cINFO_Mask_Process_End%' )));
That's a lot of seconds ! Clearly it is caused by nStart = 0 and sSec is not recalculated anymore. However, I use a bunch of Expand's in the END mask.1480 [4] INFO 2020-07-10 20:06:46.958 TM1.TILogOutput TI_test START
1480 [4] INFO 2020-07-10 20:06:48.958 TM1.TILogOutput TI_test END ( after 1,910,030,806.00 sec.)
It's more out of curiosity but working with Expand and masks can really increase the maintenance of code. Is there anyone who can make it work with the sSec = ... line at the top of the Prolog, where all the information is neatly organised - except the parts that we cannot know upfront ?
Thanks heaps !