Console output¶
SPARTA outputs information about its progress to the console, but interpreting this output can be non-trivial. This document gives some output examples and explains their meaning.
Startup¶
At the beginning, SPARTA outputs information about the compile-time and run-time configuration:
--------------------------------------------------------------------------------------------
[Main] COMPILER SETTINGS
--------------------------------------------------------------------------------------------
[Main] User-defined output settings
[Main] OUTPUT_TRACER_PARTICLES 0
[Main] OUTPUT_TRACER_SUBHALOS 1
[Main] OUTPUT_RESULT_INFALL 1
[Main] OUTPUT_RESULT_INFALL_SMR 0
...
[Main] Actions to be performed
[Main] DO_ANALYSIS_ANY 1
[Main] DO_ANALYSIS_RSP 1
[Main] DO_ANALYSIS_PROFILES 0
[Main] DO_ANALYSIS_PROFILES_ALL 0
...
The OUTPUT_* switches are set by the user (see Compiling SPARTA), the DO_* switches are worked out by the code itself. They indicate the actual actions performed by the code; many actions can be internally switched on by certain output fields. The second section gives the full run-time configuration, whether set by the user or default:
--------------------------------------------------------------------------------------------
[Main] RUN-TIME CONFIGURATION
--------------------------------------------------------------------------------------------
[Main] Input (halo catalogs)
[Main] catalog_path /some/dir/catalogs
[Main] cat_type 0
[Main] cat_n_chunks 1
[Main] catalog field id id
[Main] catalog field desc_id desc_id
...
Snapshots¶
The following examples assume the default log_level of 1 (see Run-time configuration parameters). If this
level is increased, there is additional output, but that is mostly designed for debugging
purposes. In some of the output, we have removed the leading “[Main] [SN 28]” indicators to avoid
line breaking. Each snapshot’s output is split into sections, starting with basic information:
[Main] [SN 28] Snapshot: 29/30, file 057, a = 0.20416, z = 3.89812, t = 1.64698
In this case, the snapshot index (28) does not match up with the file index (57), which is allowed. The time is measured since the Big Bang, like all times in SPARTA. The second section gives us an idea of how many halos the code is tracking:
[Main] [SN 28] Halos (alive): 9249 total, 8601 connected, 766 new, 8986 hosts (97.2 %), 263 subs (2.8 %)
[Main] [SN 28] Halos (ended): 113 total, 85 discarded, 28 saved (178 cumulative)
The live halos were either connected from a previous snapshot, or newly created. Halo results are saved to file as soon as a halo ends in order to free memory as soon as possible. However, not all halos are written to file, for example if they never reached a critical mass. The number of saved halos is given by the cumulative number at the end.
The following output lines give us a more detailed statistics of the tracers SPARTA is currently tracking. Each type of tracer (particles and subhalos in this case) get separate lines. First, the particle tracer lines will typically look something like this:
[Main] [SN 28] Tracer ptl:
Active 857149 (5.1 %), ignoring 385042 (2.3 %), processed 1404859 (8.4 %), deleted 81300 (0.5 %)
Of proc'd: new 173086 (12.3 %), rec'd 0 (0.0 %), ign 304779 (21.7 %), tr 734640 (52.3 %), n-tr 192354 (13.7 %)
Of del'td: host-sub 24948 (30.7 %), escpd 151 (0.2 %), unconn 14276 (17.6 %), all done 41925 (51.6 %)
Subhalo tags: 9941, ignored 1017, created 1368, result 2303
Here, active means that SPARTA is actively tracking these tracers, that is, there is a tracer object in memory and we will try to connect this tracer in the next snapshot. To avoid excessive tracking, SPARTA keeps a list of tracers to ignore, for example particles that have already orbited over a halo and for which all analyses have been finished. The number of processed tracers is the total number of tracers that were considered in this snapshot.
For particle tracers, all percentages refer to the total number of particles in the simulation. It is not uncommon for SPARTA to track a significant fraction of all particles! The second line tells us what happened to all processed particle tracers, namely whether:
a new tracer was created
a tracer was recreated, meaning it had been a tracer before, was deleted, but has come back and needs to be analyzed again
a tracer was ignored, typically because it was found on the ignore list
a tracer simply continued from one sanpshot to another (“tracked”)
a tracer did not yet exist and is not being created for whatever reason (“not tracked”).
The following line tells us why particle tracers were deleted:
because the halo became a subhalo (what exactly happens to particle tracers in this case depends on the settings)
because they escaped, meaning strayed too far from the halo
because they could not be found in the halo in the next snapshot (“unconn”, typically also because the particle left the halo)
because all their tracer results had finished (“all done”).
The final line relating to particle tracers tells us how many particles were tagged as belonging to a subhalo. Some of these tags were ignored because the particle is on the ignore list, in some cases a tracer was created due to the tag, and in some cases an existing result was altered to incorporate the tag information (“result”). These are technical distinctions and typically not important.
The next lines tell us about the statistics of subhalo tracers:
[Main] [SN 28] Tracer sho:
Active 429, new 130, deleted 93
Of del'td: host-sub 14 (15.1 %), escpd 0 (0.0 %), unconn 57 (61.3 %), all done 22 (23.7 %)
The fields have the same meaning as for particle tracers, but there are fewer scenarios. As tracers are analyzed, each halo accumulates tracer results:
[Main] [SN 28] Results:
tcr res current sn-new cm-new sn-fld cm-fld sn-svd cm-svd fld-f svd-f
ptl ifl 842775 97395 929445 0 0 0 0 0.000 0.000
ptl sbk 108471 17222 111760 4737 36875 0 0 0.248 0.000
sho ifl 944 130 1036 0 0 10 56 0.000 0.054
sho sbk 20 5 20 2 8 0 0 0.286 0.000
There is one line for each tracer and each result. The columns tell us the number of:
current: results currently kept in memory
sn-new: results that were successfully created during this snapshot
cm-new: cumulative sum of all results that have been successfully created
sn-fld: number of results that failed during this snapshot
cm-fld: cumulative number of all failed results
sn-svd: results saved to file during this snapshot
cm-svd: cumulative number saved to file
fld-f: fraction of total events that failed
svd-f: fraction of successful events that was saved (not all halos are saved to file).
We now move from statistics about the objects SPARTA is tracking into diagnostics of efficiency, memory, and timing:
[Main] [SN 28] Efficiency: Volume ratio 1.04 [1.03..1.04], snap files read 4 [4..4]
[Main] [SN 28] Exchanged 17 halos, 0 sub pointers, 1942 particles, 0 subhalos
One indicator for the efficiency of the domain decomposition is how large the volume is that the average process needs to consider compared to its share of the box. In an ideal world, that number should be close to unity (i.e., if the box was cleanly split between processes). In reality, and depending on the file format, the volume ratio can be significantly larger than one because the volumes around halos overlap, or because the files are not split into rectangular volumes. The number of snapshot files read per process tells us how many files the particles on a given process were distributed over.
The second line appears if domain decomposition is turned on. The number of exchanged halos should always be much smaller than the total number, otherwise the domain decomposition is failing.
We now move from memory to timing. The following line contains basic timing information:
[Main] [SN 28] Timing: Total 3.6, balance 1.40 (indep. 2.3, idle 0.3)
The total number tells us how long it took SPARTA to complete this snapshot. Note that this time
can vary drastically, from almost zero (if only halos but no particles are considered, for example)
to ~hours for heavy computations. If log_level_timing is set higher than zero, we also get a
much more detailed accounting of where SPARTA spent its time during this snapshot. The statistics
refer to that process that took the longest overall, but if the run is reasonably well balanced,
they should be representative of the other processes as well:
[Main] [SN 28] On max. proc (003) Time (s) %
[Main] [SN 28] ------------------------------------------------------------
[Main] [SN 28] Reading catalog (main) 0.1 4.0
[Main] [SN 28] Exchange 0.0 1.3
[Main] [SN 28] Reading snapshots 0.7 37.0
[Main] [SN 28] Process snap (indep.) 1.0 57.0
[Main] [SN 28] Building tree 0.8 45.9
[Main] [SN 28] Tree searches 0.0 1.9
[Main] [SN 28] Particle preparation 0.1 3.9
[Main] [SN 28] Tracer results 0.0 1.6
[Main] [SN 28] Tracer ptl result sbk 0.0 1.3
[Main] [SN 28] Analyses 0.0 1.3
[Main] [SN 28] Analysis hps 0.0 1.3
[Main] [SN 28] ------------------------------------------------------------
[Main] [SN 28] Timing total 1.8 100.0
The listing contains only fields that took up at least 1% of the total run time during this
snapshot. By setting log_level_timing to 2, you can get the full listing, but that will
generally not be more informative than the reduced listing (unless you want to know exactly how
much time a less-relevant action took up).
The following section tells us about the memory consumption of SPARTA, an extremely important number because large memory consumption can cause a job to crash. Memory is called persistent in this context if it persists between snapshots:
[Main] [SN 28] Pers. memory: Total 328 MB (82 per proc), halos 83 (25.3 %), tracers ptl 122 (37.2 %)
[Main] [SN 28] Results ifl 37 (11.4 %) sbk 4 (1.3 %)
The output gives a rough indication of which fields are responsible for the bulk of the memory consumption (for more detailed output, see below). In particular, the halos fraction refers to the actual halo objects, but does not include their tracers which are listed separately. Tracer results are yet another category.
However, we do not only care about how much memory is allocated for tracers and results, but also how efficiently it is allocated. Since the large arrays in SPARTA are typically dynamically allocated, they have some unused memory to avoid frequent re-allocations. The next few lines tell us the fraction of memory in the dynamical arrays that is actually used:
[Main] [SN 28] Memory eff.: Tracer ptl 0.697, ignore list 0.374, results: ifl 0.696 sbk 0.597
[Main] [SN 28] Tracer sho 0.014, ignore list 0.014, results: ifl 0.075 sbk 0.053
[Main] [SN 28] Analyses: rsp --- hps 1.000
We see that the large particle and particle result arrays are used to about 70% in this particular run. The subhalo arrays are less efficient, but they are also very small in comparison. The analysis arrays are allocated perfectly (in the case of hps) because there is exactly one per halo, and no splashback analyses have been allocated yet because they are computed at the end of a halo’s lifetime.
Finally, we may want a more detailed accounting of exactly which parts of the code consume the bulk
of the memory. Depending on the log_level_memory parameter, the final lines give us an
impression of the memory consumption of SPARTA:
[Main] [SN 28] Memory: Total current 0.3 GB (82.0 MB per proc), peak 1.1 GB (272.9 MB per proc)
[Main] [SN 28] Overall peak was 312925148, 298.4 MB on proc 3
[Main] [SN 28] Memory ID Description At overall peak: Byte MB Fraction
[Main] [SN 28] DA_HALO Halo objects 24832000 23.7 7.9 %
[Main] [SN 28] DA_TRACER Tracer objects 34080800 32.5 10.9 %
[Main] [SN 28] DA_RESIFL Infall result objects 10175360 9.7 3.3 %
[Main] [SN 28] DA_ALHPS Haloprops analysis objects 20228208 19.3 6.5 %
[Main] [SN 28] PARTICLES Raw particle data 182641248 174.2 58.4 %
[Main] [SN 28] PARTICLEMESSAGES Particle exchange packets 36458368 34.8 11.7 %
There is an important distinction between the memory currently occupied (which contains only objects that persist between snapshots, since this output refers to the end of the snapshot), and peak memory consumption, which would be responsible for out-of-memory crashes. As the latter is typically more relevant, the output focuses on peak consumption and tells us
the total peak and how much that would be per process if the memory was shared equally
what the actual peak on one process was, and which process
which fields occupied significant memory at that peak.
For example, the output above tells us that, at peak, raw particle data read from snapshot files and particle-data messages between processes were responsible for about 70% of SPARTA’s memory consumption.
Note that the peak memory consumption refers to the peak at any time, not necessarily at the given snapshot. Typically, the memory consumption rises with time as more and more halos form. However, in some cases, the load balancing algorithm shifts memory away from the peak-consumption process and the peak decreases for one or a few snapshots. In that case, the above lines will simply be repeated at the following snapshot(s).
Final output¶
Once all snapshots have been finished, SPARTA will (depending on settings) output final timing and memory information, e.g.:
[Main] All times are in seconds.
[Main] Task Time Per snap Level % Total %
[Main] --------------------------------------------------------------------------
[Main] Initialization 0.6 0.3
[Main] Snapshots 165.4 99.5
[Main] Statistics 0.0 0.0 0.0 0.0
[Main] Connection requests 0.0 0.0 0.0 0.0
[Main] Reading catalog (main) 4.9 0.1 2.9 2.9
[Main] Connections 0.2 0.0 0.1 0.1
[Main] Load balancing 12.7 0.2 7.7 7.6
[Main] Exchange 4.6 0.1 2.8 2.8
[Main] Halo box 0.4 0.0 0.2 0.2
[Main] Reading snapshots 39.4 0.7 23.9 23.7
[Main] Process snap (indep.) 84.7 1.4 51.3 51.0
[Main] Building tree 57.2 1.0 68.2 34.4
[Main] Sorting 2.2 0.0 2.6 1.3
[Main] Tagging subhalos 4.5 0.1 5.4 2.7
[Main] Halo loop 0.0 0.0 0.0 0.0
[Main] Tree searches 4.8 0.1 5.7 2.9
[Main] Mass profile 0.2 0.0 0.2 0.1
[Main] Particle preparation 8.4 0.1 10.0 5.0
[Main] Subhalo preparation 0.0 0.0 0.0 0.0
[Main] Tracer results 2.8 0.0 3.3 1.7
[Main] Tracer ptl result ifl 0.4 0.0 15.7 0.3
[Main] Tracer ptl result sbk 2.3 0.0 84.3 1.4
[Main] Mark ending tracers 0.2 0.0 0.2 0.1
[Main] Particle post-processing 0.0 0.0 0.0 0.0
[Main] Subhalo post-processing 0.0 0.0 0.0 0.0
[Main] Tracer ignore lists 0.1 0.0 0.1 0.1
[Main] Delete tracers 0.2 0.0 0.3 0.1
[Main] Find ended halos 0.0 0.0 0.0 0.0
[Main] Analyses 3.3 0.1 4.0 2.0
[Main] Analysis rsp 0.6 0.0 18.6 0.4
[Main] Analysis hps 2.7 0.0 81.4 1.6
[Main] Idle 17.8 0.3 10.7 10.7
[Main] Write results 0.3 0.0 0.2 0.2
[Main] Delete ended halos 0.3 0.0 0.2 0.2
[Main] Write restart files 0.0 0.0 0.0 0.0
[Main] Finalize 0.2 0.1
[Main] --------------------------------------------------------------------------
[Main] Total 166.2 100.0
Unlike the timing information output at each snapshot, this contains a full listing of all active parts of the code (but not parts that were excluded at compile-time). The level percentage refers to the fraction of the next-higher (less indented) level of processes. For example, all level percentages under “process snapshot” sum to 100%, and the individual tracer results also sum to 100%. The final column shows the fraction of the total runtime each part of the code occupied. In this case, the main takeaways are that loading particles and building the particle tree took up about 60% of the code’s runtime (a fairly typical situation).
The final output is a full accounting of SPARTA’s memory consumption:
Memory: Peak total consumption was 2.5 GB (634.6 MB per proc).
Overall peak was 751869780, 717.0 MB on proc 2. Memory consuming fields:
---------------------------------------------------------------------------------------------------------
| Memory ID | Description | Highest consumption | At overall peak |
| | | Byte MB | Byte MB Fraction |
---------------------------------------------------------------------------------------------------------
| DA_HALO | Halo objects | 48896000 46.6 | 48896000 46.6 6.5 % |
| DA_TRACER | Tracer objects | 178834032 170.5 | 171008552 163.1 22.7 % |
| DA_RESIFL | Infall result objects | 65665920 62.6 | 62944640 60.0 8.4 % |
| DA_RESSBK | Splashback result objects | 17882880 17.1 | 16944960 16.2 2.3 % |
| DA_ALRSP | Rsp analysis objects | 19035712 18.2 | 0 0.0 0.0 % |
| DA_ALHPS | Haloprops analysis objects | 47311264 45.1 | 46366320 44.2 6.2 % |
| DA_INT | Integer lists | 16000 0.0 | 0 0.0 0.0 % |
| DA_SUBPOINTER | Subhalo lists | 49056 0.0 | 47328 0.0 0.0 % |
| DA_ID | Ignored ID lists | 10168800 9.7 | 9722400 9.3 1.3 % |
| BOXES | Snapshot file boundaries | 38400 0.0 | 38400 0.0 0.0 % |
| HDF5BUFFER | HDF5 read/write buffer | 28360 0.0 | 0 0.0 0.0 % |
| CATREADING | Halo catalog read/exchange | 422776 0.4 | 0 0.0 0.0 % |
| SNAPREADBUF | Snapshot read buffer | 13374192 12.8 | 987932 0.9 0.1 % |
| PARTICLES | Raw particle data | 344000448 328.1 | 308899424 294.6 41.1 % |
| PARTICLEMESSAGES | Particle exchange packets | 92870656 88.6 | 86013824 82.0 11.4 % |
| OUTPUTBUF | Output buffers | 51559980 49.2 | 0 0.0 0.0 % |
| EXCHANGEBUF | Exchange buffers | 17152800 16.4 | 0 0.0 0.0 % |
| TREE | Tree calculations | 65879304 62.8 | 0 0.0 0.0 % |
| TREEPOT | Tree potential | 123584 0.1 | 0 0.0 0.0 % |
| DOMAINDECOMP | Domain decomposition | 42416 0.0 | 0 0.0 0.0 % |
| HALOLOGIC | Halo/subhalo handling | 191352 0.2 | 0 0.0 0.0 % |
| TRACERHANDLING | Tracer handling | 25834 0.0 | 0 0.0 0.0 % |
| TCRPTL | Tracer: particles | 718128 0.7 | 0 0.0 0.0 % |
| RESSBK | Result: splashback | 24 0.0 | 0 0.0 0.0 % |
| ANLRSP | Analysis: Rsp | 267266 0.3 | 0 0.0 0.0 % |
| ANLHPS | Analysis: Halo properties | 276436 0.3 | 0 0.0 0.0 % |
---------------------------------------------------------------------------------------------------------
Again, here we include all memory categories that contributed any memory consumption, even if a small fraction. The “highest consumption” columns refer to the peak consumption in each field, whereas the right columns refer to the consumption at the overall peak on any one core. The former give us a feeling for which fields are important consumers, whereas the latter allow us to diagnose causes of possible out-of-memory situations. The two listings can be quite different; note, for example, that the various output and exchange buffers can be significant memory consumers, but that they are zero at peak because peak occured during snapshot loading rather than during the exchange or output steps.