PyROOT: Walking through a ROOT-file gets slower the longer you "walk"

danielberninghoff · September 23, 2019, 11:45am

Hi everybody,

I am experiencing the problem that when “walking” through objects in a ROOT-file, retrieving the objects takes more and more time the longer you walk.

Consider the following code where I walk through a ROOT-file with many TEfficiency objects inside. For convenience, I use the rootpy.io.file.walk function for walking through the ROOT-file. However, as I elaborate below, it is not the cause of the problem. You can find the script and the corresponding test ROOT-file scurves.root here:

#!/usr/bin/env python
from rootpy.io import root_open
import rootpy.ROOT as ROOT
import time

_print_interval = 1000
_last_time = time.time()
_obj_cnt = 0
def print_time_past():
    global _print_interval, _last_time, _obj_cnt
    _obj_cnt += 1
    if _obj_cnt%_print_interval == 0:
        ms_past = (time.time()-_last_time)*1000.
        print(f"Took {ms_past:.0f}ms for the last {_print_interval} objects.")
        _last_time = time.time()

def walk():
    fname = "scurves.root"

    with root_open(fname, "READ") as root_file:
        for path, dirs, objects in root_file.walk(""):
            for obj_name in objects:
                obj = root_file[path+"/"+obj_name] #This line is critical!
                #Do something with object
                print_time_past()

walk()

You will notice that, when running it, it will take more and more time to walk through batches of 1000 objects, producing an output like this:

Took 3816ms for the last 1000 objects.
Took 2334ms for the last 1000 objects.
Took 2174ms for the last 1000 objects.
Took 2253ms for the last 1000 objects.
Took 2355ms for the last 1000 objects.
Took 2582ms for the last 1000 objects.
Took 2583ms for the last 1000 objects.
Took 2652ms for the last 1000 objects.
Took 2750ms for the last 1000 objects.
Took 2909ms for the last 1000 objects.
Took 2778ms for the last 1000 objects.
Took 2902ms for the last 1000 objects.
Took 3109ms for the last 1000 objects.
Took 3269ms for the last 1000 objects.
Took 3412ms for the last 1000 objects.
Took 3410ms for the last 1000 objects.
Took 3880ms for the last 1000 objects.
Took 4391ms for the last 1000 objects.
Took 4919ms for the last 1000 objects.
Took 4758ms for the last 1000 objects.
Took 4143ms for the last 1000 objects.
Took 4400ms for the last 1000 objects.
Took 4303ms for the last 1000 objects.
Took 4446ms for the last 1000 objects.
Took 4438ms for the last 1000 objects.
Took 5050ms for the last 1000 objects.
Took 4827ms for the last 1000 objects.
Took 5275ms for the last 1000 objects.
Took 6279ms for the last 1000 objects.
Took 5203ms for the last 1000 objects.
Took 5862ms for the last 1000 objects.
Took 5982ms for the last 1000 objects.
Took 6300ms for the last 1000 objects.
Took 5883ms for the last 1000 objects.
Took 6926ms for the last 1000 objects.
Took 8219ms for the last 1000 objects.
Took 7514ms for the last 1000 objects.
Took 6585ms for the last 1000 objects.
Took 6371ms for the last 1000 objects.
Took 6994ms for the last 1000 objects.
Took 8177ms for the last 1000 objects.
Took 8137ms for the last 1000 objects.
Took 7065ms for the last 1000 objects.
Took 7374ms for the last 1000 objects.
Took 7479ms for the last 1000 objects.
Took 7564ms for the last 1000 objects.
Took 8076ms for the last 1000 objects.
Took 9441ms for the last 1000 objects.
Took 8773ms for the last 1000 objects.
Took 10552ms for the last 1000 objects.
Took 9495ms for the last 1000 objects.
Took 10253ms for the last 1000 objects.
Took 13477ms for the last 1000 objects.
Took 16660ms for the last 1000 objects.
Took 18195ms for the last 1000 objects.

I believe it is somehow related to memory usage when actually retrieving the object from the ROOT-file, since when commenting out the line

obj = root_file[path+"/"+obj_name] #This line is critical!

looping through batches of 1000 objects takes equally long no matter how far you “walk” (which also means that the rootpy.io.file.walk function itself is innocent)

Tested with:
Python 3.6.5
rootpy 1.0.1
ROOT 6.14/04

Looking very much forward for ideas and suggestions, thanks already!

pcanal · September 24, 2019, 2:03pm

maybe @etejedor has an idea?

etejedor · September 26, 2019, 8:04am

Dear @danielberninghoff,

Since you are using rootpy, I can’t really tell if this is an issue related to rootpy's root_file or it is related to the PyROOT underneath. Do you observe a similar behaviour with a pure PyROOT loop?

danielberninghoff · September 26, 2019, 12:55pm

Hi @etejedor,

thanks for your reply. I just built a pure PyROOT version of my example:

#!/usr/bin/env python
import ROOT
import time
import os.path



_print_interval = 1000
_last_time = time.time()
_obj_cnt = 0
def print_time_past():
    global _print_interval, _last_time, _obj_cnt
    _obj_cnt += 1
    if _obj_cnt%_print_interval == 0:
        ms_past = (time.time()-_last_time)*1000.
        print(f"Took {ms_past:.0f}ms for the last {_print_interval} objects.")
        _last_time = time.time()

def walk_scurves(root_file, in_dir="", basepath=""):
    tdir = root_file.GetDirectory(in_dir)
    basepath = os.path.join(basepath, in_dir)

    for key in tdir.GetListOfKeys():
        name = key.GetName()
        classname = key.GetClassName()
        if classname == "TEfficiency":
            yield os.path.join(basepath, name)
        elif classname.startswith("TDirectory"):
            for scurve in walk_scurves(tdir, name, basepath):
                yield scurve

def main():
    fname = "scurves.root"

    root_file = ROOT.TFile(fname,"READ")
    for scurve in walk_scurves(root_file):
        obj = root_file.Get(scurve)
        #Do something with object
        print_time_past()

    root_file.Close()


main()

It seems to be generally more efficient than the rootpy version, but it also suffers from getting significantly slower over time - see following output using the same input file:

Took 664ms for the last 1000 objects.
Took 251ms for the last 1000 objects.
Took 300ms for the last 1000 objects.
Took 452ms for the last 1000 objects.
Took 496ms for the last 1000 objects.
Took 555ms for the last 1000 objects.
Took 580ms for the last 1000 objects.
Took 654ms for the last 1000 objects.
Took 751ms for the last 1000 objects.
Took 849ms for the last 1000 objects.
Took 888ms for the last 1000 objects.
Took 930ms for the last 1000 objects.
Took 1024ms for the last 1000 objects.
Took 1048ms for the last 1000 objects.
Took 1115ms for the last 1000 objects.
Took 1170ms for the last 1000 objects.
Took 1260ms for the last 1000 objects.
Took 1414ms for the last 1000 objects.
Took 1614ms for the last 1000 objects.
Took 1712ms for the last 1000 objects.
Took 1587ms for the last 1000 objects.
Took 1624ms for the last 1000 objects.
Took 1683ms for the last 1000 objects.
Took 1718ms for the last 1000 objects.
Took 2145ms for the last 1000 objects.
Took 2215ms for the last 1000 objects.
Took 2303ms for the last 1000 objects.
Took 2180ms for the last 1000 objects.
Took 2234ms for the last 1000 objects.
Took 2279ms for the last 1000 objects.
Took 2252ms for the last 1000 objects.
Took 2376ms for the last 1000 objects.
Took 2503ms for the last 1000 objects.
Took 2814ms for the last 1000 objects.
Took 2998ms for the last 1000 objects.
Took 2714ms for the last 1000 objects.
Took 2647ms for the last 1000 objects.
Took 2907ms for the last 1000 objects.
Took 3003ms for the last 1000 objects.
Took 3292ms for the last 1000 objects.
Took 3260ms for the last 1000 objects.
Took 3531ms for the last 1000 objects.
Took 4034ms for the last 1000 objects.
Took 3541ms for the last 1000 objects.
Took 3296ms for the last 1000 objects.
Took 4338ms for the last 1000 objects.
Took 4289ms for the last 1000 objects.
Took 3807ms for the last 1000 objects.
Took 6720ms for the last 1000 objects.
Took 4429ms for the last 1000 objects.
Took 4185ms for the last 1000 objects.
Took 5595ms for the last 1000 objects.
Took 4928ms for the last 1000 objects.
Took 5280ms for the last 1000 objects.
Took 5474ms for the last 1000 objects.

Again, you can find the example data and python scripts at https://cernbox.cern.ch/index.php/s/U6VD4gUETVUI3bi

Looking very much forward for your suggestions.

Cheers,
Daniel

etejedor · September 26, 2019, 2:34pm

Thanks Daniel, I will have a look and get back to you.

danielberninghoff · October 9, 2019, 11:57am

Hi @etejedor,

inspired from your answer in PyROOT loop over files, huge memory leak I think I found the solution to my problem: using ROOT.SetOwnership(obj, True).

It was one the first things that I tried originally, but only on the TEfficiency objets itself. As it turns out, doing that for the TDirectory objects as well that I am “walking” through is the crucial bit.

Now the code looks like this:

#!/usr/bin/env python
import ROOT
import time
import os.path



_print_interval = 1000
_last_time = time.time()
_obj_cnt = 0
def print_time_past():
    global _print_interval, _last_time, _obj_cnt
    _obj_cnt += 1
    if _obj_cnt%_print_interval == 0:
        ms_past = (time.time()-_last_time)*1000.
        print(f"Took {ms_past:.0f}ms for the last {_print_interval} objects.")
        _last_time = time.time()

def walk_scurves(root_file, in_dir="", basepath=""):
    tdir = root_file.GetDirectory(in_dir)
    ROOT.SetOwnership(tdir, True) #IMPORTANT!
    basepath = os.path.join(basepath, in_dir)

    for key in tdir.GetListOfKeys():
        name = key.GetName()
        classname = key.GetClassName()
        if classname == "TEfficiency":
            yield os.path.join(basepath, name)
        elif classname.startswith("TDirectory"):
            for scurve in walk_scurves(tdir, name, basepath):
                yield scurve

def main():
    fname = "scurves.root"

    root_file = ROOT.TFile(fname,"READ")
    for scurve in walk_scurves(root_file):
        obj = root_file.Get(scurve)
        ROOT.SetOwnership(obj, True) #IMPORTANT!
        #Do something with object
        print_time_past()

    root_file.Close()


main()

and the output:

Took 719ms for the last 1000 objects.
Took 91ms for the last 1000 objects.
Took 89ms for the last 1000 objects.
Took 90ms for the last 1000 objects.
Took 89ms for the last 1000 objects.
Took 88ms for the last 1000 objects.
Took 89ms for the last 1000 objects.
Took 88ms for the last 1000 objects.
Took 89ms for the last 1000 objects.
Took 89ms for the last 1000 objects.
Took 83ms for the last 1000 objects.
Took 72ms for the last 1000 objects.
Took 76ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 72ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 76ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 76ms for the last 1000 objects.
Took 78ms for the last 1000 objects.
Took 78ms for the last 1000 objects.
Took 76ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 76ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 78ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 72ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 71ms for the last 1000 objects.
Took 73ms for the last 1000 objects.
Took 72ms for the last 1000 objects.
Took 79ms for the last 1000 objects.
Took 74ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 80ms for the last 1000 objects.
Took 78ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 75ms for the last 1000 objects.
Took 76ms for the last 1000 objects.

Thanks a lot for your support!

Cheers,
Daniel

PS: Please let me know if you think that this is not the proper solution to the issue

etejedor · October 9, 2019, 3:11pm

Hi @danielberninghoff ,

Good to hear it is working!

I believe you do not need the ROOT.SetOwnership(obj, True), just the ROOT.SetOwnership(tdir, True). The reason is that Python does not own by default the directories you get with GetDirectory, it is C++ who owns them. Most probably they are attached to the C++ TFile, and since the TFile is not destroyed until the end of the application, the application accumulates them and this causes the slowdown. If you explicitly request Python to destroy them, this accumulation does not happen.

danielberninghoff · October 9, 2019, 3:35pm

Thanks @etejedor for your reply!

Why do you believe that it is not necessary for the TEfficiency objects themselves? Are they by default owned by Python or are they bound to their respective TDirectory and get destroyed with them?

etejedor · October 9, 2019, 3:49pm

No, the TEfficiency are not owned by Python either, it just seems that waiting until the end of the application to delete them does not have an influence in the execution time, while it does matter for the TDirectory ones. But of course, it does not hurt to get rid of the TEfficiency objects as well, so your solution is good!

system · October 23, 2019, 3:50pm

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.