Memory usage issue when filling TTree

nlurkin · February 21, 2017, 6:53pm

Dear ROOT experts,

We are running into a very strange issue with ROOT TTrees and memory usage.
I managed to produce a minimal setup able to reproduce the problem (minimal.C, provided in attachment). The logic is the following:

I use the experiment reconstruction software to reconstruct about 40000 events and produce a ROOT file. Then I use the step0() of my minimal script to clone the input tree and extract the first event of this ROOT file (the output is provided in attachment as event0_bad.root, and the behavior does not depend on which event I am using).

 ./myscript 0 reco_40000.root event0_bad.root

I use the experiment reconstruction software to reconstruct about 1000 events and produce a ROOT file (so a subset of the one in the previous point). Then I use the step0() of my minimal script to clone the input tree and extract the first event of this ROOT file (the output is provided in attachment as event0_good.root).

 ./myscript 0 reco_1000.root event0_good.root

Now already we can see a difference between the two ROOT files that we cannot understand. Despite the fact the content of the trees are identical, if we open them in ROOT and print the TTrees with

Reco->Print()

, we see that the _bad one has big numbers in the basket size (example: 886272) while the _good one as basket sizes of 32000 (default). Furthemore the memory usage of step0() in the _good case is about 360Mb while it is about 740Mb in the _bad case. It should be noted as well that we observe a memory usage jump of ~ 200Mb at event 31285 when running our reconstruction software, and this seems to be linked only to the number of events written in the output tree and not to a specific events as shifting the event processing window produces the same effect. These memory jumps always appear in the problematic cases.
-> How can all these differences be explained?

Because this problem seems to be linked with statistics and I need to process about 40000 events, I use the step1() of my minimal script

    ./my_script 1 event0_bad.root event0_bad_1000.root
    ./my_script 1 event0_good.root event0_good_1000.root

to multiply this event 1000 times (this step doesn’t seem to have any influence in the problem, I just cannot input these event0_ files 40000 times in the TChain, it is too slow. So instead I multiply it 1000 times and input the file 40 times in the TChain). This produces the files event0_bad_1000.root and event0_good_1000.root. Then step2() of the script

    ./my_script 2 event0_bad_1000.root event0_bad_final.root
    ./my_script 2 event0_good_1000.root event0_good_final.root

just copies the entries of the input TChain into an output TTree. We can see that the memory usage (provided in attachment) is very different in both cases. In the _good one it is constant around 360Mb, while in the _bad one we observed a 55Mb jump at event 31285 (same value as in point 1. despite the fact we are processing the event 0 over and over again).
-> We do not understand how to explain (and therefore fix) such behavior. Two files where the trees have identical content have different behavior when going through the exact same processing steps. We think this is linked to the writing of the output TTree on disk (which we suspect happens at the same moment as the memory usage increase).

This is the simplest setup I managed to create that reproduces the issue. With all detector branches activated, this translates into 1.5Gb memory usage jumps which causes us many troubles. We also noticed that the speed of processing events (including Filling the output TTree) visibly slows down when this memory jump occurs. I interprete this as a sign that the basket size is suddenly much bigger and therefore writing events in the tree takes more time.

We would be really glad if anyone with a better understanding of how the TTree works could help us figure out what is wrong.

You will find in attachment of this post:

the script minimal.C I am using to reproduce this. It can be compiled with

g++ -o my_script minimal.C -L/cvmfs/sft.cern.ch/lcg/releases/LCG_84/ROOT/6.06.02/x86_64-slc6-gcc49-opt/lib `root-config --libs` -I`root-config --incdir` `root-config --cflags` -g

The script is run with:

./my_script stepNumber inputFile outputFile

the root file containing the single event in the _good and _bad cases (event0_good.root and event0_bad.root). The original file (not attached) containing 40000 events is about 70Mb.
The two memory plots referenced earlier without (_good) and with (_bad) the memory usage jump at 31285.

The ROOT version we are using is 6.06.02

Thanks for any help!

event0_good.root (19 KB)
event0_bad.root (19.1 KB)
minimal.C (5.25 KB)

Pepe_Le_Pew · February 21, 2017, 7:16pm

In the ends of your “step0”, “step1” and “step2”, try to add:
delete out;
delete in;

nlurkin · February 21, 2017, 7:46pm

Hello,

Thanks for your fast answer, but that makes no difference at all.

pcanal · February 22, 2017, 10:07pm

Hi,

The trigger is:root [2] Reco->GetAutoFlush() (long long) 31287In the ‘good’ file, the auto flush setting is still the default.

This indicates that the tree was (implicitly or explicitly) set to have ‘cluster’ of entries contains 31287 entries. The net result is that the TTree is trying to fit into a single set of basket/buffer (and thus is memory) that many entries.

So in the large file, the basket size is adjusted to hold that many entries. When you clone the TTree, the basket is (intentionally) not reset.

[quote]while in the _bad one we observed a 55Mb jump at event 31285 (same value as in point 1. despite the fact we are processing the event 0 over and over again). [/quote]This jump is likely to accommodate the compression buffer of those large basket. When you reach the end of a cluster, all the basket are compressed and then flush to disk. To do the compression we need one memory buffer large enough to accommodate the largest buffer.

Note the size of the cluster is determine either by an explicit call to SetAutoFlush, which can take the size of the cluster either in number of event or in (approximate) compressed size.

If the size is given in the (approximate) compressed size [This is actually the default with 32Mb], then the TTree starts with the buffer size given explicitly or implicitly (the default is 32Kb per basket) and compresed/flush the basket when they are full. Once the amount of data flushed reached the 32mb (of compressed data), the TTree does:

record the number of entries (let’s say N), so far and use is for now on as the frequency of flushing
recalculate the basket size to minimize the number of basket in the cluster (and roughly it resize each basket to be able to hold N entries based on the data size seen so far.

One extreme case where using the default can be ‘bad’ for memory usage is the case where the first entries have a high compression ratio. Let’s say that the first 32000 entries are 1K of total compressed data. Then they all fit in one cluster and the memory allocated for the baskets in total will 30Mb times the compression ratio. Like say for example 40, in which case, you need 1,200Mb).

Cheers,
Philippe.

nlurkin · March 2, 2017, 4:18pm

Your answer was exactly what we needed to know. We have indeed many branches with a compression factor of ~100. We managed to mitigate the problem by playing with SetBasketSize and SetAutoFlush. We manage to save in total about 1Gb of memory usage.

Thanks for your help!

bozzochet · September 22, 2017, 1:08pm

Dear Philippe (or anyone else),

I’m having a similar problem. Before opening a new topic I searched a little and I decide to ‘up’ this one.

I have a program (compiled executable) that is accessing a certain amount of trees in ROOT files (usually 200, chained in a TChain) and creating multiple (later I’ll explain why multiple) ‘skimmed’ (less entries and less/different branches) versions of the same TTree.

  int complevel=ROOT::CompressionSettings(ROOT::kLZMA, 2);
  printf("The choosen compression level is %d\n", complevel);

  for(int itag=0; itag<NTAG; itag++)
    {
      
      for(int isign=0; isign<NSIGN; isign++)
        for(int iene=0; iene<NENE+1; iene++)
          {
            char fname[1024];
            sprintf( fname, "%s_%s%s_%.2d_%.6d_%.6d.root", sig_name[isign], tag_name[itag], (SPAN<=5&&SPAN>=0)?Form("_sp%d",SPAN):"", iene, list_first_line, list_last_line);
            f[isign][itag][iene] = new TFile( Form("%s/%s", dir, fname), "RECREATE", "File with Superskimmed Hadded trees", complevel);
            f[isign][itag][iene]->cd();
            t[isign][itag][iene] = chain->CloneTree(0);
            
            // t[isign][itag][iene]->SetAutoSave(1000000);//1 MB
            t[isign][itag][iene]->SetAutoFlush(-1000000);//1 MB
            t[isign][itag][iene]->SetDirectory(f[isign][itag][iene]);

            t[isign][itag][iene]->SetBranchStatus("accPhi",   0);
            t[isign][itag][iene]->SetBranchStatus("accTheta", 0);
            t[isign][itag][iene]->SetBranchStatus("accP",     0);

            //****
            //New Branches
            //****
            t[isign][itag][iene]->Branch("eop",           &eop,           "eop/F");
            .....

where, as you can see, the new TFile is opened, the original TChain is cloned, the SetAutoFlush is called, some Branches are disabled and some new other are created.
Then the program continues and at a certain moment the loop on the original chain entries starts:

  for(int ientry=0; ientry<nentries; ientry++)
    {
      chain->GetEntry(ientry);
      .....

and at the end:

      .....
      t[tree_sign][tree_analtag][ene_index]->Fill(); 
    }

Now:

if I comment the ‘tree->Fill()’, I have a footprint in memory like

mduranti@ui02-ams:TreeBuilder> top | grep Build_super
21771 mduranti  20   0  166m  40m  22m D  7.7  0.2   0:00.49 Build_superskim                                                                                                                                                                                                                                                  
21771 mduranti  20   0  166m  40m  22m D  6.3  0.2   0:00.68 Build_superskim                                                                                                                                                                                                                                                  
....                                                                                                                                                                                                                                                  
21771 mduranti  20   0  234m 110m  22m R 89.4  0.5   5:44.24 Build_superskim                                                                                                                                                                                                                                                  
21771 mduranti  20   0  344m 156m  22m R 91.4  0.7   5:47.01 Build_superskim
....

for the whole program execution: so there’s no leak or stuff like this.

If uncomment the ‘Fill()’:

mduranti@ui02-ams:TreeBuilder> top | grep Build_super
18700 mduranti  20   0  166m  39m  22m D  5.0  0.2   0:01.05 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0  166m  39m  22m D  5.0  0.2   0:01.20 Build_superskim                                                                                                                                                                                                                                                  
....                                                                                                                                                                                                                                               
18700 mduranti  20   0  220m  94m  22m D 48.3  0.4   0:04.01 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0  226m 100m  22m S  6.6  0.4   0:04.21 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 7923m 3.0g  22m R 77.1 12.9   0:06.54 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 9078m 3.5g  22m R 93.7 14.8   0:09.38 Build_superskim                                                                                                                                                                                                                                                  
....                                                                                                                                                                                                                                                 
18700 mduranti  20   0 10.5g 5.0g  22m R 99.5 21.2   6:55.60 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 10.5g 5.0g  22m R 98.1 21.2   6:58.56 Build_superskim                                                                                                                                                                                                                                                  
....                                                                                                                                                                                                                                                  
18700 mduranti  20   0 10.4g 5.0g  22m R 100.0 21.4   9:36.62 Build_superskim                                                                                                                                                                                                                                                 
18700 mduranti  20   0 10.4g 5.0g  22m R 99.7 21.4   9:39.64 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 13.4g 6.1g  22m D 84.0 26.2   9:42.18 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 15.8g 7.1g  22m R 88.4 30.2   9:44.86 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 17.0g 7.5g  22m R 97.8 32.0   9:47.82 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 17.2g 7.6g  22m R 98.8 32.4   9:50.82 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 17.3g 7.7g  22m R 97.7 32.6   9:53.78 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 17.6g 7.7g  22m R 65.1 32.9   9:55.75 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 17.7g 7.8g  22m R 93.9 33.2   9:58.59 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 17.8g 7.8g  22m R 86.7 33.4  10:01.21 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 18.0g 7.9g  22m R 90.1 33.9  10:03.94 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 18.4g 8.1g  22m R 88.8 34.5  10:06.63 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 18.4g 8.1g  22m R 98.7 34.5  10:09.62 Build_superskim                                                                                                                                                                                                                                                  
....                                                                                                                                                                                                                                                  
18700 mduranti  20   0 20.5g 9.8g  22m R 94.0 41.7  23:30.85 Build_superskim                                                                                                                                                                                                                                                  
18700 mduranti  20   0 20.5g 9.8g  22m R 98.3 41.7  23:33.83 Build_superskim

growing and growing, essentially for the whole job (sometimes I also seen a small decrease at a certain point and then the increase starting again.

Where’s my error?

Consider that the various trees (one for each energy range and for one sign of the charge of the particle) are, in total 308 (I know they’re a lot, but neither thousands…) and, given the 1MB I put in AutoFlush the footprint should stay well below 1GB. Why isn’t the case? And why the VIRT memory is even bigger?

Thanks,
Matteo

P.S.: The footprint in memory is also much bigger than the files size:

18700 mduranti  20   0 15.4g 7.9g  22m R 94.3 33.5  60:22.69 Build_superskim

(at the end of the execution)

while

mduranti@ui02-ams:TreeBuilder> ls *ive_*.root | wc -l
308
mduranti@ui02-ams:TreeBuilder> du -sh *ive_*.root
2,7M	Negative_ForAnal_00_007000_007199.root
2,3M	Negative_ForAnal_01_007000_007199.root
....
128K	Positive_ForAnal_75_007000_007199.root
128K	Positive_ForAnal_76_007000_007199.root
2,0G	total

P.S.2: If I remove the compression in the TFile essentially nothing changes and the total file size is 2.2G, so still much less than the footprint in memory.

Axel · November 29, 2017, 4:32pm

Apologies nobody replied earlier! In general it’s much easier for us to keep track of new issues through new posts, instead of up-ing seemingly related old ones.

Are you ever closing the files, or are you collecting files and trees in memory? The loop

suggests that you’ll end up with NTAG*NSIGN*NENE files and trees in memory. Depending on their values that might be a lot!

I.e. I’d change f and t to be simple local variables in the inner loop, instead of arrays, and make sure you call delete f at the end of each iteration.

Cheers, Axel.

bozzochet · December 1, 2017, 9:25am

Ciao Axel,

I replied to the post since usually the moderators prefer to not to open new post for the same issue, and I was quite sure that we were talking about the very same issue.

I understand that my message was quite long but, as I said, NTAG*NSIGN*NENE is 308 and changing to local variables and/or delete them would have no effect (but a crash…): they are TFiles and TTrees that are created at the BEGINNING of the execution and BEFORE the event loop. Then the program loops over the events and, depending on the event characteristics, one of the 308 trees is Filled(). At the end of the event loop the TFiles are Closed().

As I wrote if I SIMPLY do not Fill() the trees, the footprint is small: this means that there’s no other memory leak.

Ciao,
Matteo

Axel · December 1, 2017, 10:19am

Hi,

Your input files will have a tree cache of 30MB each, times 300 makes 9GB. Virtual memory is not significant, these are simply address values handed out by the kernel. What matters is the 7.9GB RSS.

Could you delete the input files at the end of each iteration? Do you actually need the files and trees around after the loop? If not my suggestion will also make nicer code…

Maybe @pcanal knows the connection with Fill()?

And:

Not here Because more often than not, similar issues end up having nothing in common with the original one. We always prefer new topics.

Cheers, Axel.

bozzochet · December 1, 2017, 11:02am

Ok for the “new topic”, I’ll try to remember.

Really I don’t understand your point… The “input” files are 200 files TChained into chain, a single TChain. I do not Open() any single input TFile, so I cannot close… TChain is not smart to “keep in memory” just the current file? “Each iteration” (out of NTAG*NSIGN*NENE) is JUST the CREATION of the OUTPUT TFile and TTree and the loop over the events (so over the chain) is AFTER all the iteration.

Again, anyhow: just commenting the Fill() makes the footprint really small, so I don’t think can be related to the input TChain…

Ciao,
Matteo

P.S.: I realized that maybe the confusion of the NTAG*NSIGN*NENE iterations come from the fact that in the “snippet” I didn’t close the loop before the following snippet. I’ll edit…

bozzochet · December 1, 2017, 11:10am

No, I cannot edit anymore…

In my “original” post the loop:

is closed at the end of the snippet and the loop is done afterward. So is like:

for(int itag=0; itag&lt;NTAG; itag++) {
    for(int isign=0; isign&lt;NSIGN; isign++) {
       for(int iene=0; iene&lt;NENE+1; iene++) {
          ......
       }
    }
 }
...
for(int ientry=0; ientry<nentries; ientry++) {
   chain->GetEntry(ientry);
   ....
   t[tree_sign][tree_analtag][ene_index]->Fill();
}

Axel · December 1, 2017, 11:25am

Hi,

Indeed, I misread - these are all output files. And yes of course, TChain keeps only one file open.

Could you upload the whole source file? Such that @pcanal can have a look I bet it’s because of the 300 trees…

Axel.

bozzochet · January 17, 2018, 9:57am

Sorry for the late reply… I forgot to upload the source file.

I attach here, but honestly this is not a “minimal version” of program to show the problem, and it will be almost to impossible to compile and run (without the ‘rhight’ input files). Anyhow I’ll try to point to the relevant code points…

The main essentially call the Build_superskimmed() function. It parses an input text files, chains, into a TChain, the input ROOT files and perform the SetBranchAddress.
At line 529 starts the creation of the output files. This ends at line 597.

Then it loops on the entries of the input chain and at line 721 (and 723, but usually is undef) it Fill()s the choosen TTree. As said in the previous posts: commenting the TTree::Fill(), the “memory leak” seems to disappear.

Then essentially is over.

Thanks,
Matteo

Build_superskimmed.C (36.1 KB)