[rules-users] Drools Fusion inconsistencies at increasing event throughputs

Wed Apr 2 08:33:04 EDT 2014

Hi all,
We tested the commit using the latest snapshot (6.1.0-SNAPSHOT, I went
quickly through the code and it seems the right version).
Everything works as expected a part from a strange issue, that seems
related to event throughput.
Namely, when usic the basic pattern for counting (i.e. no CronTrigger),
from time to time the "cron triggered" rules won't trigger.
Few evidences added in the log below (@300eps):

# StreamTester - 300eps +/- 10%
[DEBUG] 2014-04-02 13:31:58.288 (ReteooRuleBase.java:<init>:200) Starting
Engine in PHREAK mode
[DEBUG] 2014-04-02 13:32:00.006
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 489
[DEBUG] 2014-04-02 13:32:00.095
(Rule_Count_live_counters1625367465.java:defaultConsequence:14) Live
counters = 492
[DEBUG] 2014-04-02 13:32:01.688 (StreamTester.java:run:69) Total events:
1000
[DEBUG] 2014-04-02 13:32:04.838 (StreamTester.java:run:69) Total events:
2000
[DEBUG] 2014-04-02 13:32:08.001 (StreamTester.java:run:69) Total events:
3000
<!-- rule "Count epm" timer ( cron: 0/10 * * * * ? ) did not trigger -->
[DEBUG] 2014-04-02 13:32:11.177 (StreamTester.java:run:69) Total events:
4000
[DEBUG] 2014-04-02 13:32:14.231 (StreamTester.java:run:69) Total events:
5000
[DEBUG] 2014-04-02 13:32:17.287 (StreamTester.java:run:69) Total events:
6000
[DEBUG] 2014-04-02 13:32:20.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 6893
[DEBUG] 2014-04-02 13:32:20.329 (StreamTester.java:run:69) Total events:
7000
[DEBUG] 2014-04-02 13:32:23.375 (StreamTester.java:run:69) Total events:
8000
[DEBUG] 2014-04-02 13:32:26.408 (StreamTester.java:run:69) Total events:
9000
[DEBUG] 2014-04-02 13:32:29.522 (StreamTester.java:run:69) Total events:
10000
<!-- rule "Count epm" timer ( cron: 0/10 * * * * ? ) did not trigger -->
[DEBUG] 2014-04-02 13:32:32.560 (StreamTester.java:run:69) Total events:
11000
[DEBUG] 2014-04-02 13:32:35.593 (StreamTester.java:run:69) Total events:
12000
[DEBUG] 2014-04-02 13:32:38.640 (StreamTester.java:run:69) Total events:
13000
[DEBUG] 2014-04-02 13:32:40.002
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 13447
[DEBUG] 2014-04-02 13:32:41.685 (StreamTester.java:run:69) Total events:
14000
[DEBUG] 2014-04-02 13:32:44.735 (StreamTester.java:run:69) Total events:
15000
[DEBUG] 2014-04-02 13:32:47.785 (StreamTester.java:run:69) Total events:
16000
<!-- rule "Count epm" timer ( cron: 0/10 * * * * ? ) did not trigger -->
[DEBUG] 2014-04-02 13:32:50.836 (StreamTester.java:run:69) Total events:
17000
[DEBUG] 2014-04-02 13:32:53.882 (StreamTester.java:run:69) Total events:
18000
[DEBUG] 2014-04-02 13:32:56.917 (StreamTester.java:run:69) Total events:
19000
[DEBUG] 2014-04-02 13:33:00.014
(Rule_Count_live_counters1625367465.java:defaultConsequence:14) Live
counters = 19443
<!-- rule "Count epm" timer ( cron: 0/10 * * * * ? ) did not trigger -->
[DEBUG] 2014-04-02 13:33:00.273 (StreamTester.java:run:69) Total events:
20000
[DEBUG] 2014-04-02 13:33:03.820 (StreamTester.java:run:69) Total events:
21000
[DEBUG] 2014-04-02 13:33:06.934 (StreamTester.java:run:69) Total events:
22000
[DEBUG] 2014-04-02 13:33:10.150 (StreamTester.java:run:69) Total events:
23000
<!-- rule "Count epm" timer ( cron: 0/10 * * * * ? ) delayed (fair enough
IMO) -->
[DEBUG] 2014-04-02 13:33:12.477
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 19327
[DEBUG] 2014-04-02 13:33:13.755 (StreamTester.java:run:69) Total events:
24000
[DEBUG] 2014-04-02 13:33:17.442 (StreamTester.java:run:69) Total events:
25000
<!-- rule "Count epm" timer ( cron: 0/10 * * * * ? ) did not trigger -->
[DEBUG] 2014-04-02 13:33:20.926 (StreamTester.java:run:69) Total events:
26000
[DEBUG] 2014-04-02 13:33:24.392 (StreamTester.java:run:69) Total events:
27000
[DEBUG] 2014-04-02 13:33:27.991 (StreamTester.java:run:69) Total events:
28000
<!-- rule "Count epm" timer ( cron: 0/10 * * * * ? ) did not trigger -->
[DEBUG] 2014-04-02 13:33:31.534 (StreamTester.java:run:69) Total events:
29000
[DEBUG] 2014-04-02 13:33:35.019 (StreamTester.java:run:69) Total events:
30000

The problem, at least on my notebook, is still there @100eps and @50eps
(untriggered rate decreasing in accordance with event throughput).
@10eps everything's fine (see log below):

# StreamTester - 10eps +/- 10%
[DEBUG] 2014-04-02 13:44:39.058 (ReteooRuleBase.java:<init>:200) Starting
Engine in PHREAK mode
[DEBUG] 2014-04-02 13:44:40.011
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 8
[DEBUG] 2014-04-02 13:44:50.004
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 107
[DEBUG] 2014-04-02 13:45:00.004
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 205
[DEBUG] 2014-04-02 13:45:00.010
(Rule_Count_live_counters1625367465.java:defaultConsequence:14) Live
counters = 205
[DEBUG] 2014-04-02 13:45:10.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 304
[DEBUG] 2014-04-02 13:45:20.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 404
[DEBUG] 2014-04-02 13:45:30.011
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 503
[DEBUG] 2014-04-02 13:45:40.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 594
[DEBUG] 2014-04-02 13:45:50.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 595
[DEBUG] 2014-04-02 13:46:00.012
(Rule_Count_live_counters1625367465.java:defaultConsequence:14) Live
counters = 597
[DEBUG] 2014-04-02 13:46:00.015
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 597
[DEBUG] 2014-04-02 13:46:10.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 595
[DEBUG] 2014-04-02 13:46:20.004
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 595
[DEBUG] 2014-04-02 13:46:20.194 (StreamTester.java:run:69) Total events:
1000
[DEBUG] 2014-04-02 13:46:30.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 595
[DEBUG] 2014-04-02 13:46:40.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 595
[DEBUG] 2014-04-02 13:46:50.003
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 594
[DEBUG] 2014-04-02 13:47:00.003
(Rule_Count_live_counters1625367465.java:defaultConsequence:14) Live
counters = 593
[DEBUG] 2014-04-02 13:47:00.005
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 593

More surprisingly (well, maybe not that much) if we switch to the
CronTrigger pattern (i,e, the test case you submitted), everything works
smoothly even @300eps.
The only effect is a delay (1-2 secs) in when the counting rule is actually
triggered (see log below). Delay drops below 1 sec @100eps.

[DEBUG] 2014-04-02 14:10:29.550 (ReteooRuleBase.java:<init>:200) Starting
Engine in PHREAK mode
[Wed Apr 02 14:10:30 CEST 2014] epm = 99
[DEBUG] 2014-04-02 14:10:32.837 (StreamTester.java:run:69) Total events:
1000
[DEBUG] 2014-04-02 14:10:35.939 (StreamTester.java:run:69) Total events:
2000
[DEBUG] 2014-04-02 14:10:38.997 (StreamTester.java:run:69) Total events:
3000
[Wed Apr 02 14:10:41 CEST 2014] epm = 3331
[DEBUG] 2014-04-02 14:10:42.175 (StreamTester.java:run:69) Total events:
4000
[DEBUG] 2014-04-02 14:10:45.229 (StreamTester.java:run:69) Total events:
5000
[DEBUG] 2014-04-02 14:10:48.285 (StreamTester.java:run:69) Total events:
6000
[DEBUG] 2014-04-02 14:10:51.417 (StreamTester.java:run:69) Total events:
7000
[Wed Apr 02 14:10:51 CEST 2014] epm = 6568
[DEBUG] 2014-04-02 14:10:54.486 (StreamTester.java:run:69) Total events:
8000
[DEBUG] 2014-04-02 14:10:57.535 (StreamTester.java:run:69) Total events:
9000
[DEBUG] 2014-04-02 14:11:00.603 (StreamTester.java:run:69) Total events:
10000
[Wed Apr 02 14:11:01 CEST 2014] epm = 9812
[DEBUG] 2014-04-02 14:11:03.719 (StreamTester.java:run:69) Total events:
11000
[DEBUG] 2014-04-02 14:11:06.761 (StreamTester.java:run:69) Total events:
12000
[DEBUG] 2014-04-02 14:11:09.807 (StreamTester.java:run:69) Total events:
13000
[Wed Apr 02 14:11:11 CEST 2014] epm = 13065
[DEBUG] 2014-04-02 14:11:12.940 (StreamTester.java:run:69) Total events:
14000
[DEBUG] 2014-04-02 14:11:16.001 (StreamTester.java:run:69) Total events:
15000
[DEBUG] 2014-04-02 14:11:19.034 (StreamTester.java:run:69) Total events:
16000
[Wed Apr 02 14:11:21 CEST 2014] epm = 16319
[DEBUG] 2014-04-02 14:11:22.129 (StreamTester.java:run:69) Total events:
17000
[DEBUG] 2014-04-02 14:11:25.176 (StreamTester.java:run:69) Total events:
18000
[DEBUG] 2014-04-02 14:11:28.222 (StreamTester.java:run:69) Total events:
19000
[DEBUG] 2014-04-02 14:11:31.458 (StreamTester.java:run:69) Total events:
20000
[Wed Apr 02 14:11:31 CEST 2014] epm = 19491
[DEBUG] 2014-04-02 14:11:34.598 (StreamTester.java:run:69) Total events:
21000
[DEBUG] 2014-04-02 14:11:37.638 (StreamTester.java:run:69) Total events:
22000
[DEBUG] 2014-04-02 14:11:40.777 (StreamTester.java:run:69) Total events:
23000
[Wed Apr 02 14:11:42 CEST 2014] epm = 19450
[DEBUG] 2014-04-02 14:11:44.200 (StreamTester.java:run:69) Total events:
24000
[DEBUG] 2014-04-02 14:11:47.261 (StreamTester.java:run:69) Total events:
25000
[DEBUG] 2014-04-02 14:11:50.328 (StreamTester.java:run:69) Total events:
26000
[Wed Apr 02 14:11:52 CEST 2014] epm = 19335
[DEBUG] 2014-04-02 14:11:53.717 (StreamTester.java:run:69) Total events:
27000
[DEBUG] 2014-04-02 14:11:56.768 (StreamTester.java:run:69) Total events:
28000
[DEBUG] 2014-04-02 14:11:59.814 (StreamTester.java:run:69) Total events:
29000
[Wed Apr 02 14:12:02 CEST 2014] epm = 19251
[DEBUG] 2014-04-02 14:12:03.349 (StreamTester.java:run:69) Total events:
30000

Possibly a noop is less demanding than a lengthy operation such as an
accumulate...

Hope this helps.
Thanks in advance,
Vieri

-- 
Vieri Emiliani
vieri.emiliani at gmail.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/rules-users/attachments/20140402/9682a702/attachment-0001.html 