search

cms-sw / cmssw

CMS Offline Software
http://cms-sw.github.io/
Apache License 2.0
1.08k stars 4.31k forks source link

Memory Jump from `14_1_0_pre5` for Phase2 Workflows #45854

Open AdrianoDee opened 2 months ago

AdrianoDee commented 2 months ago

In one of the latest round of RelVal productions we have observed an increased usage of memory for the RECO step for Phase2 (D110) PU workflows. We spotted this since many jobs started to fail due to an excessive memory usage. This happened because we usually set the memory limit per job to 16GB (for 8 threads 2 streams jobs) and we went quite frequently above that threshold. See e.g. the error report for a TTbar workflow showing the error report (find below the memory reported by condor to have exceeded the maxPSS). For the equivalent in pre4 we just had a few failures.

image

See also the PeakValueRss reported in the FrameworkJobReport.xml output for each job. I'm not sure how to interpret the low value tail for pre5.

image

Bottom line: something happened between pre4 and pre5 that caused the memory usage at RECO step to jump quite a bit.

Reports

I've copied all the job reports and configs for TTbar PU=200 here or you can check in

  1. /eos/cms/store/logs/prod/2024/06/WMAgent/pdmvserv_RVCMSSW_14_1_0_pre4TTbar_14TeV__STD_2026D110_PU_240604_235438_8449/
  2. /eos/cms/store/logs/prod/2024/08/WMAgent/pdmvserv_RVCMSSW_14_1_0_pre5TTbar_14TeV__STD_2026D110_PU_240801_183220_4814/

We have "solved" this on our side by rising the memory used to 20GB. And the situation is unchanged in 14_1_0pre6 (and 14_1_0_pre7) since we are still seing failures if the memory max is set to 16GB.

AdrianoDee commented 2 months ago

assign reconstruction

AdrianoDee commented 2 months ago

assign upgrade

cmsbuild commented 2 months ago

New categories assigned: reconstruction,upgrade

@jfernan2,@mandrenguyen,@srimanob,@subirsarkar you have been requested to review this Pull request/Issue and eventually sign? Thanks

cmsbuild commented 2 months ago

cms-bot internal usage

cmsbuild commented 2 months ago

A new Issue was created by @AdrianoDee.

@Dr15Jones, @antoniovilela, @makortel, @mandrenguyen, @rappoccio, @sextonkennedy, @smuzaffar can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

makortel commented 2 months ago

@AdrianoDee What would be the way to reproduce these jobs in pre4 and pre5 (onwards)?

AdrianoDee commented 2 months ago

@makortel if you check this (or under /eos/user/a/adiflori/www/phase2_pre5_memory_issue/)

I've copied all the job reports for TTbar PU=200 here

you will find all the config used by each job (so with the relative lumisections) as a PSet.py (loading a pickle file). E.g. in /eos/user/a/adiflori/www/phase2_pre5_memory_issue/14_1_0_pre5/0/job/WMTaskSpace/cmsRun1 there's everything needed to run it

[adiflori@lxplus957 cmsRun1]$ ls -tlrh
total 67M
-rw-r--r--. 1 adiflori zh 419K Sep  2 01:15 FrameworkJobReport.xml
-rw-r--r--. 1 adiflori zh  128 Sep  2 01:15 PSet.py
-rw-r--r--. 1 adiflori zh  38M Sep  2 01:15 PSet.pkl
-rw-r--r--. 1 adiflori zh  70K Sep  2 01:15 cmsRun1-stdout.log
-rw-r--r--. 1 adiflori zh  54K Sep  2 01:15 Report.pkl
-rw-r--r--. 1 adiflori zh  227 Sep  2 01:15 cmsRun1-stderr.log
drwxr-xr-x. 2 adiflori zh 4.0K Sep  3 16:30 __pycache__
-rw-r--r--. 1 adiflori zh  29M Sep  3 16:30 dump.py

where (dump.py) was just me checking the edmConfigDump output made sense (and it does).

AdrianoDee commented 2 months ago

(Made clearer in the description the link includes the job configs too)

jfernan2 commented 1 month ago

From RECO side we have been looking at this increase in RSS memory profile since the beginning[1] (indeed there is a drop of RSS to normal levels at the end of the tasks) though igprof profile does not see any difference in mem live consumption[2][3]

We have looked at the allocated memory from individual Reco Modules in pre4[4] and pre5[5] and just a general light increase in across all modules can be seen, but not a single real culprit.

Our suspect from the beginning was the change to AL9 of the test machines, since pre4>pre5 was at almost the same time as the transition of the operative system, but we did not know if this theory made sense since we ignored how RSS mem is managed. I have discarded this hypotesis now by running pre4 again in AL9.

[1] https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_12634.21.html [2] https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/comp_igprof/html/CMSSW_14_1_0_pre5/12634.21/step3/mem_live.1.html [3] https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/comp_igprof/html/CMSSW_14_1_0_pre5/12634.21/step3/mem_live.399.html

[4] https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/circles/piechart.php?local=false&dataset=CMSSW_14_1_0_pre4%2Fel8_amd64_gcc12%2F12634.21%2Fstep3_circles&resource=mem_alloc&colours=default&groups=reco_PhaseII_private&threshold=0

[5] https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/circles/piechart.php?local=false&dataset=CMSSW_14_1_0_pre5%2Fel8_amd64_gcc12%2F12634.21%2Fstep3_circles&resource=mem_alloc&colours=default&groups=reco_PhaseII_private&threshold=0

makortel commented 1 month ago

Our suspect from the beginning was the change to AL9 of the test machines, since pre4>pre5 was at almost the same time as the transition of the operative system, but we did not know if this theory made sense since we ignored how RSS mem is managed.

We have seen before reports or suspicion on the EL8/EL9 host OS leading to more memory being used compared to SLC7 https://github.com/cms-sw/cmssw/issues/42929 https://github.com/cms-sw/cmssw/issues/45028

I have discarded this hypotesis now by running pre4 again in AL9.

@jfernan2 Just to confirm I understood correctly, do you mean that you don't see a significant difference in memory usage between pre4 and pre5 when running on the same node or OS (AL9 I guess)?

@AdrianoDee Is there significant difference in sites or host OS versions where the jobs were run between pre4, pre5, pre6, and pre7?

makortel commented 1 month ago

I've copied all the job reports for TTbar PU=200 here

Using the setup from above, I processed the same 10 events of the pre4 input on an EL8 node using pre4 and pre5

The number of processed events was small, and real statistical conclusions would require more runs, but at least the numbers are not outrageously different.

jfernan2 commented 1 month ago

@jfernan2 Just to confirm I understood correctly, do you mean that you don't see a significant difference in memory usage between pre4 and pre5 when running on the same node or OS (AL9 I guess)?

My initial conclusion yesterday was that I was seeing NO difference between AL9 and older OS, based on this plot for wf11834.21:

https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_11834.21.html

where both pre4, pre5 (and pre6) run on AL9, and, except for the very fist few events, RSS was lower for pre4 than pre5 (and pre6)

However, this night ended my test on another crosscheck wf12634 in pre4 using AL9, and things have changed:

https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_12634.21.html

pre4 is now at the RSS levels of pre5 (pre6 and pre7) for more than the half of the first events.

So, it looks like there is some dependence on AL9 and the way it handles the RSS....

I am running some extra tests on pre3 using AL9 (all releases except pre4, pre5, pre6 and pre7 in those plots were made before AL9 entered into the game) and with a Phase2 wf25034.21 using pre4 AL9 in order to confirm.

I also noticed that the trend in RSS over the job is very different in MC (high at the beginning and then dropping) wfs w.r.t. those in data (increasing over time), see e.g. https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_136.889.html https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_140.047.html

although the number of events in the task for data wfs is an order of magnitude higher than for mc wfs. I am also testing those again in pre4 using AL9 to have another independent view

AdrianoDee commented 1 month ago

On our side we submit all the RelVals with SCRAM_ARCH=el8_amd64_gcc12 so I suppose they all run in el8.

jfernan2 commented 1 month ago

That's the case too in our profiling tests but the machine says at the beginning of the log: Building remotely on vocms011 (el9 GenuineIntel reco-profiling no_label cpu-32 amd64)

AdrianoDee commented 1 month ago

Ah so there's some possible loop-hole, let me check more carefully.

jfernan2 commented 1 month ago

After my last profiling tests in pre3 and pre4 with other MC and data workflows, I confirm that running in AL9 increases the peak RSS by a 20-30% in the same job w.r.t. previous OS versions. The RSS gets increased at the beginning of the task/job and then drops for the last events. I will update the plots above with the latest tests later, you can have all the results in text mode at the following folder (dates from Aug and Sep mean AL9):

ls -ld /eos/cms/store/user/cmsbuild/profiling/data/CMSSW_14_1_0_pre?/el8_amd64_gcc12/*/step3_TimeMemoryInfo.log | grep Sep

makortel commented 1 month ago

On our side we submit all the RelVals with SCRAM_ARCH=el8_amd64_gcc12 so I suppose they all run in el8.

Well, yes and no. The jobs will use the el8 binaries, and thus require either el8 host OS or an el8 container, but in the container case, the host OS can be (nearly) anything (as far as scram and CMSSW are concerned).

srimanob commented 1 month ago

Hi, Is the https://github.com/cms-sw/cmssw/issues/45854#issuecomment-2333615751 answered the increasing of Memory? One thing if you don't spot anything on RECO is DQM. DQM runs on the same step with RECO, so I don't think we can separate memory used for DQM or RECO step in relvals. I see several DQM-related PR added to in 14_1_0_pre5. Just a guess if we don't spot the issue from RECO.

jfernan2 commented 1 month ago

Hi @srimanob The RECO profiling tests show that running in AL9 produces an increase of the RSS memory of 20-30% in the first part of the job, DQM part is excluded in these jobs.

srimanob commented 1 month ago

Right @jfernan2 I mean if this 20% increase answers the issue, then we focus on it. If not, we need to look on something beyond RECO, and DQM may be the next target as it is not part of profiling.

Do we know if job crash in very beginning, sometimes later.

jfernan2 commented 1 month ago

No, there is no job crash, just RSS memory is increased at the beginning of the job, see e.g. https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_11834.21.html

makortel commented 1 month ago

No, there is no job crash, just RSS memory is increased at the beginning of the job, see e.g. https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_11834.21.html

I wonder how reproducible is this RSS behavior wrt. the job progress (in terms of event number)? I.e. how the RSS vs "time" plot would look like if you'd run the same job (e.g. pre5) several times on the same node?

jfernan2 commented 1 month ago

I can'y give you an exact answer, but based on the graphs I sent you for several pre-releases, I would expect fluctuations around the mean value as those given in first left plot of https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_140.047.html

of the order of 400MB around a mean central value. What is probably more significant is the RSS peak value at the left column of table in the link above

srimanob commented 1 month ago

Hi @AdrianoDee

Looking on absolute memory we use in pre5 on Alma9, I try to run as RelVals, 100 jobs, 100 events/job, and what I observe is the RSS is quite stable, a little bit lower than 15 GB. RSS is typically larger when compared to PSS, so I don't understand why we have very large PSS. That means RSS is even larger or equal.

For current action, 1 stream should allow you to survive in 16 GB PSS. I also measure it.

8 Threads, 2 Streams T8S2

8 Threads, 1 Stream T8S1

jfernan2 commented 1 month ago

My last test repeating on AL9 the pre3 shows high RSS for the whole job/task, from event 1 to 400: https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_11834.21.html

Same for data wfs on pre4 (on AL9): https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_136.889.html https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/summary_plot_html/CMSSW_14_1_step3_140.047.html

makortel commented 1 month ago

Would someone be able to compare (again) the behavior of cmsRun (jemalloc), cmsRunTC (TCMalloc), and cmsRunGlibC (glibc malloc)?

makortel commented 1 month ago

@srimanob @jfernan2 Do you run your tests on an otherwise free machine, or is other activity possible? In https://github.com/cms-sw/cmssw/issues/42387 it was reported that in cases where the memory ends up being fragmented (because of being heavily used by many processes) termination of an unrelated process can result in a huge spike in RSS (with jemalloc).

jfernan2 commented 1 month ago

In my case I use the dedicated machine for RECO profiling vocms011 which has two profiling tasks at most running in parallel

jfernan2 commented 1 month ago

In our test cmsRunGlibC is running for the igprof part: e.g. igprof -d -mp -z -o step3_igprofMEM.gz -t cmsRunGlibC cmsRunGlibC step3_igprof.py

but gives no difference in results for pre5 w.r.t. pre4: https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/comp_igprof/html/CMSSW_14_1_0_pre5/11834.21/step3/mem_live.1.html https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/results/comp_igprof/html/CMSSW_14_1_0_pre5/11834.21/step3/mem_live.399.html

Full details are here: https://cms-reco-profiling.web.cern.ch/cms-reco-profiling/

makortel commented 1 month ago

In our test cmsRunGlibC is running for the igprof part: e.g. igprof -d -mp -z -o step3_igprofMEM.gz -t cmsRunGlibC cmsRunGlibC step3_igprof.py

but gives no difference in results for pre5 w.r.t. pre4:

I think this is expected behavior. IgProf (and any memory profiler that hooks into the memory allocation functions) reports the memory the application requests, and this correlates with the VSIZE (that includes also "overheads" such as the OS reserving memory in terms of pages of e.g. 4 kB or 64 kB). RSS, on the other hand, depends on the amount of memory that is actually being touched by the application.

For example, 

std::vector<int> vec;
vec.reserve(1024*1024);

would (in the leading order) result in 4 MB increase in VSIZE, while RSS would not be impacted. Only code like vec[0] = 0; would result in RSS to increase. And a memory profiler would only see the memory allocation from vec.reserve().

With https://github.com/cms-sw/cmssw/issues/45854#issuecomment-2340904341 I really meant keeping all other things equal, and just using cmsRunTC / cmsRunGlibC instead of cmsRun to run the configuration.

srimanob commented 1 month ago

Hi @makortel

I run jobs in CERN Batch. So, the machine I run may have other activities, but may not be CMSSW. I am submitting jobs with cmsRunTC / cmsRunGlibC.

From your comment, https://github.com/cms-sw/cmssw/issues/45854#issuecomment-2340916395, it is highly possible if we will run the same relvals job in the same machine. I assume. I don't know much detail on machine we dedicate for relvals, but I assume it is not a random in the pool.

srimanob commented 1 month ago

Hi @makortel cmsRunGlibC: <Metric Name="LargestRssEvent-f-RSS" Value="36023.4"/> cmsRunTC: <Metric Name="LargestRssEvent-f-RSS" Value="14986.6"/> cmsRun: <Metric Name="LargestRssEvent-f-RSS" Value="14858.2"/>

makortel commented 1 month ago

Thanks @srimanob. Interesting that jemalloc shows the smallest RSS, IIRC in the past at lest one of TCMalloc or GlibC has resulted smaller RSS but then been significantly slower in a multithreaded program.

srimanob commented 1 month ago

Hi @makortel To be sure, do you want me to do in 1 threads or normal 8 threads? I usually measure with 8 threads to use the number for production.

jfernan2 commented 1 month ago

For the peak RSS I have also this plot prior to the inclusion of AL9, I do not know if the fall in 13_3_X was due to AL8, I don't recall the dates of the previous Linux version https://gitlab.cern.ch/cms-reconstruction/cms-reco-profiling/-/blob/main/results/release_mem_run3_8thread.png?ref_type=heads

AdrianoDee commented 3 weeks ago

Hi, we see failures even when running

AdrianoDee commented 3 weeks ago

Another piece of information that seems interesting to me. When running exactly the same wf, with exactly the same settings, with SCRAM_ARCH=el9_amd64_gcc12 the situation improves. I've run in 14_1_0_pre7 a TTbar Phase2 PU200 wf with the arch set to:

So it seems something related to the OS (and the fact that we presumably run in containers).

AdrianoDee commented 3 weeks ago

For the moment the only stable and successful setup I found is 8 threads 1 stream and 20GB.

makortel commented 3 weeks ago

Were the jobs run on the same nodes (or the same underlying OS)?

makortel commented 3 weeks ago
  • 8 threads 1 stream with 16GB. See e.g. this job and its logs;
  • 8 threads 2 streams with 20GB. See e.g this job and its logs;

Plotting the RSS and VSIZE from these results image

I think we'd need a serious analysis of where the memory is being used. The 70 GB VSIZE is scary (especially given what we've learned of the OS-dependent behavior of RSS elsewhere, e.g. in https://github.com/cms-sw/cmssw/issues/46040 or https://github.com/cms-sw/cmssw/issues/42387).

One sort-of obvious memory hog is the (playback of) classical mixing.

dan131riley commented 3 weeks ago

Playback has some serious inefficiencies if the upstream PU producer is multi-threaded/multi-streamed, but I wouldn't expect that to cause memory explosion issues. It might be interesting to run the whole chain with one stream for each step (I believe there should only be one pileup input per stream, so the number of threads shouldn't matter).

Playback could be made much more time and IO efficient with some caching in the embedded file input module, but wouldn't expect a large memory impact.

AdrianoDee commented 3 weeks ago

Were the jobs run on the same nodes (or the same underlying OS)?

Should be el9 for both. I say should because I can't find any evidence in the logs of which is the underlying OS. I need to properly check.

For the playback, note that we see similar failures even when the jobs is (wrongfully) submitted with no PU replay at RECO step (as in this case for example with 20GB 2 streams and 8 cores).

AdrianoDee commented 3 weeks ago

I've resubmitted a couple of wfs excluding the VALIDATION step, since in the past there have been issues there and the prod-like wfs used for the reco-timings don't run it and don't show such a jump.

AdrianoDee commented 2 weeks ago

One further piece. The wf with no VALIDATION or DQM sent with 16GB and 2 streams was successful. As a comparison:

From the logs I see the VSIZE and RSS much more under control (the no-validation job ran on twice of the events given no failures).

P.S. let me thank @fabiocos for suggesting the source could be there ( :

drawing drawing
AdrianoDee commented 2 weeks ago

assign dqm

cmsbuild commented 2 weeks ago

New categories assigned: dqm

@antoniovagnerini,@nothingface0,@rvenditti,@syuvivida,@tjavaid you have been requested to review this Pull request/Issue and eventually sign? Thanks

srimanob commented 2 weeks ago

Hi @AdrianoDee It seems I should have bet more last month :)

Thanks for checking. In validation, you include the PU replay as default of validation + DQM, right? Note also on https://github.com/cms-sw/cmssw/issues/38828 if we run something unnecessary twice.

AdrianoDee commented 2 weeks ago

Yes, the replay is included

AdrianoDee commented 2 weeks ago

Ah but note that we have the same memory “explosion" even when not-included.

Il giorno 17 ott 2024, alle ore 07:02, Adriano Di Florio @.***> ha scritto:

Yes, the replay is included

— Reply to this email directly, view it on GitHub https://github.com/cms-sw/cmssw/issues/45854#issuecomment-2418504651, or unsubscribe https://github.com/notifications/unsubscribe-auth/AEA6IGV3J7XHZYSZDWRH7ADZ35AG7AVCNFSM6AAAAABNPTBKXCVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDIMJYGUYDINRVGE. You are receiving this because you are subscribed to this thread.

makortel commented 1 week ago

I profiled the example job, I think it was this one

  • 8 threads 2 streams with 20GB. See e.g this job and its logs;

, with IgProf, and below is the MEM_LIVE after first event (full profile is here).