7
$\begingroup$

I am running an externally compiled C++ program using RunProcess, and I encountered a strange thing: when I run the RunProcess command many times, it takes increasingly more and more time for identical evaluation. How comes? Can I do something to prevent this?

Minimal example of this behavior

We can see this behavior running simply date (as noted by Jason B.): ListPlot@Table[First@AbsoluteTiming@Do[RunProcess["date"], 5], 400]

We measure the time it takes to run RunProcess["date"] five times over 400 experiments. The code yields the following:

enter image description here

As you can see, despite running an identical command, the running time gets longer the more times we do it.

Question

So I have two questions:

  • Why is this happening?
  • Is there a better way to use external code if I need its output many times? I realise that running new process over and over again as a function call is not the most efficient way to go, but is there a better way if I am using a code which I don't understand and don't want to touch in any way?

System specifications

  • System: macOS Monterey 12.1
  • Mathematica version: 12.3.1

(Original example of this question)

I took the following C++ code

#include <algorithm>
using namespace std;

int main(int argc, char const *argv[])
{
    double product;

    for (int i = 0; i < 1000000; ++i)
    {
        product = rand() * rand();
    }
    return 0;
}

I compiled it using g++ clutter.cpp -std=c++11 -o clutter. In Mathematica, I ran the following code:

times = {}
Module[{timeStart, time},
     timeStart = Now;
     Do[RunProcess["<PATH>/clutter"], 10];
     time = Now - timeStart;
     AppendTo[times, time];
]& /@ Range[1000];

That is, I ran 1000$\times$10 calls to RunProcess, and measured the time for each 10 calls. (If you want to run this, you might want to lower the numbers, this took 254 seconds together). The times were as in the figure: Time in seconds for each 10 runs

As you can see, the time more than doubles throughout the experiment.

$\endgroup$
6
  • $\begingroup$ Run this without the AppendTo in order to isolate the contributions. See: 127644. $\endgroup$
    – Syed
    Commented Jan 26, 2022 at 18:45
  • $\begingroup$ Shouldn't Now-ts be evaluated before AppendTo making the append process outside of the timing? I see your point, and I'll make it clearer, but considering other experiments I have done, I am pretty sure that is not the problem. $\endgroup$ Commented Jan 26, 2022 at 19:20
  • 3
    $\begingroup$ A simpler example might be ListPlot@Table[First@AbsoluteTiming@Do[RunProcess["date"], 5], 400] $\endgroup$
    – Jason B.
    Commented Jan 26, 2022 at 19:22
  • $\begingroup$ @JasonB. Nice, this does indeed also manifest the same phenomenon -- I added it as the main example in the question. Thank you. $\endgroup$ Commented Jan 26, 2022 at 21:09
  • $\begingroup$ On MacOS v13.0 I don't see nearly this slow down. I might have a slight one but nothing to write home about $\endgroup$
    – b3m2a1
    Commented Jan 27, 2022 at 9:39

1 Answer 1

4
$\begingroup$

It's not really an answer but it's easier to insert code here.

It seems like we also have memory leak (or intended caching behavior) here:

getSizes[] := (# -> ToExpression["ByteCount[" <> # <> "]"]) & /@ 
     Names["ProcessLink`Private`*"] // Flatten // Association;
before = getSizes[]; Do[RunProcess["date"], 200]; after = getSizes[];
diffs = Merge[{after, before}, Apply[Subtract]] // ReverseSort;
Take[diffs, 5] // Normal // Column

gives me

{
 {"ProcessLink`Private`unicodeStreams" -> 113280},
 {"ProcessLink`Private`stdoutFileNames" -> 47432},
 {"ProcessLink`Private`stderrFileNames" -> 47432},
 {"ProcessLink`Private`$TempPrefix" -> 0},
 {"ProcessLink`Private`$StringFields" -> 0}
}

So it looks like streams become stuck in global variables. It may or may not be the cause of the slowdown so I'll try to investigate further.

b3m2a1 Addendum:

This does seem to be the source of the slowdown, as this provides constant time operations:

myRunProcess[args___] :=
 Block[
  {
   ProcessLink`Private`unicodeStreams = <||>,
   ProcessLink`Private`stdoutFileNames = <||>,
   ProcessLink`Private`stderrFileNames = <||>
   },
  RunProcess[args]
  ]

subtimes =
  Table[
   First@AbsoluteTiming@Do[myRunProcess["date"], 5],
   400
   ];

ListPlot[subtimes, PlotRange -> All]

enter image description here

This suggests that something is looping over the keys of these Associations but there is nothing obvious in the spelunking.

At any level, this provides a potential workaround, but as always when messing with undocumented stuff like this, something might break.

Also note that StartProcess doesn't suffer from this slow down so it is clearly something in the way KillProcess or similar is handled.

Pavel Perikov Addendum:

This was a nice hunt, but I think WRI is better positioned to pinpoint the exact cause here. Please report it. It's surely something to be addressed.

$\endgroup$
10
  • 2
    $\begingroup$ While these are indeed memory leaks and should be cleared up through some weak referencing, this is likely not the issue as the file names/streams point to closed processes and deleted processes $\endgroup$
    – b3m2a1
    Commented Jan 27, 2022 at 9:39
  • $\begingroup$ @b3m2a1 I hope to investigate further later today. Just sharing observations :) $\endgroup$ Commented Jan 27, 2022 at 9:41
  • 2
    $\begingroup$ Actually I just realized this is the issue but likely not b.c. of any memory things. If you use Block to reset those three caches to empty Association you recover the original speed which suggests something is looping through all of the elements of the Association $\endgroup$
    – b3m2a1
    Commented Jan 27, 2022 at 9:52
  • 2
    $\begingroup$ I'm still not sure where the issue is specifically, but the addendum I just added lays out a way to be sure that this is in fact the issue and provides a possible workaround $\endgroup$
    – b3m2a1
    Commented Jan 27, 2022 at 10:06
  • 2
    $\begingroup$ Reported to support. Also, in the mean time, the @b3m2a1 workaround with Block works like a charm for my particular original application -- something that increased to several minutes run-time after just a few runs now stays steady at 30s. Thank you both! One additional meta-question: Should I accept this as the answer now? I think it answers my question as much as it can, but I'm not sure about the community standards with bugs -- is it resolved only after a bug is resolved or is identifying a bug the resolution? I would guess the latter is the case, but want to make sure. $\endgroup$ Commented Jan 27, 2022 at 12:59

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.