Measurement of memory consumption

[jmeier]

Check these boxes if you have followed the posting rules.

• Q&A General is the most appropriate section for my question
• I have consulted the posting Guidelines on the Discussions front page
• I have searched the Discussions forum and my question has not been asked before
• I have searched the MOOSE website and the documentation does not answer my question
• I have formatted my post following the posting guidelines (screenshots as a last resort, triple back quotes around pasted text)

Question

Dear Moose Community,

I hope this question has a simple answer, but I'm stuck anyways: I'd like to know the total memory consumption (RAM) of my MooseApp run. It does not have to be exact.

I work on a WSL / Ubuntu.

I've read PerfGraphOutput.

So I set perf_graph=true and started a simple Moose model with mpiexec -n 1:

Performance Graph:
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|                                Section                               | Calls |   Self(s)  |   Avg(s)   |    %   | Mem(MB) |  Total(s)  |   Avg(s)   |    %   | Mem(MB) |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| shaleTestApp (main)                                                  |     1 |      0.008 |      0.008 |   0.00 |       5 |    168.030 |    168.030 | 100.00 |     291 |
|   Action::SetupMeshAction::Mesh::SetupMeshAction::act::setup_mesh    |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   Action::SetupMeshAction::Mesh::SetupMeshAction::act::set_mesh_base |     2 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   MeshGeneratorSystem::createMeshGeneratorOrder                      |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   FEProblem::computeUserObjects                                      |     2 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   FEProblem::computeUserObjects                                      |     3 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   FEProblem::outputStep                                              |    12 |      0.002 |      0.000 |   0.00 |       0 |      0.528 |      0.044 |   0.31 |      12 |
|   Transient::PicardSolve                                             |    11 |      0.009 |      0.001 |   0.01 |       0 |    166.536 |     15.140 |  99.11 |     116 |
|     FEProblem::computeUserObjects                                    |    88 |      0.001 |      0.000 |   0.00 |       0 |      0.001 |      0.000 |   0.00 |       0 |
|     FEProblem::outputStep                                            |    33 |      0.002 |      0.000 |   0.00 |       0 |      0.002 |      0.000 |   0.00 |       0 |
|     FEProblem::solve                                                 |    11 |     70.019 |      6.365 |  41.67 |      88 |    164.479 |     14.953 |  97.89 |     116 |
|       FEProblem::computeUserObjects                                  |    84 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|       FEProblem::computeResidualInternal                             |    94 |      0.002 |      0.000 |   0.00 |       0 |     32.874 |      0.350 |  19.56 |       0 |
|         FEProblem::computeUserObjects                                |   188 |      0.002 |      0.000 |   0.00 |       0 |      0.002 |      0.000 |   0.00 |       0 |
|       FEProblem::computeJacobianInternal                             |    31 |      0.001 |      0.000 |   0.00 |       0 |     61.572 |      1.986 |  36.64 |      28 |
|         FEProblem::computeUserObjects                                |    62 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   Transient::final                                                   |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|     FEProblem::computeUserObjects                                    |     2 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|     FEProblem::outputStep                                            |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Finished Executing                                                                       [167.78 s] [  438 MB]

Now the same for mpiexec -n 5

Performance Graph:
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|                                Section                               | Calls |   Self(s)  |   Avg(s)   |    %   | Mem(MB) |  Total(s)  |   Avg(s)   |    %   | Mem(MB) |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| shaleTestApp (main)                                                  |     1 |      0.008 |      0.008 |   0.02 |       3 |     45.483 |     45.483 | 100.00 |     106 |
|   Action::SetupMeshAction::Mesh::SetupMeshAction::act::setup_mesh    |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   Action::SetupMeshAction::Mesh::SetupMeshAction::act::set_mesh_base |     2 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   MeshGeneratorSystem::createMeshGeneratorOrder                      |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   FEProblem::computeUserObjects                                      |     2 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   FEProblem::computeUserObjects                                      |     3 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   FEProblem::outputStep                                              |    12 |      0.001 |      0.000 |   0.00 |       0 |      0.333 |      0.028 |   0.73 |      22 |
|   Transient::PicardSolve                                             |    11 |      0.006 |      0.001 |   0.01 |       0 |     44.707 |      4.064 |  98.29 |       6 |
|     FEProblem::computeUserObjects                                    |    88 |      0.001 |      0.000 |   0.00 |       0 |      0.001 |      0.000 |   0.00 |       0 |
|     FEProblem::outputStep                                            |    33 |      0.002 |      0.000 |   0.00 |       0 |      0.002 |      0.000 |   0.00 |       0 |
|     FEProblem::solve                                                 |    11 |     23.389 |      2.126 |  51.42 |      -4 |     44.255 |      4.023 |  97.30 |       6 |
|       FEProblem::computeUserObjects                                  |    84 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|       FEProblem::computeResidualInternal                             |    91 |      0.002 |      0.000 |   0.01 |       0 |      6.888 |      0.076 |  15.14 |       0 |
|         FEProblem::computeUserObjects                                |   182 |      0.001 |      0.000 |   0.00 |       0 |      0.001 |      0.000 |   0.00 |       0 |
|       FEProblem::computeJacobianInternal                             |    31 |      0.001 |      0.000 |   0.00 |       0 |     13.970 |      0.451 |  30.72 |      10 |
|         FEProblem::computeUserObjects                                |    62 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|   Transient::final                                                   |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|     FEProblem::computeUserObjects                                    |     2 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
|     FEProblem::outputStep                                            |     1 |      0.000 |      0.000 |   0.00 |       0 |      0.000 |      0.000 |   0.00 |       0 |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Finished Executing                                                                       [ 45.28 s] [  249 MB]

The run with 1 CPU took longer than with 5 CPUs. And the factor in wall-time is reasonable considering I only have 32980 DOF in my non-linear system and 5 CPUs is probably a bit much. So far so good.

But the numbers on memory-consumption is not clear to me:

• with 1 CPU Moose writes below the performance graph "438 MB" - in the performance graph "291 MB" is written
• with 5 CPUs Moose writes below the performance graph "249 MB" - in the performance graph "106 MB" is written

More in detail:

• Why does the memory consumption given in the performance graph and below is off by factor 1.5, 2.3?
• Why is the memory consumption with 5 CPUs smaller than with 1? Is the memory consumption written per CPU and I have to multiply by the number of CPUs used?

Thank you in advance!

[milljm]

I've wanted to get back to making one of my very first projects with MOOSE, work again with Python 3.x

This DOES NOT WORK, but the following script:

moose/scripts/memory_logger.py

is designed to do what it is you are asking. It needs SERIOUS TLC. Being one of my first Python projects :(

Embarrassing to look at.

[jmeier]

Thank you very much for this tip!

For later reference: the description for this script can be found here:
mooseframework.inl.gov/python/memory_logger.html

[milljm]

Oh this shouldn't be the answer... The script won't work as is... I am looking at now. I'll get back to you if this turns out to be something simple.

[jmeier]

Ok, so let's postpone marking this as answer. I have to install PBS first before to be able to have a look. Thanks for your help!

[milljm]

No need for PBS if you are not operating on an HPC cluster. This script will run fine on a single machine :)

also some good news: I am already able to make this script spit back some information. So it would seem little may be required to bring this back to life.

[jmeier]

Oh, my fault. I misread the error message I got:

  File "/home/mjg/projects/moose/scripts/memory_logger.py", line 185
    print 'I could not find your PBS_NODEFILE. Is PBS loaded?'
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
SyntaxError: Missing parentheses in call to 'print'. Did you mean print(...)?

[GiudGiud]

iirc you can just use "time" on linux to measure memory. the one from /usr/bin/time
https://stackoverflow.com/a/33532736

[jmeier]

My first test was not successful: time --verbose ls gives
--verbose: command not found

I'll have a closer look. Thanks for the tip!

BTW: which time gives
/usr/bin/time

[GiudGiud]

not sure you need verbose?

[GiudGiud]

ok you do on macos when using gnu-time.

[jmeier]

Turns out, in Ubuntu one has to explicitly use the time in /usr/bin/time to get the --verbose. This can be done using one the following ways:

• calling time via its full path /usr/bin/time -v ... (@GiudGiud already had this command, but I overlooked)
• enforce the time given by which time by just prefixing an backslash \time -v ...

Doing so, gives the following numbers (all in MB, just one run each, numbers vary slightly from run to run - take with grain of salt)

Measurement method	N = 1	N = 5
Performance Graph	290	138
Finished Executing	435	283
sum of "mpiexec -n N \time -f '%M' ...."	665	1 669
WRONG, but just for fun: "\time -f '%M' mpiexec -n N ..."	664	357

As already stated by @GiudGiud, \time must be inside the mpiexec-call and one has to sum up the results. Problem here is, that all of the time-commands finish at the same time and their values tend to mix up (especially if one uses -v; -f '%M' limits this effect).

Let's see how these numbers match with the script kindly provided by @milljm

[GiudGiud]

Problem here is, that all of the time-commands finish at the same time and their values tend to mix up (especially if one uses -v; -f '%M' limits this effect).

Yes that's a problem. You'll want to do something like:

mpirun -n 4 /usr/bin/time -v app-opt -i input.i &> log_${OMPI_COMM_WORLD_RANK}

(with openmpi, there are different variables for others, find out which with mpirun -n 1 env)

Then you can do the sum from the files.
But Jason's script will do what you need so no need to sink too much time into this

[milljm]

Ok, this is very unorthodox, supplying a patch during a Discussion. But I feel this will at least "get you going for now", while I polish it up. You'll have to do precisely the following:

Download the patch file (attached), and save it to the root of your MOOSE repository. Apply the patch like so:

cd ~/projects/moose
patch -p1 < memory_logger.patch

Next, run the memory_logger as so, on a test file, just to see if it works (replace YOU with your actual user name):

cd ~/projects/moose/test/tests/kernels/simple_diffusion
~/projects/moose/scripts/memory_logger.py --run 'mpiexec -n 5 /home/YOU/projects/moose/test/moose_test-opt -i /home/YOU/projects/moose/test/tests/kernels/simple_diffusion/simple_diffusion.i -r 5'

Then do what the program explains to do when it finishes. If this works, we can then concentrate on how to run this on your actual problem. It should ask you to do something like the following:

~/projects/moose/scripts/memory_logger.py --read /home/YOU/projects/moose/test/tests/kernels/simple_diffusion/memory.log

Note: pay carful attention to the command line arguments after --run. You need to supply absolute paths to everything. No relative paths (no use of ~/ or $HOME etc.

memory_logger.patch

[jmeier]

Different platforms, different compilers, potentially different de-allocation strategy. It's not an exact science though 6x on the perf graph is probably a new record for its inaccuracy. As long as you can scale up to the case needed that's all I care about

A rough number is all I need - no problem this is not an exact science. But even the perf_graph numbers make little sense to me. At the moment its just a very small test model.

If we were looking to reduce this, we'd have to look into getting a summary from PETSc of how many are allocated, and how (parallel, ghosted,..) and see if we can cut down on that.

At the moment its just a very small test model. For this model, I just like to measure for now - not to optimize.

[jmeier]

I have thought about this topic again from various angles - and I think my initial question could have been formulated more precisely.

As pointed out by GuidGuid here and there, measuring memory from the "outside" as e.g. memory_logger.py is doing will also measure variables/objects not in use anymore but not de-allocated yet etc.. In my small model compared to my RAM available, cleanup may be postponed longer (e.g. more stuff waiting to be de-allocated?). I assume that the moment memory pressure rises (e.g. for larger models), those unused variables/objects will be removed more frequently.
I see the high value of being able to measure memory usage from the outside including all 'memory relics' etc., like memory_logger.py seems to do. I guess especially in the development of Moose or MooseApps.

My initial motivation was to get peak memory usage without those 'memory-relics'. Following the answer of GuidGuid, I assume this must be done from the inside - e.g. perf graph.

A brief summary of the current situation (I hope I'm not leaving too much out):

Option 1: perf_graph=true

• perf_graph shows a value for "total Mem(MB)": it is unclear to me, what this number really measures.
• For me, "total Mem(MB)" reduces in magnitude, the more CPU's I use.
• I assume perf_graph does not measure variables/objects not used anymore but not de-allocated yet.
• Does perf_graph include the RAM used by PETSc?

Option 2: memory_logger.py

• memory_logger.py seems to measure the RAM-footprint from the outside - including not yet de-allocated memory
• I assume this includes the RAM used by PETSc?
• The RAM usage reported by memory_logger.py increases with the number of CPUs used (what is plausible to me).

Sometimes Moose prints those yellow numbers including a memory value. I'm unsure where they are coming from and how to trigger them:

Finished Setting Up                                                                      [  0.66 s] [  208 MB]

[GiudGiud]

For me, "total Mem(MB)" reduces in magnitude, the more CPU's I use.

Should be on a per CPU basis, but it's unclear how that is done to me. We should output the integrated value instead

Does perf_graph include the RAM used by PETSc?

It should yes. We measure this, you can see the jump when the system is allocated

I assume this includes the RAM used by PETSc?

@milljm will know more, but yes it should include PETSc

The RAM usage reported by memory_logger.py increases with the number of CPUs used (what is plausible to me).

Makes sense if it includes all processes

Sometimes Moose prints those yellow numbers including a memory value. I'm unsure where they are coming from and how to trigger them:

This comes from the perf graph live print, which is based on the perf graph. Whenever a task, registered to the perf graph, meets a cpu time threshold (set by the user, defaults to 5 or 10s iirc), the perf graph reports the time and memory cost when it finishes

[GiudGiud]

@loganharbour is working on something you might be able to use here
#29584
the test harness will be able to measure memory consumption. It will handle the reduction over MPI processes too, one will just need to write the input as a test and run it with run_tests

[jmeier]

This is good news! I'm looking forward to this.