Parameter/variable name lookup confusion

[opeongo]

As I was putting together a test script for #655 I noticed a problem with parameter/variable name lookups. The following script fails at line 23 with the error message:
Attempt to resolve method: add() on undefined variable or class name: c.ylds : at Line: 23

test1(String c) {  //change String c to String d and it works!
   return this;
}

container() {
   System.err.println("allocate container");
   ylds = new ArrayList();
   work() {
      System.err.println("working");
   }
   return this;
}

c = null;
for (int i=0; i<2; i++) {
   for (int j=0; j<10; j++) {
      if (j%5 == 0) {
         if (c != null) {
            c.work();
         }
         c = container();
      }
      c.ylds.add(test1("hello"));  // line 23
   }
}

However, if I change the formal parameter name in the test1 method from c to d the script will work successfully.

What am I missing here?

[nickl-]

The script calls line 23 every iteration but only c = container(); on the 5th. So c.ylds is undefined for 0 to 4.

The parameter name of the test1 method should have no effect.

[opeongo]

Your mental interpreter did not execute this correctly. If you try running it you will see that the container is created when j == 0 (0%5 == 0 by the way). If c was null there would have been a different error.

I agree that the name of the parameter to the test1 method should not have any effect, But in this test case it appears to do so, which indicates some kind of lookup mistake.

[opeongo]

Here is a revised minimal test script that isolates the problem a bit better. No loops, no if's to distract the focus.

test1(String c) {  // Change String c to String d and it works
   return this;
}

container() {
   System.err.println("allocate container");
   ylds = new ArrayList();
   return this;
}

Object c = null;
{
   {
      c = container();
   }
   // c = container();  // uncomment this line and it works correctly
   c.ylds.add(test1("hello"));  // Line 17, Error here.  Comment out and it will work
}
c.ylds.add(test1("hello"));  // Line 19, This works

Something happens when allocations are made within block namespaces. Note that as the comments state that this script can be modified to work correctly by either

1. renaming the parameter to the test1 method, or
2. instantiating the container object outside of the inner block, or
3. Commenting out line 17, and the script will succeed at line 19.

You don't have to change more than one condition. Any of these three changes independently will avoid the error.

Of course this is a a toy problem and you could just say "get rid of the blocks, you don't need them, that will fix your problem". True, but think of them as placeholders for more complex structures (such as loops and conditionals) that are commonly required for everyday tasks.

[nickl-]

Can reproduce:

allocate container
// Error: Evaluation Error: Attempt to resolve method: add() on undefined variable or class name: c.ylds : at Line: 18 : in file: <unknown file> : c .ylds .add ( test1 ( "hello" ) )

Called from method: global/BlockNameSpace : at Line: 18 : in file: <unknown file> : test1 ( "hello" )

[nickl-]

Parent #660

[opeongo]

There is still a problem here that is failing in my real world test. I have tried to make some test cases unfortunately I cannot seem to make one to reproduce the problem. I suspect it has something to do with caching and the isMethod flag.

[opeongo]

So I see that when a new BlockNameSpace is created for the first time the isMethod value from the parent is propogated.

Is this something that needs to also be checked when recycling a BlockNameSpace object from the cache?

[opeongo]

@nickl- Ok, I was able to isolate the problem that I am having and reduce it in to a small test case:

Object closure1() {
   list = new ArrayList();

   return this;
}

double doesntMatter() {
    return 1;
}

try {
    t = closure1();
    System.err.println(t.list.size());
} catch (Exception ex) {
    ex.printStackTrace();
}

Running the above script results in:

beanshell>java -cp target\bsh-3.0.0-SNAPSHOT.jar bsh.Interpreter longRuntest.bsh
Evaluation Error: bsh.EvalError: Sourced file: longRuntest.bsh : Attempt to resolve method: size() on undefined variable or class name: t.list : at Line: 14 : in file: longRuntest.bsh : t .list .size ( )

I don't have an explanation and I would be only guessing to try to provide one.

[nickl-]

How do you eat an elephant?

[opeongo]

How do you eat an elephant?

I don't think that this is the right analogy. An elephant is a big but well-defined and finite thing. When you have to eat an elephant you know that there is a big task ahead and you can plan out how to break the problem down into bite sized pieces in order to get it done. Generally there is steady forward progress.

But this thing with the namespace recycling isn't like that. It's more like an an iceberg: you are only seeing the tip of it and are addressing one small piece at a time in a piecemeal fashion. There is more under the surface that has not been revealed yet. As more parts of the problem become revealed and you can see that there is a different shape compared to what you first thought. What initially seemed like a good approach when you only saw the tip of the iceberg might end up being the wrong approach when you see more of the problem.

Maybe it's time to take a look at what is emerging.

First of all let's acknowledge that the bugs that we are seeing did not manifest before the ReferenceCache was added four years ago c42361a. We can agree on this, yes?

The ReferenceCache is intended to avoid the cost of object allocation and garbage collection, in other words to outsmart the gc. This kind of object recycling can sometimes improve performance in specific cases but it is easy to overestimate the benefits and underestimate the difficulty of getting it right.

Your approach to implementing namespace recycling seems to have been: "initially implement it for almost all namespace allocations, then incrementally back out special cases when breakage occurs", and this has ended up being a game of whack-a-mole. Have you thought about tackling this differently, such as: "identify the special cases where namespace recycling is proven to be not a problem, and only implement it for those cases"?

For example, with anonymous class and scripted objects all namespaces from the declaring namespace up to the topmost parent cannot be recycled. So let's flip your approach around, and say that only namespaces where there are no descendants (children, grandchildren, etc) that leak this are eligible for recycling. Then it becomes more manageable: just add a doesLeakNamespace() method on to SimpleNode that visits through all descendants and returns false if there are no return statements returning this. Nodes that have a false value are eligible to be recycled, and they can be given a clean BlockNameSpace object from a stack without worrying about trying to match to a parent etc. To make things performant this method could be called once when the tree is parsed and the result store in a field in each node.

If you did it this way you would have an elephant. The way it is now is more like the gift that keeps on giving.

[opeongo]

Also, if you have a step after the parse to go through the AST you can do interesting things like constant folding, dead code elimination and semantic analysis. It looks like semantic analysis will be required for the lambda implementation, but it is also useful for checking things like if (1 == "abcd") which is a code smell worth warning about. Since this can be done during parse there is no runtime penalty. This would also be the place to take care of the actions that are in the insureParsed() methods and deal with those concerns during declaration rather than runtime.

[opeongo]

Just to add some more clarity, the doesLeakNamespace() method would be an abstract method in SimpleNode. Each specialized class would have it's own implementation that mostly would return true if any of it's children return true, and false otherwise. Only the BSHReturnStatement class would actually check for leakage using the type of logic that you already added to BSHMethodDeclaration.

[nickl-]

You eat an elephant bite for bite. We will get through this elephant too...

Thanx for the ideas, will need pondering before I remark.

[nickl-]

Ok so after pondering the suggestions I opted to make the block name space cache optional. Using a Boolean type for the override name space flag it can define 3 states:

1. true we do not swap any name space and override the current top while processing the block
2. false we swap the top name space from callstack with a new block name space instance
3. null we swap the top name space from callstack with a reusable unique cached block name space instance

The cached name space was then only implemented for the loops, for, for enhanced, and while, as they are the ones reaping most of the benefit since the same block definitely gets processed multiple times. They also have closed scope so no need to worry about anything else needing or reusing the block name space.

If we find any other blocks that might benefit from a cache strategy we can implement it for them on a case by case basis.

For the loops doing 100000 repetitions there is a 500% performance improvement using the cache compared to going without.

[nickl-]

However even though we are now creating new block name space instances un-cached for all the blocks in the example at: #659 (comment) it still doesn't work. So this particular problem obviously lies elsewhere.

[nickl-]

The doesntMatter bug is also resolved now:

beanshell/src/test/resources/test-scripts/scripted_object2.bsh

Lines 6 to 44 in 7a5f878

	/*
	* closure called from block with additional method does not break
	* Related to #659
	*/
	Object closure1() {
	list = new ArrayList();
	this.list.add(1);
	return this;
	}
	double doesntMatter() {
	return 1;
	}
	try {
	t = closure1();
	assertEquals("list size is equal te 1", 1, t.list.size());
	} catch (Exception ex) {
	assert(false);
	}
	/*
	* sudo scripted object returning from this reported #659
	*/
	closure2() {
	list = new ArrayList();
	this.list.add(1);
	return this.list;
	}
	assertEquals("has one element from global", 1, closure2().size());
	{ assertEquals("has one element from block", 1, closure2().size()); }
	{
	t = closure2();
	assertEquals("has one element from block assigned", 1, t.size());
	}

[nickl-]

Closed: all reported issues are now resolved...until further notice

[opeongo]

The problem still exists. I have a somewhat complicated script, but here is where the failure occurs:

   for (int i=0; i<4; i++) {
      if (i>=4)                             // <----- this is line 386
         System.err.println("i="+i);   

Here is the error message that I get:

Caused by: Sourced file: unpack.bsh : illegal use of undefined variable, class, or 'void' literal : at Line: 386 : in file: unpack.bsh : ) System .err .println ( "i=" + i ) ;

Caused by: illegal use of undefined variable, class, or 'void' literal

I will try to reduce this to a test script, but it does seem a bit random in that the unchanged script will fail in different places on successive runs.

The failing script had run for several minutes doing quite a bit of I/O and repeat method calls. I am guessing that the seemingly random nature of the error might have to do with some kind of reference cache reuse issue.

[opeongo]

I spent the past few days trying to crack this nut, but with no success. I instrumented the code, followed traces, etc, but I cannot seem to figure out what is going wrong.

I tried an experiment and commented out the call to get recycled namespaces from the reference cache in BSHBLock. Previously it looked like:

        if ( null == overrideNamespace )
            enclosingNameSpace = callstack.swap(
                BlockNameSpace.getInstance(callstack.top(), blockId));
        else if ( !overrideNamespace )
            enclosingNameSpace = callstack.swap(
                new BlockNameSpace(callstack.top(), blockId));
        else enclosingNameSpace = null;

and I changed it to

        if ( null == overrideNamespace || !overrideNamespace )
            enclosingNameSpace = callstack.swap(
                new BlockNameSpace(callstack.top(), blockId));
        else enclosingNameSpace = null;

This mostly gets rid of the recycled namespaces (they are still in use in enhanced for loops). After making the change the error about disappearing variables went away.

I cannot explain what is going on, but at least there is a smoking gun.

If you have any suggestions on what to look for I can try again.

[opeongo]

I have a reproducible test case that demonstrates a symptom. I don't know if this is the root of the problem but it seems like it might be related.

I tried running the bshdoc tool bshdoc.bsh.txt and got the following error:

beanshell>java -cp target\bsh-3.0.0-SNAPSHOT.jar bsh.Interpreter scripts\bshdoc.bsh src\main\resources\bsh\commands\addClassPath.bsh
<?xml version="1.0" encoding="UTF-8"?>
<?xml-stylesheet type="text/xsl" href="bshcommands.xsl"?>
<!-- This file was auto-generated by the bshdoc.bsh script -->
<BshDoc>
 <?xml version="1.0" encoding="UTF-8"?>
 <?xml-stylesheet type="text/xsl" href="bshcommands.xsl"?>
 <!-- This file was auto-generated by the bshdoc.bsh script -->
 <BshDoc>
Evaluation Error: bsh.EvalError: Sourced file: beanshell\scripts\bshdoc.bsh : illegal use of undefined variable, class, or 'void' literal : at Line: 157 : in file: beanshell\scripts\bshdoc.bsh : ;

Called from method: bshdoc/BlockNameSpace13 : at Line: 159 : in file: beanshell\scripts\bshdoc.bsh : bshdoc ( filenames [ i ] )
Called from method: bshdoc/BlockNameSpace13/BlockNameSpace15 : at Line: 173 : in file: beanshell\scripts\bshdoc.bsh : bshdoc ( list )

The coding style in this file is out of date, but I am not sure why the error occurs.

The namespace names that are shown in the error message are possibly a bit suspect. For example, shouldn't line 173 be called from the global namespace?

[opeongo]

I reduced the above problem down to a simple reproducible example and opened a new issue #731.

[nickl-]

        if ( null == overrideNamespace || !overrideNamespace )
            enclosingNameSpace = callstack.swap(
                new BlockNameSpace(callstack.top(), blockId));
        else enclosingNameSpace = null;

This mostly gets rid of the recycled namespaces (they are still in use in enhanced for loops). After making the change the error about disappearing variables went away.

Nope this looks like it gets rid of them completely. Doesn't the loops pass null for exactly this reason?

[nickl-]

l : at Line: 386 : in file: unpack.bsh : ) System .err .println ( "i=" + i ) ;

This is strange, if it was another variable it may make sense but I am sure we update i on every run so why would it go missing? weird!!

[nickl-]

I reduced the above problem down to a simple reproducible example and opened a new issue #731.

That is very good news indeed!!! Wheeee \o/

[opeongo]

Here is an interesting traceback:

	at bsh.Interpreter.eval(Interpreter.java:759)
	at bsh.Interpreter.source(Interpreter.java:614)
	at bsh.Interpreter.source(Interpreter.java:628)
	at bsh.Interpreter.source(Interpreter.java:655)
	... 9 more
Caused by: java.lang.NullPointerException: Cannot read field "used" because "ns" is null
	at bsh.BlockNameSpace.getInstance(BlockNameSpace.java:95)
	at bsh.BSHBlock.evalBlock(BSHBlock.java:116)
	at bsh.BSHBlock.eval(BSHBlock.java:105)
	at bsh.BSHForStatement.eval(BSHForStatement.java:83)
	at bsh.BSHBlock.evalBlock(BSHBlock.java:161)
	at bsh.BSHBlock.eval(BSHBlock.java:105)
	at bsh.BshMethod.invokeImpl(BshMethod.java:470)
	at bsh.BshMethod.invoke(BshMethod.java:314)

The code at the point of error is

    public static NameSpace getInstance(NameSpace parent, int blockId ) {
        BlockNameSpace ns = (BlockNameSpace) blockspaces.get(
                new UniqueBlock(parent, blockId));
        if (1 < ns.used.getAndIncrement()) ns.clear();   // Line 95
        return ns;
    }

I can't see an obvious reason for ns to be null, because the reference cache is supposed to return a new object if either

1. there is no matching key in the cache, or
2. the value returned for the key is null.

But always blockspaces.get() should return a NameSpace, right? And the fact that it returned null in this case seems to point at a ReferenceCache problem.

The reference monitor queue is running in a separate thread and may have reaped the the reference entry just as it was being retrieved. Or maybe the key was retrieved in the program thread and the gc thread kicked in and cleared the value just before the entry was dereferenced. Or perhaps it was related to the lazy instantiation. There are a few complicated interactions here and possibly a window where it is not protected from concurrent operations.

Maybe this is at the root of the problems that I have been seeing with variables disappearing during long running scripts. Perhaps the timings lined up that a reference unexpectedly got cleared out of sequence. They seemed like non-deterministic (timing-based) errors.

Hitting this error is a rare thing. If it is happening in the ReferenceCache and it is related to concurrent operations then it will be very hard (impossible?) to write a reproducible test case.

Any suggestions on where to look or how to test?

[opeongo]

I spent a bit more time looking at the implementation of ReferenceCache and how it is used to cache BlockNameSpace objects, and I found a few problems.

The first obvious one is that the blockspaces cache is declared with weak keys and weak values. But in the call to BlockNameSpace.getInstance() the key that is passed in is quickly discarded, meaning that the entry is immediately eligible to be cleared as soon as the method returns and and the transient key goes out of scope. So at worst these entries will only be around for one usage before they are gc'ed away, and this defeats the whole purpose of this cache. The fix for this would be to use a hard reference for the key, but I don't think that's the end of it.

The next one is due to the fact that the values are held in the cache as weak references and don't get a chance to be bound to a hard reference until after BlockNameSpace.getInstance() returns. For it's natal lifespan within the ReferenceCache.get()method it is weakly held and subject to clearing by the gc. Here is the flow: The ReferenceCache.get() calls the init() method to start the initialization of the BlockNameSpace object in the cache. To make this happen asynchronously a task object is created and set as the weak reference value in the cache and is also submitted as a hard reference to the executor. The continuation of the get method will wait for the executor to finish. As soon as the executor finishes running it will release its hard reference to the task object. The only remain reference to the task object is the weak value reference, making the reference immediately eligible to be cleared by the gc. Before the cache.get() completes there is a brief window where the gc could have erased the value reference, and that is a likely explanation of what happened in the traceback shown up above.

I cannot see an easy way to alter this ReferenceCache scheme to make it fully reliable. Running the executor task in one thread and then retrieving the result in the other thread leaves a tiny window of time when there are no hard references to the newly allocated BlockNameSpace, so there will always be a risk of the value reference being cleared and the BlockNameSpace.getInstance method returning a null. And the Executor really doesn't help here with the BlockNameSpace cache, because the main thread will always be waiting at the cache.get() for the executor to complete. It is serialized multi-threading: extra overhead and negative benefit.

Besides these issues there are a few others that I mentioned previously. Value references are enqueued to the ReferenceQueueMonitor but they don't have a specialized clear() method to remove the entries from the cache, so dead entries will build up over time and waste memory. Also it looks like there is potential for a race in the get() method.

Is there a strong reason to be storing the BlockNameSpace objects in a map by namespace and sequence count? Aren't BlockNameSpace objects substitutable because they are being fully cleared before reuse? What state do they contain that cannot easily and cheaply be restored (parent, name)? If you really want to recycle these objects then I suggest a simpler structure like a stack that has lower overheads, lower complexity, and is easier to reason about.

[opeongo]

Also, the UniqueBlock class needs to override the equals method, otherwise the default test will only match to the exact same object. The equals method is required to implement logical equality to test if the namespace and id are the same, e.g.

        @Override
        public boolean equals(Object o) {
            if (o == this)
                return true;
            else if (o instanceof UniqueBlock) {
                UniqueBlock ub = (UniqueBlock) o;
                return ns == ub.ns &&
                    id == ub.id;
            } else
                return false;
        }

However, it looks like the equality test is overriden in the ReferenceCache to be:

        public boolean equals(final Object obj) {
            return hashCode == obj.hashCode();
        }

The hashcode calculation is:

            hashCode = key.hashCode() + key.toString().chars().sum();

This is unsafe because it is possible for two different objects to have the same hash code. Maybe this is allowing hash collisions and the wrong namespace objects getting retrieved.

[opeongo]

Happy day, I think that I found the problem! I am pretty sure that it is what I mentioned previously about the equality test being overridden by a weak hashcode comparison, and this was allowing collisions to happen.

I implemented a simpler weak value reference hashmap and it repeatedly runs successfully on my long running test cases. Of course with intermittent non-deterministic bugs it is hard to conclusively say that the bug has been squashed, but I am feeling pretty confident because

1. there is a rational explanation of where the error was coming from; and
2. the test have run to completion several times in a row, where previously it was never able to finish.

I will clean up my code and post a PR when I get a chance.

[opeongo]

I also had a look at the MemberCache implementation that uses the ReferenceCache and it also has a few problems.

The MemberCache uses class references as keys. In normal practice the class references will not be collected by the gc unless the ClassLoader that they come from is also gc'ed. This means that for most situations the soft references on the keys will never be cleared. It is possible under memory pressure for the soft value references to the MemberCache objects to be gc'ed and cleared, but entries in the map will never be removed because the overridden clear method in the value reference doesn't do anything. Entries in the cache map will just build up, so this is a memory leak problem.

Also, it looks like that the Executor is not fully effective at parallelizing the instantiation of the MemberCache values. The issue shows up in the MemberCache constructor:

        public MemberCache(Class<?> clazz) {
            Class<?> type = clazz;
            while (type != null) {
                if (isPackageAccessible(type)
                    && ((isPackageScope(type) && !isPrivate(type))
                        || isPublic(type) || haveAccessibility())) {
                    for (Field f : type.getDeclaredFields())
                        if (isPublic(f) || haveAccessibility())
                            cacheMember(Invocable.get(f));
                    for (Method m : type.getDeclaredMethods())
                        if (isPublic(m) || haveAccessibility())
                            if (clazz == type) cacheMember(Invocable.get(m));
                            else cacheMember(memberCache.get(type)               // line 127
                            .findMethod(m.getName(), m.getParameterTypes()));
                    for (Constructor<?> c: type.getDeclaredConstructors())
                        if (clazz == type) cacheMember(Invocable.get(c));
                        else cacheMember(memberCache.get(type)                     // line 131
                            .findMethod(c.getName(), c.getParameterTypes()));
                }
                processInterfaces(type.getInterfaces());
                type = type.getSuperclass();
                memberCache.init(type);                          // line 136
            }
        }

I instrumented the code to see how often the main thread had to pause while waiting for the executor task to finish. The init method is called at line 136 and it submits the task to the executor. The loop continues and at lines 127 and 131 the get method is called and retrieves the value of the previously created future. In all of the tests the thread pauses at lines 127 or 131 the majority of the time waiting for the executor thread to complete the future task. So this ends up being serialized multi-threading where the one thread is simply waiting for the other thread to complete the action. It is probably not worth the overhead of the context switches involved.

There is also the potential for the reference to get cleared in the gap between the executor completing the task and the get method returning the value, just like in the blockSpaces cache. This is a little bit less likely because the soft references require memory pressure, but there is a clear risk of returning a null. This is a problem that I cannot see fixing easily.

I suggest to not use the ReferenceCache class for MemberCache objects and instead use something simpler like the value reference cache that I added in PR #741.