RunProcess explanation

[PavoGa]

I setup the same test. Created a subset on a dimension with 50 members, ran a subprocess with RunProcess passing parameters, wrote those parameters to a cube and they all showed up as expected. The master process started (from the server log) at 16:02:14.584 and last subprocess completed at 16:02:14.669, so less than a second to execute the master and 50 subprocesses. 13 of those processes completed after the master process.

Cleared the cube and ran several times with same result, 100% writes as expected. Just some shots in the dark here, but you are on PA right? And parallel interaction is on? Is there anything else at all these processes are doing that is not spelled out in your description?

I use RunProcess a good bit and putting together one that runs a whole host of subprocesses in groups with inter-dependencies (one group of parallel processes has to finish while next three sets are sitting there waiting to begin and they must process in order).

[MarenC]

Hi,

thanks for your testing!

I can confirm that there is no other code at all in either process. There are simply 2 processes, the master has 47 runprocess statements on the prolog and the called process has 1 cellput statement, using the pEmpid parameter.

And in the cfg file ParallelInteraction=T.

I am out next week but will do some testing, check the logs and update as soon as I can

Maren

[MarenC]

Hi,

I ran the Master process, which simply has RunProcess('calledProcess', pEmpID) repeated on 47 lines

The called process simply has Cellputn 1 on the Prolog.

I have looked in the Server Log and it it repeated 9 times, i.e. not 47 times as it should have been, as below:

• 11052 [2] INFO 2020-02-17 09:37:48.110 TM1.Process Process "MasterProcess" executed by user "Admin"
  10876 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  12788 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  14448 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  416 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  2792 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  15104 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  2032 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  15172 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  12580 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess" executed by user "Admin"
  10876 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  12788 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  14448 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  12580 [1] INFO 2020-02-17 09:37:48.110 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  2792 [1] INFO 2020-02-17 09:37:48.120 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.01 seconds
  416 [1] INFO 2020-02-17 09:37:48.120 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.01 seconds
  15104 [1] INFO 2020-02-17 09:37:48.120 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.01 seconds
  2032 [1] INFO 2020-02-17 09:37:48.120 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.01 seconds
  15172 [1] INFO 2020-02-17 09:37:48.120 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.01 seconds
  11052 [2] INFO 2020-02-17 09:37:48.126 TM1.Process Process "MasterProcess": finished executing normally, elapsed time 0.02 seconds

When I add sleep between each RunProcess it runs all 47 as expected, as per server log below, not sure if it makes a difference but when I add sleep each executed is followed by the finished executing whereas in the server log above without sleep it runs them all and then lists the finished executing after:

• 11052 [2] INFO 2020-02-17 09:42:50.500 TM1.Process Process "MasterProcess" executed by user "Admin"
  1012 [1] INFO 2020-02-17 09:42:50.500 TM1.Process Process "CalledProcess" executed by user "Admin"
  1012 [1] INFO 2020-02-17 09:42:50.500 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  3788 [1] INFO 2020-02-17 09:42:50.600 TM1.Process Process "CalledProcess" executed by user "Admin"
  3788 [1] INFO 2020-02-17 09:42:50.600 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  8088 [1] INFO 2020-02-17 09:42:50.716 TM1.Process Process "CalledProcess" executed by user "Admin"
  8088 [1] INFO 2020-02-17 09:42:50.716 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  12460 [1] INFO 2020-02-17 09:42:50.816 TM1.Process Process "CalledProcess" executed by user "Admin"
  12460 [1] INFO 2020-02-17 09:42:50.816 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  17328 [1] INFO 2020-02-17 09:42:50.916 TM1.Process Process "CalledProcess" executed by user "Admin"
  17328 [1] INFO 2020-02-17 09:42:50.916 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  3496 [1] INFO 2020-02-17 09:42:51.017 TM1.Process Process "CalledProcess" executed by user "Admin"
  3496 [1] INFO 2020-02-17 09:42:51.017 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  10352 [1] INFO 2020-02-17 09:42:51.117 TM1.Process Process "CalledProcess" executed by user "Admin"
  10352 [1] INFO 2020-02-17 09:42:51.117 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  15100 [1] INFO 2020-02-17 09:42:51.218 TM1.Process Process "CalledProcess" executed by user "Admin"
  15100 [1] INFO 2020-02-17 09:42:51.218 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  15592 [1] INFO 2020-02-17 09:42:51.318 TM1.Process Process "CalledProcess" executed by user "Admin"
  15592 [1] INFO 2020-02-17 09:42:51.318 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  7944 [1] INFO 2020-02-17 09:42:51.418 TM1.Process Process "CalledProcess" executed by user "Admin"
  7944 [1] INFO 2020-02-17 09:42:51.418 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  12548 [1] INFO 2020-02-17 09:42:51.519 TM1.Process Process "CalledProcess" executed by user "Admin"
  12548 [1] INFO 2020-02-17 09:42:51.519 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  16824 [1] INFO 2020-02-17 09:42:51.634 TM1.Process Process "CalledProcess" executed by user "Admin"
  16824 [1] INFO 2020-02-17 09:42:51.635 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  15108 [1] INFO 2020-02-17 09:42:51.735 TM1.Process Process "CalledProcess" executed by user "Admin"
  15108 [1] INFO 2020-02-17 09:42:51.735 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  6020 [1] INFO 2020-02-17 09:42:51.835 TM1.Process Process "CalledProcess" executed by user "Admin"
  6020 [1] INFO 2020-02-17 09:42:51.835 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  16096 [1] INFO 2020-02-17 09:42:51.935 TM1.Process Process "CalledProcess" executed by user "Admin"
  16096 [1] INFO 2020-02-17 09:42:51.935 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  5564 [1] INFO 2020-02-17 09:42:52.035 TM1.Process Process "CalledProcess" executed by user "Admin"
  5564 [1] INFO 2020-02-17 09:42:52.035 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  17372 [1] INFO 2020-02-17 09:42:52.136 TM1.Process Process "CalledProcess" executed by user "Admin"
  17372 [1] INFO 2020-02-17 09:42:52.136 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  17036 [1] INFO 2020-02-17 09:42:52.236 TM1.Process Process "CalledProcess" executed by user "Admin"
  17036 [1] INFO 2020-02-17 09:42:52.236 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  3508 [1] INFO 2020-02-17 09:42:52.336 TM1.Process Process "CalledProcess" executed by user "Admin"
  3508 [1] INFO 2020-02-17 09:42:52.336 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  2740 [1] INFO 2020-02-17 09:42:52.436 TM1.Process Process "CalledProcess" executed by user "Admin"
  2740 [1] INFO 2020-02-17 09:42:52.436 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  14364 [1] INFO 2020-02-17 09:42:52.537 TM1.Process Process "CalledProcess" executed by user "Admin"
  14364 [1] INFO 2020-02-17 09:42:52.537 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  15364 [1] INFO 2020-02-17 09:42:52.637 TM1.Process Process "CalledProcess" executed by user "Admin"
  15364 [1] INFO 2020-02-17 09:42:52.637 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  7116 [1] INFO 2020-02-17 09:42:52.737 TM1.Process Process "CalledProcess" executed by user "Admin"
  7116 [1] INFO 2020-02-17 09:42:52.737 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  10600 [1] INFO 2020-02-17 09:42:52.838 TM1.Process Process "CalledProcess" executed by user "Admin"
  10600 [1] INFO 2020-02-17 09:42:52.838 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  824 [1] INFO 2020-02-17 09:42:52.953 TM1.Process Process "CalledProcess" executed by user "Admin"
  824 [1] INFO 2020-02-17 09:42:52.953 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  14844 [1] INFO 2020-02-17 09:42:53.053 TM1.Process Process "CalledProcess" executed by user "Admin"
  14844 [1] INFO 2020-02-17 09:42:53.053 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  7112 [1] INFO 2020-02-17 09:42:53.154 TM1.Process Process "CalledProcess" executed by user "Admin"
  7112 [1] INFO 2020-02-17 09:42:53.154 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  10196 [1] INFO 2020-02-17 09:42:53.254 TM1.Process Process "CalledProcess" executed by user "Admin"
  10196 [1] INFO 2020-02-17 09:42:53.254 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  1620 [1] INFO 2020-02-17 09:42:53.354 TM1.Process Process "CalledProcess" executed by user "Admin"
  1620 [1] INFO 2020-02-17 09:42:53.354 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  16264 [1] INFO 2020-02-17 09:42:53.454 TM1.Process Process "CalledProcess" executed by user "Admin"
  16264 [1] INFO 2020-02-17 09:42:53.454 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  496 [1] INFO 2020-02-17 09:42:53.555 TM1.Process Process "CalledProcess" executed by user "Admin"
  496 [1] INFO 2020-02-17 09:42:53.555 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  13420 [1] INFO 2020-02-17 09:42:53.655 TM1.Process Process "CalledProcess" executed by user "Admin"
  13420 [1] INFO 2020-02-17 09:42:53.655 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  8968 [1] INFO 2020-02-17 09:42:53.755 TM1.Process Process "CalledProcess" executed by user "Admin"
  8968 [1] INFO 2020-02-17 09:42:53.755 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  15036 [1] INFO 2020-02-17 09:42:53.871 TM1.Process Process "CalledProcess" executed by user "Admin"
  15036 [1] INFO 2020-02-17 09:42:53.871 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  5412 [1] INFO 2020-02-17 09:42:53.971 TM1.Process Process "CalledProcess" executed by user "Admin"
  5412 [1] INFO 2020-02-17 09:42:53.971 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  1048 [1] INFO 2020-02-17 09:42:54.072 TM1.Process Process "CalledProcess" executed by user "Admin"
  1048 [1] INFO 2020-02-17 09:42:54.072 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  2736 [1] INFO 2020-02-17 09:42:54.172 TM1.Process Process "CalledProcess" executed by user "Admin"
  2736 [1] INFO 2020-02-17 09:42:54.172 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  15852 [1] INFO 2020-02-17 09:42:54.273 TM1.Process Process "CalledProcess" executed by user "Admin"
  15852 [1] INFO 2020-02-17 09:42:54.273 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  14708 [1] INFO 2020-02-17 09:42:54.373 TM1.Process Process "CalledProcess" executed by user "Admin"
  14708 [1] INFO 2020-02-17 09:42:54.373 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  12808 [1] INFO 2020-02-17 09:42:54.473 TM1.Process Process "CalledProcess" executed by user "Admin"
  12808 [1] INFO 2020-02-17 09:42:54.473 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  5276 [1] INFO 2020-02-17 09:42:54.573 TM1.Process Process "CalledProcess" executed by user "Admin"
  5276 [1] INFO 2020-02-17 09:42:54.573 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  10824 [1] INFO 2020-02-17 09:42:54.683 TM1.Process Process "CalledProcess" executed by user "Admin"
  10824 [1] INFO 2020-02-17 09:42:54.683 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  10440 [1] INFO 2020-02-17 09:42:54.789 TM1.Process Process "CalledProcess" executed by user "Admin"
  10440 [1] INFO 2020-02-17 09:42:54.789 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  2660 [1] INFO 2020-02-17 09:42:54.892 TM1.Process Process "CalledProcess" executed by user "Admin"
  2660 [1] INFO 2020-02-17 09:42:54.892 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  12732 [1] INFO 2020-02-17 09:42:55.005 TM1.Process Process "CalledProcess" executed by user "Admin"
  12732 [1] INFO 2020-02-17 09:42:55.005 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  13596 [1] INFO 2020-02-17 09:42:55.106 TM1.Process Process "CalledProcess" executed by user "Admin"
  13596 [1] INFO 2020-02-17 09:42:55.106 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  12396 [1] INFO 2020-02-17 09:42:55.206 TM1.Process Process "CalledProcess" executed by user "Admin"
  11052 [2] INFO 2020-02-17 09:42:55.206 TM1.Process Process "MasterProcess": finished executing normally, elapsed time 4.71 seconds
  12396 [1] INFO 2020-02-17 09:42:55.206 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds

Maren

[lotsaram]

Like PavoGa I can't replicate this at all. If I perform a similar test to what you described all the RunProcess processes get executed.
I think you are (well) past the point where anyone here can help and you need to be engaging with IBM Support.

[MarenC]

Ok thanks, I may be well past the point where anyone can help but PavGo did ask me to provide the server log output and that is all I have done.

Will contact IBM and feedback if I get anywhere.

Maren

[PavoGa]

A little surprised at one thing in your first log output. None of the subprocesses finished after the main process. Off the top of my head, I do not recall that happening any time I've been testing RunProcess. Even if I kicked off say a half-dozen subs, some are going to finish after the main process does.

EDIT:

Looking at it, the last subprocess kicks off at 48.110 and the master does not complete until 48.126. So for .016, an eternity for something like this, the Master process is twiddling its thumbs doing what? One last question on the first run, what executions actually wrote to the cube? The first nine, the last nine or some random selection?

[PavoGa]

One last question: What is your MTQ setting the config file?

[MarenC]

Hi Pavoga,

MTQ = -2.

"One last question on the first run, what executions actually wrote to the cube? The first nine, the last nine or some random selection?"

Always seems to be the First n number, so in the case I posted previously the first 9 but I have just rerun the process and this time the first 14 were updated. Log below

• 10784 [2] INFO 2020-02-17 16:44:15.443 TM1.Process Process "MasterProcess" executed by user "Admin"
  15296 [1] INFO 2020-02-17 16:44:15.455 TM1.Process Process "CalledProcess" executed by user "Admin"
  13580 [1] INFO 2020-02-17 16:44:15.455 TM1.Process Process "CalledProcess" executed by user "Admin"
  13424 [1] INFO 2020-02-17 16:44:15.456 TM1.Process Process "CalledProcess" executed by user "Admin"
  16908 [1] INFO 2020-02-17 16:44:15.462 TM1.Process Process "CalledProcess" executed by user "Admin"
  16256 [1] INFO 2020-02-17 16:44:15.463 TM1.Process Process "CalledProcess" executed by user "Admin"
  15296 [1] INFO 2020-02-17 16:44:15.463 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  13580 [1] INFO 2020-02-17 16:44:15.463 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  7724 [1] INFO 2020-02-17 16:44:15.463 TM1.Process Process "CalledProcess" executed by user "Admin"
  13424 [1] INFO 2020-02-17 16:44:15.463 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  16908 [1] INFO 2020-02-17 16:44:15.471 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.01 seconds
  16256 [1] INFO 2020-02-17 16:44:15.471 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.01 seconds
  17184 [1] INFO 2020-02-17 16:44:15.471 TM1.Process Process "CalledProcess" executed by user "Admin"
  7944 [1] INFO 2020-02-17 16:44:15.472 TM1.Process Process "CalledProcess" executed by user "Admin"
  7724 [1] INFO 2020-02-17 16:44:15.474 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  13596 [1] INFO 2020-02-17 16:44:15.474 TM1.Process Process "CalledProcess" executed by user "Admin"
  7944 [1] INFO 2020-02-17 16:44:15.478 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  17184 [1] INFO 2020-02-17 16:44:15.478 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  13596 [1] INFO 2020-02-17 16:44:15.479 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  1928 [1] INFO 2020-02-17 16:44:15.482 TM1.Process Process "CalledProcess" executed by user "Admin"
  6228 [1] INFO 2020-02-17 16:44:15.485 TM1.Process Process "CalledProcess" executed by user "Admin"
  1928 [1] INFO 2020-02-17 16:44:15.487 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  6228 [1] INFO 2020-02-17 16:44:15.489 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  1056 [1] INFO 2020-02-17 16:44:15.494 TM1.Process Process "CalledProcess" executed by user "Admin"
  6312 [1] INFO 2020-02-17 16:44:15.499 TM1.Process Process "CalledProcess" executed by user "Admin"
  1056 [1] INFO 2020-02-17 16:44:15.499 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  11080 [1] INFO 2020-02-17 16:44:15.501 TM1.Process Process "CalledProcess" executed by user "Admin"
  6312 [1] INFO 2020-02-17 16:44:15.502 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  11080 [1] INFO 2020-02-17 16:44:15.503 TM1.Process Process "CalledProcess": finished executing normally, elapsed time 0.00 seconds
  10784 [2] INFO 2020-02-17 16:44:15.512 TM1.Process Process "MasterProcess": finished executing normally, elapsed time 0.07 seconds

Maren

[PavoGa]

I've run out of ideas. I do not see this behavior ever where the master process finishes AFTER all the sub-processes it executes with RunProcess have completed. And it really is not really close as it finishes a fraction of a second after both kicking off the last process and when that process finishes.

Probably going to be something simple or a setting, but it's got me. Only other thing I suggest is change your MTQ to a positive integer that is half of your available cores and see what happens. But that is just a shot in the dark. Some oddities with RunProcess are being documented (see thread about passing parameters that are decimal values) and you could have found another one.

[MarenC]

I have appreciated your help on this PavoGa. The MTQ didn't do anything, so I will post back if anything comes of this.

And yes I have been looking at the other RunProcess thread

Maren