Uploaded image for project: 'Drools'
  1. Drools
  2. DROOLS-9

Exception in User-defined Java method when rules are optimized by the JIT compiler

    XMLWordPrintable

Details

    • Bug
    • Resolution: Won't Do
    • Major
    • None
    • None
    • None
    • None
    • Hide
      • compile the attached project: open with Eclipse, or compile with maven
      • start the java class /DroolsJITTestCase/src/main/java/com/sample/DroolsTest.java as an Application
      • you will see this output:

      SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
      SLF4J: Defaulting to no-operation (NOP) logger implementation
      SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Service.getAllTimers
      Exception in thread "Thread-0" [Error: service.getTimePerStroke($service.getLongValue(service.workplaceIdForMachineId($machineId, $actionTimestamp), "RC.WORKPLACE_LEADING_OPERATION_ID")): null]
      [Near :

      {... $service.getLongValue(service. ....}

      ]
      ^
      [Line: 1, Column: 1]
      at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.compileGetChain(ReflectiveAccessorOptimizer.java:416)
      at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.optimizeAccessor(ReflectiveAccessorOptimizer.java:143)
      at org.mvel2.ast.ASTNode.optimize(ASTNode.java:159)
      at org.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:115)
      at org.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:108)
      at org.mvel2.MVELRuntime.execute(MVELRuntime.java:85)
      at org.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123)
      at org.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119)
      at org.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:113)
      at org.mvel2.MVEL.executeExpression(MVEL.java:930)
      at org.drools.rule.constraint.MvelConditionEvaluator.evaluate(MvelConditionEvaluator.java:70)
      at org.drools.rule.constraint.MvelConditionEvaluator.ensureBranchEvaluation(MvelConditionEvaluator.java:117)
      at org.drools.rule.constraint.MvelConditionEvaluator.ensureCompleteEvaluation(MvelConditionEvaluator.java:102)
      at org.drools.rule.constraint.MvelConditionEvaluator.ensureCompleteEvaluation(MvelConditionEvaluator.java:90)
      at org.drools.rule.constraint.MvelConditionEvaluator.getAnalyzedCondition(MvelConditionEvaluator.java:82)
      at org.drools.rule.constraint.MvelConstraint.executeJitting(MvelConstraint.java:270)
      at org.drools.rule.constraint.MvelConstraint.access$200(MvelConstraint.java:51)
      at org.drools.rule.constraint.MvelConstraint$ConditionJitter.run(MvelConstraint.java:250)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
      at java.lang.Thread.run(Thread.java:662)
      Caused by: java.lang.reflect.InvocationTargetException
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at java.lang.reflect.Method.invoke(Method.java:597)
      at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.getMethod(ReflectiveAccessorOptimizer.java:1104)
      at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.getMethod(ReflectiveAccessorOptimizer.java:987)
      at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.compileGetChain(ReflectiveAccessorOptimizer.java:377)
      ... 20 more
      Caused by: java.lang.RuntimeException
      at com.sample.Service.getTimePerStroke(Service.java:42)
      ... 27 more

      Show
      compile the attached project: open with Eclipse, or compile with maven start the java class /DroolsJITTestCase/src/main/java/com/sample/DroolsTest.java as an Application you will see this output: SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder". SLF4J: Defaulting to no-operation (NOP) logger implementation SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details. Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Service.getAllTimers Exception in thread "Thread-0" [Error: service.getTimePerStroke($service.getLongValue(service.workplaceIdForMachineId($machineId, $actionTimestamp), "RC.WORKPLACE_LEADING_OPERATION_ID")): null] [Near : {... $service.getLongValue(service. ....} ] ^ [Line: 1, Column: 1] at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.compileGetChain(ReflectiveAccessorOptimizer.java:416) at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.optimizeAccessor(ReflectiveAccessorOptimizer.java:143) at org.mvel2.ast.ASTNode.optimize(ASTNode.java:159) at org.mvel2.ast.ASTNode.getReducedValueAccelerated(ASTNode.java:115) at org.mvel2.ast.BinaryOperation.getReducedValueAccelerated(BinaryOperation.java:108) at org.mvel2.MVELRuntime.execute(MVELRuntime.java:85) at org.mvel2.compiler.CompiledExpression.getDirectValue(CompiledExpression.java:123) at org.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:119) at org.mvel2.compiler.CompiledExpression.getValue(CompiledExpression.java:113) at org.mvel2.MVEL.executeExpression(MVEL.java:930) at org.drools.rule.constraint.MvelConditionEvaluator.evaluate(MvelConditionEvaluator.java:70) at org.drools.rule.constraint.MvelConditionEvaluator.ensureBranchEvaluation(MvelConditionEvaluator.java:117) at org.drools.rule.constraint.MvelConditionEvaluator.ensureCompleteEvaluation(MvelConditionEvaluator.java:102) at org.drools.rule.constraint.MvelConditionEvaluator.ensureCompleteEvaluation(MvelConditionEvaluator.java:90) at org.drools.rule.constraint.MvelConditionEvaluator.getAnalyzedCondition(MvelConditionEvaluator.java:82) at org.drools.rule.constraint.MvelConstraint.executeJitting(MvelConstraint.java:270) at org.drools.rule.constraint.MvelConstraint.access$200(MvelConstraint.java:51) at org.drools.rule.constraint.MvelConstraint$ConditionJitter.run(MvelConstraint.java:250) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) Caused by: java.lang.reflect.InvocationTargetException at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.getMethod(ReflectiveAccessorOptimizer.java:1104) at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.getMethod(ReflectiveAccessorOptimizer.java:987) at org.mvel2.optimizers.impl.refl.ReflectiveAccessorOptimizer.compileGetChain(ReflectiveAccessorOptimizer.java:377) ... 20 more Caused by: java.lang.RuntimeException at com.sample.Service.getTimePerStroke(Service.java:42) ... 27 more
    • High

    Description

      I watched this issue after upgrading from Drools 5.3.1 to Drools 5.5.0.Final.

      I didn't find any trivial example, so I reproduced the error with a non-trivial test case derived from a real-live rule, and attached the test case to this issue. The output is listed in the field "Steps to reproduce":

      What does the application:

      • it calls the rule "DroolsJITTest-Rule" 20 times - 20 is the threshold for jitting. In the output, you can see the line "Service.getAllTimers" 20 times.
      • after that output, a exception during jitting is thrown, because com.sample.Service.getTimePerStroke(Service.java:42) throwed an exception
      • this service is called in the LHS of the rule

      But:

      1. in the rule, the following expression evaluates always to false, because service.getLongValue returns always 0
        $service.getLongValue(service.workplaceIdForMachineId($machineId, $actionTimestamp), "RC.WORKPLACE_LEADING_OPERATION_ID") > 0
        
      2. from this and rule semantics it follows that the next expression should never be evaluated, but the JIT compiler evaluates it:
        service.getTimePerStroke($service.getLongValue(service.workplaceIdForMachineId($machineId, $actionTimestamp), "RC.WORKPLACE_LEADING_OPERATION_ID")) > 15
        
      3. as we have seen in the bullet no. 1, the parameter of service.getTimePerStroke is 0. In com.sample.Service, Line 41 the parameter value is asserted to be not 0, so an RuntimeException is thrown (Line 42).

      Code of the rule:

      rule "DroolsJITTest-Rule"
      when
      	$service : Service() 
      	p: PulseEvent(
      		$actionTimestamp : actionTimestamp,
      		$eventTimestamp : eventTimestamp
      	)
          t: TimerToken(
      		$machineId : id,
      		$timestampUTC : timestampUTC,
      		$service.getLongValue(service.workplaceIdForMachineId($machineId, $actionTimestamp), "RC.WORKPLACE_LEADING_OPERATION_ID") > 0,
      		service.getTimePerStroke($service.getLongValue(service.workplaceIdForMachineId($machineId, $actionTimestamp), "RC.WORKPLACE_LEADING_OPERATION_ID")) > 15
      	) from $service.getAllTimers("RC.MACHINE_STROKE_TIMER")
      then
          System.out.println( "Rule executed" );
          update(p);
      end
      

      I think, it's a failure that the JIT compiler evaluates the line

      service.getTimePerStroke($service.getLongValue(service.workplaceIdForMachineId($machineId, $actionTimestamp), "RC.WORKPLACE_LEADING_OPERATION_ID")) > 15
      

      because the previous condition expression evaluates to false. Or do you think this behavior works as designed?

      Attachments

        Issue Links

          Activity

            People

              mfusco@redhat.com Mario Fusco
              abentele_jira Andreas Bentele (Inactive)
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: