Bug 981410 - Perf. regression when using rules with collect
Perf. regression when using rules with collect
Status: CLOSED CURRENTRELEASE
Product: JBoss BRMS Platform 6
Classification: JBoss
Component: BRE (Show other bugs)
6.0.0
Unspecified Unspecified
unspecified Severity high
: ER3
: 6.0.0
Assigned To: Mario Fusco
Petr Široký
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-07-04 11:51 EDT by Petr Široký
Modified: 2014-08-06 16:20 EDT (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2014-08-06 16:20:04 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Maven based reproducer (26.66 KB, application/zip)
2013-07-04 11:53 EDT, Petr Široký
no flags Details
Reproducer with only 'collect' rules enabled (31.57 KB, application/zip)
2013-07-08 10:59 EDT, Petr Široký
no flags Details

  None (edit)
Description Petr Široký 2013-07-04 11:51:41 EDT
Description of problem:
Evaluating simple rules with accumulate and collect takes longer with 6.0.0-SNAPSHOT, comparing to 5.3.1-P03. Rules have only "when" part, "then" in empty.

The rules look like this:
rule "transactionsWithCertainAccountFrom_collect_20"
when
    $account : Account(uuid == "transactionsWithCertainAccountFrom_collect_100000")
    $transactions : ArrayList(size >= 2)
                  from collect (Transaction(accountFrom == $account))
then
end

rule "totalBalanceForCertainAccounts_accumulate_20"
when
    $totalBalance : Number ()
        from accumulate (Account($balance : balance, uuid == "totalAverageMinMaxlBalanceForCertainAccounts_accumulate_100000"),
                         init(double total = 0;),
                         action(total += $balance;),
                         reverse(total -= $balance;),
                         result(total)
                        )
then
end

The difference depends on number of rules, facts, activations, etc, but is about 10% - 30%.

See attached Maven reproducer for more details.


Version-Release number of selected component (if applicable):
6.0.0-SNAPSHOT (and also beta4)


How reproducible:
Always


Steps to Reproduce:
1. Run the attached reproducer for drools5 and drools6 (mvn test)
2. Compare the results printed to stdout


Actual results:
Significant difference between the execution time for drools5 and drools6


Expected results:
Execution time is ~same for both drools5 and drools6
Comment 1 Petr Široký 2013-07-04 11:53:59 EDT
Created attachment 768859 [details]
Maven based reproducer

I will try to look more closely into this and find out what construct/operator is causing the regression.
Comment 2 Petr Široký 2013-07-08 10:59:23 EDT
Created attachment 770538 [details]
Reproducer with only 'collect' rules enabled

I have divided the test in two - one using only 'accumulate' and one only 'collect'. Running them and comparing the execution times with Drools 5, it _seems_ that the problem is caused by 'collect' only, because the 'accumulate' test is taking ~same time on both Drools 5 and Drools 6.

I have also updated the reproducer with the those two tests where one is using only accumulate and one only collect. By default only the one with collect is enabled, to its enough to run "mvn test" on both modules (drools5 and drools6) to see the difference.
Comment 3 Mario Fusco 2013-08-29 11:39:41 EDT
Running the provided test case I actually found that 5.3.x is around 20% faster than 6.0.x on my machine in that specific case (2600ms Vs. 3200ms).

Using the profiler I found that one of the causes of this difference was the excessive resizing of the HashTable implementing both the Right and Left TupleMemory. However phreak allows me to know in advance how many tuples I am going to add to a memory so I tried to ensure of having enough space in the HashTable before of starting adding them. I implemented this optimization here

https://github.com/droolsjbpm/drools/commit/090a348e0abee4243e1a74b8b52fb0eb9a13a75f

and it allowed me to half the difference with the 5.3.x bringing the execution time of the test case on the 6.0.x from 3200 to 2900 ms. 

For the rest it is hard to compare the 5.3.x and the 6.0.x, but the biggest difference I can see at the moment is in the constructor of the RightTuple that takes the 15.0% of the total execution time on the 6.0.x and only the 3.2% on the 5.3.x. In particular this difference is caused by the new DefaultFactHandle.addRightTupleInPosition method invoked in the RightTuple constructor. Despite this method looks quite trivial, evidently it becomes relevant when invoked millions of times as it happens in that test and anyway I think that what it does is nor avoidable neither further improvable.
Comment 4 Petr Široký 2013-09-19 12:58:22 EDT
I have done some preliminary testing and there definitely is an improvement around 10 %. There is still some regression but as Mario pointed out, not sure if we can do something about that.
Comment 8 Petr Široký 2013-10-29 10:42:20 EDT
Verified fixed in 6.0.0-ER4. I am not seeing the regression anymore (running the provided test case).

Note You need to log in before you can comment on or make changes to this bug.