lldb.frame.EvaluateExpression slows down when called a lot

I was recently using lldb to connect to a debug build of ruby to inspect the heap. In order to do this I was doing something like this

Running expressions has all sorts of side effects like storing data in the inferior program and it also involves running the clang expression parser which can be expensive.

You can, from a frame, get a SBValue for a variable without using the expression parser:

    lldb::SBValue
    SBFrame.GetValueForVariablePath (const char *var_path);

So you can change your code to this:

heaps_used = lldb.frame.GetValueForVariablePath('ruby_current_vm->objspace->heap_pages.used').GetValueAsUnsigned(0)
   
for i in xrange(heaps_used):
    page = lldb.frame.GetValueForVariablePath('*ruby_current_vm->objspace->heap_pages.sorted[%i]' % i)

The GetValueForVariablePath() will find the variable and not create a temporary each time. It also doesn't use the expression parser at all so it won't call any code. The objects you access must be available in the hierarchy of the struct or class and the struct or class can't override the "->" operator. Other than that, the GetValueForVariablePath() knows how to access members ("ruby_current_vm->objspace->heap_pages.sorted"), dereference pointers using the array syntax ("my_ptr[12]"), deref a pointer ("*this->other_ptr"), and take the address of something ("&ruby_current_vm->objspace->heap_pages.sorted[12]").

So give the GetValueForVariablePath a try. The SBValue returned is something that represents the live variable value, not a const result like you get back from expression. SBValue you get back is tied to the frame from which you got it, so it will continue to evaluate correctly and its value will change if you step between calling functions with it. If the frame it came from goes away (step out), then it won't return any valid values again as it will detect the frame is gone and stop answering any questions. So you should always fetch a fresh value from the frame each time you want to use it.

Greg

Thanks for the information Greg. I have a quick followup. I’m using the version of lldb that comes with XCode 5.1.1

Launching it like this

Scotts-MacBook-Pro:~ scottknight$ /Applications/Xcode.app/Contents/Developer/usr/bin/lldb -p 13892
Attaching to process with:
process attach -p 13892
Process 13892 stopped
Executable module set to “/Users/scottknight/.rbenv/versions/2.1.1/bin/ruby”.
Architecture set to: x86_64-apple-macosx.

When I tried using GetValueForVariablePath I got ‘No value’ back. See the output below.

(lldb) v
lldb-310.2.37
(lldb) script
Python Interactive Interpreter. To exit, type ‘quit()’, ‘exit()’ or Ctrl-D.

print lldb.frame.EvaluateExpression(‘ruby_current_vm’)
(rb_vm_t *) $1 = 0x00007f9a01003000

print lldb.frame.GetValueForVariablePath(‘ruby_current_vm’)
No value

Since ruby_current_vm is a global variable is there something different I would need to do to access it?

Thanks,
Scott Knight

SBValue
SBTarget::FindFirstGlobalVariable (const char* name);

This doesn't support the "GetValueForVariablePath()", so you will need to do:

ruby_current_vm = lldb.target.FindFirstGlobalVariable('ruby_current_vm');

heaps_used = ruby_current_vm.GetValueForExpressionPath('->objspace->heap_pages.used').GetValueAsUnsigned(0)

You can also use a very handy wrapper utility class called lldb.value:

ruby_current_vm = lldb.value(lldb.target.FindFirstGlobalVariable('ruby_current_vm'))

Now "ruby_current_vm" behaves like a C structure would, except you can't use "->" to refer to a child of a pointer you need to use ".". So you should be able to do:

heaps_used = ruby_current_vm.objspace.heap_pages.used

for i in xrange(heaps_used):
    page = ruby_current_vm.objspace.heap_pages.sorted[i]

You had a derefernce on "page" before, but, you can use page is a lldb.value, so you can just do "page.foo.bar" if you need anything inside of it.

Greg

Great! This is exactly what I was looking for and works perfectly.

Thanks,
Scott Knight

One last thing I can’t seem to figure out. I have this

self.ruby_current_vm = lldb.value(lldb.target.FindFirstGlobalVariable(‘ruby_current_vm’))

self.heaps_used = self.ruby_current_vm.objspace.heap_pages.used

for i in xrange(self.heaps_used):
page = self.ruby_current_vm.objspace.heap_pages.sorted[i]

for j in xrange(page.limit):
rvalue = page.start[0]

But I can’t seem to access rvalue fields correctly. I would have expected based on the output below that I could do rvalue.as.basic.flags but I get this error

rvalue.as.basic.flags
File “”, line 1
rvalue.as.basic.flags
^
SyntaxError: invalid syntax

Below is the output from printing the whole rvalue variable. It has an anonymous union as. I can do

real_rvalue = lldb.value(rvalue.dict[‘sbvalue’].GetChildAtIndex[0]) and then I seem to be able to do

real_rvalue.basic.flags but add that extra line inside the loop above kills the speed and things start getting slower and slower again.

Thanks,
Scott Knight

(RVALUE) [0] = {
as = {
free = {
flags = 98
next = 0x00007f9a0107bfa0
}
basic = (flags = 98, klass = 140299418976160)
object = {
basic = (flags = 98, klass = 140299418976160)
as = {
heap = {
numiv = 140299418632320
ivptr = 0x00007f9a00c274d0
iv_index_tbl = 0x00007f9a00c27530
}
ary = ([0] = 140299418632320, [1] = 140299414435024, [2] = 140299414435120)
}
}
klass = {
basic = (flags = 98, klass = 140299418976160)
super = 140299418632320
ptr = 0x00007f9a00c274d0
m_tbl_wrapper = 0x00007f9a00c27530
}
flonum = {
basic = (flags = 98, klass = 140299418976160)
float_value = 6.93171228777286E-310
}
string = {
basic = (flags = 98, klass = 140299418976160)
as = {
heap = {
len = 140299418632320
ptr = 0x00007f9a00c274d0 “”
aux = (capa = 140299414435120, shared = 140299414435120)
}
ary = “\x80\x80\x02\x01\x9a\x7f”
}
}
array = {
basic = (flags = 98, klass = 140299418976160)
as = {
heap = {
len = 140299418632320
aux = (capa = 140299414435024, shared = 140299414435024)
ptr = 0x00007f9a00c27530
}
ary = ([0] = 140299418632320, [1] = 140299414435024, [2] = 140299414435120)
}
}
regexp = {
basic = (flags = 98, klass = 140299418976160)
ptr = 0x00007f9a01028080
src = 140299414435024
usecnt = 140299414435120
}
hash = {
basic = (flags = 98, klass = 140299418976160)
ntbl = 0x00007f9a01028080
iter_lev = 12743888
ifnone = 140299414435120
}
data = {
basic = (flags = 98, klass = 140299418976160)
dmark = 0x00007f9a01028080
dfree = 0x00007f9a00c274d0
data = 0x00007f9a00c27530
}
typeddata = {
basic = (flags = 98, klass = 140299418976160)
type = 0x00007f9a01028080
typed_flag = 140299414435024
data = 0x00007f9a00c27530
}
rstruct = {
basic = (flags = 98, klass = 140299418976160)
as = {
heap = {
len = 140299418632320
ptr = 0x00007f9a00c274d0
}
ary = ([0] = 140299418632320, [1] = 140299414435024, [2] = 140299414435120)
}
}
bignum = {
basic = (flags = 98, klass = 140299418976160)
as = {
heap = {
len = 140299418632320
digits = 0x00007f9a00c274d0
}
ary = ([0] = 16941184, [1] = 32666, [2] = 12743888, [3] = 32666, [4] = 12743984, [5] = 32666)
}
}
file = {
basic = (flags = 98, klass = 140299418976160)
fptr = 0x00007f9a01028080
}
node = {
flags = 98
nd_reserved = 140299418976160
u1 = {
node = 0x00007f9a01028080
id = 140299418632320
value = 140299418632320
cfunc = 0x00007f9a01028080
tbl = 0x00007f9a01028080
}
u2 = {
node = 0x00007f9a00c274d0
id = 140299414435024
argc = 140299414435024
value = 140299414435024
}
u3 = {
node = 0x00007f9a00c27530
id = 140299414435120
state = 140299414435120
entry = 0x00007f9a00c27530
args = 0x00007f9a00c27530
cnt = 140299414435120
value = 140299414435120
}
}
match = {
basic = (flags = 98, klass = 140299418976160)
str = 140299418632320
rmatch = 0x00007f9a00c274d0
regexp = 140299414435120
}
rational = {
basic = (flags = 98, klass = 140299418976160)
num = 140299418632320
den = 140299414435024
}
complex = {
basic = (flags = 98, klass = 140299418976160)
real = 140299418632320
imag = 140299414435024
}
values = {
basic = (flags = 98, klass = 140299418976160)
v1 = 140299418632320
v2 = 140299414435024
v3 = 140299414435120
}
}
}

It is either a bug in the lldb.value code (which is in LLDB.framework/Resources/Python/lldb/__init__.py) or it could be a bug in LLDB where we aren't able to access a variable through an anonymous union.

You might be able to get away with:

rvalue[0].as.basic.flags

Let me know if that works? If it doesn't, you can probably modify the "class value" in the "lldb/__init__.py" to "do the right thing. Also when digging up child values by name in the []

You might also be able to do:

  rvalue = page.start[0][0]

then the rvalue should work for you?

If neither do, we can probably fix the name lookup which is currently this:

    def __getattr__(self, name):
        child_sbvalue = self.sbvalue.GetChildMemberWithName (name)
        if child_sbvalue and child_sbvalue.IsValid():
            return value(child_sbvalue)
        raise AttributeError("Attribute '%s' is not defined" % name)

If could be modified to do:

    def __getattr__(self, name):
        child_sbvalue = self.sbvalue.GetChildMemberWithName (name)
        if child_sbvalue and child_sbvalue.IsValid():
            return value(child_sbvalue)
        n = self.sbvalue.GetNumChildren()
        for i in range(n):
            child_sbvalue = self.sbvalue.GetChildAtIndex(i)
            child_name = child_sbvalue.GetName()
            if child_name == None or child_name == '':
                child_value = value(child_sbvalue)
          child_child_sbvalue = child_value.__getattr__(name)
                if child_sbvalue and child_sbvalue.IsValid():
                    return child_value
        raise AttributeError("Attribute '%s' is not defined" % name)

This extra code will check any children that don't have names and recurse down into them to find the correct name...

Greg

For what its worth, I compiled the following example

struct stuff {
    union {
        struct {
            int a;
            int b;
        } ints;
        struct {
            char a;
            char b;
        } chars;
    };
};
int main (int argc, char const *argv[], char const *envp[])
{
    stuff s;
    s.ints.a = 11;
    s.ints.b = 22;
    return 0;
}

And it all worked fine:

s = lldb.value(lldb.frame.FindVariable('s'))
print s.ints.b

(int) b = 22

print s.ints.a

(int) a = 11

print s.chars.a

(char) a = '\v'

print s.chars.b

(char) b = '\0'

print hex(s.chars.a)

0xb

What is the type of rvalue? If you can come up with a simple example on what isn't working and send it my way I can fix anything that is broken.

Greg

The type of RVALUE is defined as follows

typedef struct RVALUE {
union {
struct {
VALUE flags; /* always 0 for freed obj */
struct RVALUE *next;
} free;
struct RBasic basic;
struct RObject object;
struct RClass klass;
struct RFloat flonum;
struct RString string;
struct RArray array;
struct RRegexp regexp;
struct RHash hash;
struct RData data;
struct RTypedData typeddata;
struct RStruct rstruct;
struct RBignum bignum;
struct RFile file;
struct RNode node;
struct RMatch match;
struct RRational rational;
struct RComplex complex;
struct {
struct RBasic basic;
VALUE v1;
VALUE v2;
VALUE v3;
} values;
} as;
#if GC_DEBUG
const char *file;
VALUE line;
#endif
} RVALUE;

So I guess it’s not actually anonymous. It has the name “as” I wonder if the fact that “as” is a python keyword is what’s causing the problem.

https://docs.python.org/2.7/reference/lexical_analysis.html#keywords

page.start[0][0] seemed to give me an IndexError

page.start[0][0]
Traceback (most recent call last):
File “”, line 1, in
File “/Applications/Xcode.app/Contents/SharedFrameworks/LLDB.framework/Versions/A/Resources/Python/lldb/init.py”, line 10848, in getitem
raise IndexError(“Index ‘%d’ is out of range” % key)
IndexError: Index ‘0’ is out of range

I did inspect the SBValue of page.start[0] a little further. GetNumChildren() == 1 and when I get that child and call GetName() it equals “as”

I think it really is a python reserved word thing. page.start[0].as gives me this

print page.start[0].as
File “”, line 1
print page.start[0].as
^
SyntaxError: invalid syntax

but this works perfectly fine

print page.start[0].getattr(‘as’).basic.flags
(VALUE) flags = 98

I’m not quite sure though why page.start[0][0] doesn’t work. If GetNumChildren() == 1 and there clearly is a “as” child I would have thought it would work. Looking closer though at getitem it’s doing

child_sbvalue = (self.sbvalue.GetValueForExpressionPath("[%i]" % key))

Which isn’t the same thing as self.sbvalue.GetChildAtIndex[0]

I can stick to doing

rvalue_as = lldb.value(rvalue.dict[‘sbvalue’].GetChildAtIndex[0])

And then I can do rvalue_as.basic.flags fine, but like I said for some reason having that line inside a loop that runs 600,000 times seems to cause it to slow down slower and slower and slower. If I remove that GetChildAtIndex line the loop completes in a minute or so. I don’t expect things to be instant trying to loop through so many internal objects but having the line above seems to cause it just to take so long that I’m not patient enough to see it finish.

Thanks again for all the help troubleshooting this.

-Scott Knight

Yep, it is the python keyword... You currently need to use your workaround:

rvalue.__getattr__("as")

Glad we found it and that there is nothing wrong with the API (we are finding children of anonymous unions, phew!).

Greg

Any of idea why making that call over and over again would seem to slow down over time?

-Scott

No idea. If you are running this on MacOSX, I would run a time profile in instruments on it and see what is going on.

I attached the instruments trace here in case it might be helpful. Seems like a lot of time is spent in the ClusterManager. It seems like thats called from all the ValueObject. I do realize that I’m getting values over and over again in a loop, but it seems to just take longer each time through the loop. I also attached the python script I’m using in the zip file as well.

-Scott

lldb-cpu-time.zip (4.03 MB)

Since you are dealing with a global, you are not tied to a stack frame, so you should be able to cache this value and re-use it:

    if not self.ruby_current_vm:
  self.ruby_current_vm = lldb.value(lldb.target.FindFirstGlobalVariable('ruby_current_vm'))

Then you should be able to use this over and over without re-fetching it. And you should be really fast. Each time you fetch a variable from SBTarget::FindFirstGlobalVariable(), it re-wraps the variable in a new VariableObjectSP which has its own cluster manager. Why? Because you might do something like:

f = lldb.value(lldb.target.FindFirstGlobalVariable('g_ptr'))

f = f.a.b.c.d

Now we need a reference to the ValueObjectSP for "g_ptr" (the underlying variable that roots the entire expression) to stay alive as long as anyone has a reference to anything that is a child of "g_ptr". Here "f" now reference "g_ptr->a.b.c.d", so any value in this chain is correctly reference counted using a ClusterMananger that keeps all of them alive as long as someone has a reference to any of them.

So if you reuse your "self.ruby_current_vm", you should only have a single ClusterManager and they should stay shared as long as you use them. Currently you are re-creating the root with each call and then referencing a bunch of children which adds new shared references to each cluster manager.

Let me know how reusing the one instance goes.

Greg

So when I call my “ruby objects” command it will create an instance of my RubyObjects class and call invoke on it once. In the invoke is where I have this call

self.ruby_current_vm = lldb.value(lldb.target.FindFirstGlobalVariable(‘ruby_current_vm’))

Then in print_stats it calls into all_objects which does this

def all_objects (self):
self.heaps_used = self.ruby_current_vm.objspace.heap_pages.used

for i in xrange(self.heaps_used):
page = self.ruby_current_vm.objspace.heap_pages.sorted[i]
print “page %i” % i

for j in xrange(page.limit):
rvalue = page.start[j].getattr(‘as’)
flags = rvalue.basic.flags
yield rvalue, flags

So self.ruby_current_vm should already be reused. If I stop the loop through page.limit everything is fast, but with the code within that second for loop things just slow down more and more.

-Scott

How many objects are we talking about here?

By the time it gets through about 2000 objects the slowdown is noticeable.

I’ll try to come up with a simplified test case and script to verify things tomorrow.

-Scott.

I tried to put together a small sample that was similar to what ruby is actually doing. In the attached sample I set up a similar structure vm with list of pages and each page had a list of objects. The only thing on the object is a int flag that I just increment so when I print it out in python and can gauge progress. In the python script then I try to time each call in the loop and print that out as well. The time it takes each time through the loop seems to get higher and higher even though FindFirstGlobalVariable is only called once.

Thanks,
Scott Knight

TestLoopSpeed.zip (933 Bytes)

The cluster manager's job is to make sure that you can hand out an SBValue for one sub-element of a "root value" and have it keep alive all the parent objects. For instance you could do:

sub_element = my_frame.GetValueForVariablePath("foo.bar.baz->lala->dada")

and for sub_element to be valid it needs to keep alive all the parent elements "foo", "foo.bar", etc. Since nothing else is referencing them, we use this "ClusterManager" to keep them alive. There's one ClusterManager for each root value object, and all the sub-elements get registered with it.

It currently keeps the sub-elements in a std::vector, and when you make a new shared pointer for a member (either because you are adding an element or getting a shared pointer to an extant element) it has to look it up in its list. It looks like you are making root objects with many sub-objects? If so, then we're running into what is probably a linear search in std::vector::find. We can try switching this over to a map. That will make adding elements slower, and make the cluster manager a little bigger, but it will make looking them up and managing them faster.

Jim

I’ve been playing around with the patch attached today. It seemed to make sense to try a set instead of map since there wasn’t really key/value pairs to store in the map. I though about using llvm::SmallSet but there’s no iterator, which seems to be needed in the destructor. As is, my C++ is really rusty and I’m not entirely sure that I’m freeing things correctly in the destructor.

The good news is this does fix the speed issues I was seeing. I was curious to hear some thoughts about the best way to make this change and then I could clean up the patch and submit it to lldb-commit

Thanks,
Scott Knight

ClusterManager-vector-to-set.diff (1.89 KB)