2:28 a.m.
Dear Drools Experts,
*Short version*
1. Cron-based rules triggers (more than once) for a full second, rather
than once every defined period;
2. After some time, event creation from the drl seems to hang. The "time
to hang" decreases as we increase the throughput of incoming events;
3. The two issues seem to be somehow related (well, maybe).
*Full version*
We are testing Drools Fusion to implement CEP functionalities in our
platform. We are performing these tests using Drools 6.0.1.Final.
As a basic test case, we set up a synthetic stream of events, and defined a
couple of rules to implement a simple throughput metric. Here's the
complete drl:
*package* it.intext.unity.test
*import* it.intext.unity.test.SynthEvent;
*import* java.util.Date;
*global* org.slf4j.Logger logger;
*declare* SynthEvent
@role( event )
@timestamp( timestamp )
*end*
*declare* EventCounter
@role( event )
@timestamp( timestamp )
id : *long*
key : String
timestamp : Date
*end*
// Business rules
*rule* "Create counter"
*when*
$e : SynthEvent() *from* entry-point "synth"
*then*
entryPoints["counters"].*insert*(*new* EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
*end*
// Metrics
*rule* "Count epm"
// Emit count every 10s, accumulate over 1m
timer ( cron: 0/10 * * * * ? )
*when*
Number( $count : intValue ) *from* *accumulate*(
EventCounter( key == "event" ) over window:time( 60s
)*from*entry-point
"counters", count(1) )
*then*
logger.debug("epm = {}", $count );
*end*
The SynthEvent class is very basic:
*public* *class* SynthEvent {
*long* id;
Date timestamp;
List<String> meta;
... // Getters/Setters and constructors omitted
}
Now, the test is performed running the session in one thread (code below)
*private* *void* process(*final* KieSession session) {
*new* Thread(){
*public* *void* run() {
session.fireUntilHalt();
};
}.start();
}
while feeding the events on a second thread (code below)
*private* *void* feed(*final* KieSession session) {
*new* Thread(){
@SuppressWarnings("unchecked")
*public* *void* run() {
*try* {
*int* counter = 0;
*while*(*true*) {
counter++;
session.execute(CommandFactory.
*newInsert*(createEvent(), *null*, *false*, "synth"));
Thread.*sleep*(getSleepRate());
*if* ((counter % 1000) == 0) {
*logger*.debug("Total events: {}",
counter);
}
}
} *catch* (InterruptedException e) {
*logger*.warn("{}", e);
}
};
}.start();
}
I expected the cron rule "count epm" to trigger once every 10 seconds. But
here's an extract from the log (running at 5 events per second +/- 20%):
[DEBUG] 2014-03-25 04:56:10.008
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 1
[DEBUG] 2014-03-25 04:56:10.075
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2
[DEBUG] 2014-03-25 04:56:10.262
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3
[DEBUG] 2014-03-25 04:56:10.507
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 4
[DEBUG] 2014-03-25 04:56:10.678
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 5
[DEBUG] 2014-03-25 04:56:10.871
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 6
[DEBUG] 2014-03-25 04:56:20.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 50
[DEBUG] 2014-03-25 04:56:20.042
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 51
[DEBUG] 2014-03-25 04:56:20.231
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 52
[DEBUG] 2014-03-25 04:56:20.405
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 53
[DEBUG] 2014-03-25 04:56:20.647
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 54
[DEBUG] 2014-03-25 04:56:20.823
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 55
[DEBUG] 2014-03-25 04:56:20.992
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 56
As you can see, the "count epm" rules fires once per incoming event for a
full second (e.g. for the second cycle we see the first activation at
04:56:20.001 and the last one at 04:56:20.992).
This is not a major issue, since it can be solved with a sort-of
publish/subscribe pattern which, BTW, increases the system stability (if
anyone is interested I can post more details on the list).
Anyhow, the test ran for more than 20' consistently until we decided it was
enough.
Now, the problem is that as we increase the throughput (e.g. 50 events per
second), the test runs for a few minutes before it becomes inconsistent.
The evidence is that the first rule stops to trigger, and EventCounter
aren't created anymore. Here's a log extract:
[DEBUG] 2014-03-25 07:37:40.008
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 199
[DEBUG] 2014-03-25 07:37:40.017
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 200
[DEBUG] 2014-03-25 07:37:40.034
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 201
[DEBUG] 2014-03-25 07:37:40.058
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 202
[DEBUG] 2014-03-25 07:37:40.076
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 203
*... here the system is stable as we get about 3K events per minute as
expected*
[DEBUG] 2014-03-25 07:38:36.022 (StreamTester.java:run:70) Total events:
3000
[DEBUG] 2014-03-25 07:38:40.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2999
[DEBUG] 2014-03-25 07:38:40.016
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2998
[DEBUG] 2014-03-25 07:38:40.024
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2999
[DEBUG] 2014-03-25 07:38:40.034
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2998
[DEBUG] 2014-03-25 07:38:40.047
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2999
[DEBUG] 2014-03-25 07:38:40.057
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2998
...
[DEBUG] 2014-03-25 07:39:50.974
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3008
[DEBUG] 2014-03-25 07:39:50.988
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3007
[DEBUG] 2014-03-25 07:39:50.996
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3008
[DEBUG] 2014-03-25 07:39:55.842 (StreamTester.java:run:70) Total events:
7000
*... Somewhere in between the system becomes inconsistent and the number of
events decreases to 0*
[DEBUG] 2014-03-25 07:40:00.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2734
[DEBUG] 2014-03-25 07:40:00.017
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2733
[DEBUG] 2014-03-25 07:40:00.037
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2732
...
[DEBUG] 2014-03-25 07:40:50.937
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 181
[DEBUG] 2014-03-25 07:40:50.953
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 180
[DEBUG] 2014-03-25 07:40:50.975
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 179
[DEBUG] 2014-03-25 07:40:50.997
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 178
[DEBUG] 2014-03-25 07:40:55.438 (StreamTester.java:run:70) Total events:
10000
[DEBUG] 2014-03-25 07:41:00.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
[DEBUG] 2014-03-25 07:41:10.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
We added a quick rule to count "live EventCounter"
*rule* "Count live counters"
timer ( cron: 0/60 * * * * ? )
*when*
Number( $count : intValue ) *from* *accumulate*(
EventCounter( key == "event" ) *from* entry-point
"counters",
count(1) )
*then*
logger.debug("Live counters = {}", $count );
*end*
and, again, the evidence is that when things go wrong the EventCounter
events aren't created anymore.
[DEBUG] 2014-03-25 07:40:55.438 (StreamTester.java:run:70) Total events:
10000
[DEBUG] 2014-03-25 07:41:00.001
(Rule_Count_live_counters1625367465.java:defaultConsequence:14) Live
counters = 0
[DEBUG] 2014-03-25 07:41:00.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
[DEBUG] 2014-03-25 07:41:10.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
Adding a debug line in the "Create counter" rule confirm this hypotesis
(after a while the rule won't trigger anymore). Modified rule is:
*rule* "Create counter"
*when*
$e : SynthEvent() *from* entry-point "synth"
*then*
entryPoints["counters"].*insert*( *new* EventCounter( $e.getId(),
"event", $e.getTimestamp() ) );
*if* (Math.random() < 0.01) logger.debug("New event: {}", $e.getId());
*end*
When the system becomes inconsistent, we stop seeing "New event" log lines.
What are we missing? Any suggestion? Anyone experienced the same problems
we have?
Your help will be greatly appreciated.
Thanks in advance,
Vieri
3:12 a.m.
A rule with timer will only continue firing if its first true state
remains constant. This means that you can't do what you want to do
this way. (You might set up a rule with a repeating or cron timer that
inserts a Trigger fact that triggers the accumulate and is retracted,
or do some similar haque.)
The session.execute(command) is a rather roundabout way for inserting
facts. If you want to be fast, use session.insert(.).
Don't use rules for keeping track what's going on, or the Heisenberg
effect will spoil your efforts. It's better to set up insert/retract
listeners, e.g. for maintaining counters of facts per class. This
might give you a better idea of what goes on and wrong. (We'd all be
interested to hear more about the effect you've described!)
Cheers
-W
On 25/03/2014, Vieri <vieri.emiliani(a)gmail.com> wrote:
Dear Drools Experts,
*Short version*
1. Cron-based rules triggers (more than once) for a full second, rather
than once every defined period;
2. After some time, event creation from the drl seems to hang. The "time
to hang" decreases as we increase the throughput of incoming events;
3. The two issues seem to be somehow related (well, maybe).
*Full version*
We are testing Drools Fusion to implement CEP functionalities in our
platform. We are performing these tests using Drools 6.0.1.Final.
As a basic test case, we set up a synthetic stream of events, and defined a
couple of rules to implement a simple throughput metric. Here's the
complete drl:
*package* it.intext.unity.test
*import* it.intext.unity.test.SynthEvent;
*import* java.util.Date;
*global* org.slf4j.Logger logger;
*declare* SynthEvent
@role( event )
@timestamp( timestamp )
*end*
*declare* EventCounter
@role( event )
@timestamp( timestamp )
id : *long*
key : String
timestamp : Date
*end*
// Business rules
*rule* "Create counter"
*when*
$e : SynthEvent() *from* entry-point "synth"
*then*
entryPoints["counters"].*insert*(*new* EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
*end*
// Metrics
*rule* "Count epm"
// Emit count every 10s, accumulate over 1m
timer ( cron: 0/10 * * * * ? )
*when*
Number( $count : intValue ) *from* *accumulate*(
EventCounter( key == "event" ) over window:time( 60s
)*from*entry-point
"counters", count(1) )
*then*
logger.debug("epm = {}", $count );
*end*
The SynthEvent class is very basic:
*public* *class* SynthEvent {
*long* id;
Date timestamp;
List<String> meta;
... // Getters/Setters and constructors omitted
}
Now, the test is performed running the session in one thread (code below)
*private* *void* process(*final* KieSession session) {
*new* Thread(){
*public* *void* run() {
session.fireUntilHalt();
};
}.start();
}
while feeding the events on a second thread (code below)
*private* *void* feed(*final* KieSession session) {
*new* Thread(){
@SuppressWarnings("unchecked")
*public* *void* run() {
*try* {
*int* counter = 0;
*while*(*true*) {
counter++;
session.execute(CommandFactory.
*newInsert*(createEvent(), *null*, *false*, "synth"));
Thread.*sleep*(getSleepRate());
*if* ((counter % 1000) == 0) {
*logger*.debug("Total events: {}",
counter);
}
}
} *catch* (InterruptedException e) {
*logger*.warn("{}", e);
}
};
}.start();
}
I expected the cron rule "count epm" to trigger once every 10 seconds. But
here's an extract from the log (running at 5 events per second +/- 20%):
[DEBUG] 2014-03-25 04:56:10.008
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 1
[DEBUG] 2014-03-25 04:56:10.075
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2
[DEBUG] 2014-03-25 04:56:10.262
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3
[DEBUG] 2014-03-25 04:56:10.507
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 4
[DEBUG] 2014-03-25 04:56:10.678
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 5
[DEBUG] 2014-03-25 04:56:10.871
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 6
[DEBUG] 2014-03-25 04:56:20.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 50
[DEBUG] 2014-03-25 04:56:20.042
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 51
[DEBUG] 2014-03-25 04:56:20.231
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 52
[DEBUG] 2014-03-25 04:56:20.405
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 53
[DEBUG] 2014-03-25 04:56:20.647
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 54
[DEBUG] 2014-03-25 04:56:20.823
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 55
[DEBUG] 2014-03-25 04:56:20.992
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 56
As you can see, the "count epm" rules fires once per incoming event for a
full second (e.g. for the second cycle we see the first activation at
04:56:20.001 and the last one at 04:56:20.992).
This is not a major issue, since it can be solved with a sort-of
publish/subscribe pattern which, BTW, increases the system stability (if
anyone is interested I can post more details on the list).
Anyhow, the test ran for more than 20' consistently until we decided it was
enough.
Now, the problem is that as we increase the throughput (e.g. 50 events per
second), the test runs for a few minutes before it becomes inconsistent.
The evidence is that the first rule stops to trigger, and EventCounter
aren't created anymore. Here's a log extract:
[DEBUG] 2014-03-25 07:37:40.008
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 199
[DEBUG] 2014-03-25 07:37:40.017
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 200
[DEBUG] 2014-03-25 07:37:40.034
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 201
[DEBUG] 2014-03-25 07:37:40.058
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 202
[DEBUG] 2014-03-25 07:37:40.076
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 203
*... here the system is stable as we get about 3K events per minute as
expected*
[DEBUG] 2014-03-25 07:38:36.022 (StreamTester.java:run:70) Total events:
3000
[DEBUG] 2014-03-25 07:38:40.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2999
[DEBUG] 2014-03-25 07:38:40.016
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2998
[DEBUG] 2014-03-25 07:38:40.024
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2999
[DEBUG] 2014-03-25 07:38:40.034
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2998
[DEBUG] 2014-03-25 07:38:40.047
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2999
[DEBUG] 2014-03-25 07:38:40.057
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2998
...
[DEBUG] 2014-03-25 07:39:50.974
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3008
[DEBUG] 2014-03-25 07:39:50.988
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3007
[DEBUG] 2014-03-25 07:39:50.996
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 3008
[DEBUG] 2014-03-25 07:39:55.842 (StreamTester.java:run:70) Total events:
7000
*... Somewhere in between the system becomes inconsistent and the number of
events decreases to 0*
[DEBUG] 2014-03-25 07:40:00.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2734
[DEBUG] 2014-03-25 07:40:00.017
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2733
[DEBUG] 2014-03-25 07:40:00.037
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 2732
...
[DEBUG] 2014-03-25 07:40:50.937
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 181
[DEBUG] 2014-03-25 07:40:50.953
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 180
[DEBUG] 2014-03-25 07:40:50.975
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 179
[DEBUG] 2014-03-25 07:40:50.997
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 178
[DEBUG] 2014-03-25 07:40:55.438 (StreamTester.java:run:70) Total events:
10000
[DEBUG] 2014-03-25 07:41:00.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
[DEBUG] 2014-03-25 07:41:10.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
We added a quick rule to count "live EventCounter"
*rule* "Count live counters"
timer ( cron: 0/60 * * * * ? )
*when*
Number( $count : intValue ) *from* *accumulate*(
EventCounter( key == "event" ) *from* entry-point
"counters",
count(1) )
*then*
logger.debug("Live counters = {}", $count );
*end*
and, again, the evidence is that when things go wrong the EventCounter
events aren't created anymore.
[DEBUG] 2014-03-25 07:40:55.438 (StreamTester.java:run:70) Total events:
10000
[DEBUG] 2014-03-25 07:41:00.001
(Rule_Count_live_counters1625367465.java:defaultConsequence:14) Live
counters = 0
[DEBUG] 2014-03-25 07:41:00.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
[DEBUG] 2014-03-25 07:41:10.001
(Rule_Count_epm442808096.java:defaultConsequence:14) epm = 0
Adding a debug line in the "Create counter" rule confirm this hypotesis
(after a while the rule won't trigger anymore). Modified rule is:
*rule* "Create counter"
*when*
$e : SynthEvent() *from* entry-point "synth"
*then*
entryPoints["counters"].*insert*( *new* EventCounter( $e.getId(),
"event", $e.getTimestamp() ) );
*if* (Math.random() < 0.01) logger.debug("New event: {}",
$e.getId());
*end*
When the system becomes inconsistent, we stop seeing "New event" log lines.
What are we missing? Any suggestion? Anyone experienced the same problems
we have?
Your help will be greatly appreciated.
Thanks in advance,
Vieri
5:18 a.m.
Wolfgang,
thanks for the prompt reply. Inline comments.
On 25 March 2014 09:12, Wolfgang Laun <wolfgang.laun(a)gmail.com> wrote:
A rule with timer will only continue firing if its first true state
remains constant. This means that you can't do what you want to do
this way. (You might set up a rule with a repeating or cron timer that
inserts a Trigger fact that triggers the accumulate and is retracted,
or do some similar haque.)
This is exactly what we did (the "pretentiously called" pub/sub pattern).
declare CronTrigger
@role( event )
@timestamp( timestamp )
interval : String
timestamp : Date
end
declare MetricRequest
metric : String
end
declare Subscription
key : String
interval : String
end
And the rules are:
// Setup rules
rule "Create subscriptions"
when
then
insert( new Subscription("epm", "10s") );
end
// Cron management
rule "Cron trigger 10s"
timer ( cron: 0/10 * * * * ? )
when
then
entryPoints["triggers"].insert( new CronTrigger( "10s", new Date() )
);
end
rule "Subscription"
when
CronTrigger( $interval := interval ) from entry-point "triggers"
Subscription( $interval := interval, $key : key )
then
entryPoints["requests"].insert( new MetricRequest($key) );
end
// Business rules
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert( new EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
end
// Metrics
rule "Count epm"
when
$req : MetricRequest( metric == "epm" ) from entry-point "requests"
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s ) from
entry-point "counters", count(1) )
then
logger.debug("epm = {}", $count );
retract( $req );
end
The session.execute(command) is a rather roundabout way for
inserting
facts. If you want to be fast, use session.insert(.).
Good to know. Still, the system hangs (i.e. no EventCounter event created)
no matter which method I use (session.insert(e),
session.getEntryPoint("synth").insert(e) or
session.execute(CommandFactory.newInsert(e, null, false, "synth")). I
cannot see any evidence that proves one method to be less unstable than the
others. BTW, it seemed to me that session.insert wasn't working properly
but further testing proved I was wrong.
Don't use rules for keeping track what's going on, or the
Heisenberg
effect will spoil your efforts. It's better to set up insert/retract
listeners, e.g. for maintaining counters of facts per class. This
might give you a better idea of what goes on and wrong. (We'd all be
interested to hear more about the effect you've described!)
Actually, we are working on a real-time analytic tool and, yes, the
capability to generate temporally aggregated metrics, either from original
or inferred events, is crucial for us. This synthetic example is just a
test case, and I hoped it would go more smoothly. We used ESPER here and
there, and Drools Expert in many of our projects. We would love to switch
to Drools also for the CEP part, but I must admit I am a bit worried by our
initial tests.
Hopefully, with the help of the Drools' Community we'll manage to solve our
current issues ;)
So said:
1. No matter how we add events to the session, at some point the "Create
counter" rule stops triggering and inferred events aren't created
anymore.
2. If we switch to the pub/sub the system is more stable. Still, it
hangs as we either increase the throughput or add complexity (read more
rules).
Hope we'll get some help from this valuable community.
Thanks,
Vieri
Cheers
-W
P.S. Full source code (not much more than I posted here) available on
request. Just to speed up things a bit ;)
On 25/03/2014, Vieri <vieri.emiliani(a)gmail.com> wrote:
> Dear Drools Experts,
>
>
> *Short version*
>
>
> 1. Cron-based rules triggers (more than once) for a full second,
rather
> than once every defined period;
> 2. After some time, event creation from the drl seems to hang. The
"time
> to hang" decreases as we increase the throughput of incoming events;
> 3. The two issues seem to be somehow related (well, maybe).
>
> *Full version*
>
>
> We are testing Drools Fusion to implement CEP functionalities in our
> platform. We are performing these tests using Drools 6.0.1.Final.
>...
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
--
Vieri Emiliani
8:09 a.m.
Hi,
I am trying to reproduce the issue you reported, but so far I couldn't. This
is drl I am using:
import org.drools.test.SynthEvent
import java.util.Date
declare SynthEvent
@role( event )
@timestamp( timestamp )
end
declare EventCounter
@role( event )
@timestamp( timestamp )
id : long
key : String
timestamp : Date
end
declare CronTrigger end
rule "Trigger Metric"
timer ( cron: 0/10 * * * * ? )\n
when
then
entryPoints["triggers"].insert( new CronTrigger() );
end
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert(new EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
end
rule "Count epm"
when
$trigger : CronTrigger() from entry-point "triggers"
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s )from entry-point
"counters", count(1) )
then
System.out.println("[" + new Date() + "] epm = " + $count );
retract($trigger);
end
and this is how I am using it:
final KieSession ksession = kbase.newKieSession();
EntryPoint synthEP = ksession.getEntryPoint("synth");
new Thread(){
public void run() {
ksession.fireUntilHalt();
};
}.start();
long counter = 0;
while(true) {
counter++;
synthEP.insert(new SynthEvent(counter));
try {
Thread.sleep(20L);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
if ((counter % 1000) == 0) {
System.out.println("Total events: " + counter);
}
}
Note that since you mentioned you expected around 3K events per minute I am
doing a sleep of 20 msec between the insertion of 2 consecutive events. Is
that correct?
I let this run for 10 minutes and I got the output I am pasting at the end
of this email, so I think that it is working as expected. Please let me know
if you'll give a try at my test case and if it works correctly also for you.
Also if you find any further problem feel free to send a reproducer so I
could give it a try.
Regards,
Mario
[Tue Mar 25 13:37:30 CET 2014] epm = 318
[Tue Mar 25 13:37:40 CET 2014] epm = 774
Total events: 1000
[Tue Mar 25 13:37:50 CET 2014] epm = 1259
[Tue Mar 25 13:38:00 CET 2014] epm = 1746
Total events: 2000
[Tue Mar 25 13:38:10 CET 2014] epm = 2233
[Tue Mar 25 13:38:20 CET 2014] epm = 2720
Total events: 3000
[Tue Mar 25 13:38:30 CET 2014] epm = 2890
[Tue Mar 25 13:38:40 CET 2014] epm = 2922
Total events: 4000
[Tue Mar 25 13:38:50 CET 2014] epm = 2926
[Tue Mar 25 13:39:00 CET 2014] epm = 2929
Total events: 5000
[Tue Mar 25 13:39:10 CET 2014] epm = 2933
[Tue Mar 25 13:39:20 CET 2014] epm = 2938
Total events: 6000
[Tue Mar 25 13:39:30 CET 2014] epm = 2944
[Tue Mar 25 13:39:40 CET 2014] epm = 2948
Total events: 7000
[Tue Mar 25 13:39:50 CET 2014] epm = 2952
[Tue Mar 25 13:40:00 CET 2014] epm = 2956
Total events: 8000
[Tue Mar 25 13:40:10 CET 2014] epm = 2958
[Tue Mar 25 13:40:20 CET 2014] epm = 2959
Total events: 9000
[Tue Mar 25 13:40:30 CET 2014] epm = 2959
[Tue Mar 25 13:40:40 CET 2014] epm = 2960
Total events: 10000
[Tue Mar 25 13:40:50 CET 2014] epm = 2960
[Tue Mar 25 13:41:00 CET 2014] epm = 2960
Total events: 11000
[Tue Mar 25 13:41:10 CET 2014] epm = 2961
[Tue Mar 25 13:41:20 CET 2014] epm = 2963
Total events: 12000
[Tue Mar 25 13:41:30 CET 2014] epm = 2964
[Tue Mar 25 13:41:40 CET 2014] epm = 2964
Total events: 13000
[Tue Mar 25 13:41:50 CET 2014] epm = 2966
[Tue Mar 25 13:42:00 CET 2014] epm = 2966
Total events: 14000
[Tue Mar 25 13:42:10 CET 2014] epm = 2967
[Tue Mar 25 13:42:20 CET 2014] epm = 2964
Total events: 15000
[Tue Mar 25 13:42:30 CET 2014] epm = 2965
[Tue Mar 25 13:42:40 CET 2014] epm = 2966
Total events: 16000
[Tue Mar 25 13:42:50 CET 2014] epm = 2965
[Tue Mar 25 13:43:00 CET 2014] epm = 2967
Total events: 17000
[Tue Mar 25 13:43:10 CET 2014] epm = 2966
[Tue Mar 25 13:43:20 CET 2014] epm = 2969
Total events: 18000
[Tue Mar 25 13:43:30 CET 2014] epm = 2969
[Tue Mar 25 13:43:40 CET 2014] epm = 2969
[Tue Mar 25 13:43:50 CET 2014] epm = 2970
Total events: 19000
[Tue Mar 25 13:44:00 CET 2014] epm = 2969
[Tue Mar 25 13:44:10 CET 2014] epm = 2970
Total events: 20000
[Tue Mar 25 13:44:20 CET 2014] epm = 2969
[Tue Mar 25 13:44:30 CET 2014] epm = 2969
Total events: 21000
[Tue Mar 25 13:44:40 CET 2014] epm = 2969
[Tue Mar 25 13:44:50 CET 2014] epm = 2969
Total events: 22000
[Tue Mar 25 13:45:00 CET 2014] epm = 2969
[Tue Mar 25 13:45:10 CET 2014] epm = 2969
Total events: 23000
[Tue Mar 25 13:45:20 CET 2014] epm = 2969
[Tue Mar 25 13:45:30 CET 2014] epm = 2968
Total events: 24000
[Tue Mar 25 13:45:40 CET 2014] epm = 2969
[Tue Mar 25 13:45:50 CET 2014] epm = 2969
Total events: 25000
[Tue Mar 25 13:46:00 CET 2014] epm = 2969
[Tue Mar 25 13:46:10 CET 2014] epm = 2969
Total events: 26000
[Tue Mar 25 13:46:20 CET 2014] epm = 2968
[Tue Mar 25 13:46:30 CET 2014] epm = 2969
Total events: 27000
[Tue Mar 25 13:46:40 CET 2014] epm = 2968
[Tue Mar 25 13:46:50 CET 2014] epm = 2969
Total events: 28000
[Tue Mar 25 13:47:00 CET 2014] epm = 2969
[Tue Mar 25 13:47:10 CET 2014] epm = 2969
Total events: 29000
[Tue Mar 25 13:47:20 CET 2014] epm = 2969
--
View this message in context:
http://drools.46999.n3.nabble.com/rules-users-Drools-Fusion-inconsistenci...
Sent from the Drools: User forum mailing list archive at Nabble.com.
11:09 a.m.
First of all, thanks for the support.
Mario, I confirm that the case you provided works fine also at my side.
Still, have you tried my first example (using the cron directly to the
counting rule)? Can you confirm it is not working, since this was my first
concern?
As I said in the previous post, using the CronTrigger pattern greatly
improves stability (I managed to run it at 500 eps), but it is not
resolutive.
Adding a few rules, it's enough to go back to instability.
Here's the complete test case.
Basically, a SynthEvent is created with the meta list populated randomly
with up to 4 values picked from a list of 10 strings ("one" to
"ten").
For each meta value an Entity object is created (for enumeration purposes).
Then, rules generate metrics for both events (every 10s) and meta (every
60s).
Test is ran at 300 events per second +/- 20% (our real use case is closer
to some hundreds events per second than some tens).
First of all, the full SynthEvent class:
package it.intext.unity.test;
import java.util.Arrays;
import java.util.Date;
import java.util.List;
public class SynthEvent {
long id;
Date timestamp;
List<String> meta;
public long getId() {
return id;
}
public void setId(long id) {
this.id = id;
}
public Date getTimestamp() {
return timestamp;
}
public void setTimestamp(Date timestamp) {
this.timestamp = timestamp;
}
public List<String> getMeta() {
return meta;
}
public void setMeta(List<String> meta) {
this.meta = meta;
}
public SynthEvent() {
super();
}
@Override public String toString() { StringBuilder builder = new
StringBuilder(); builder.append("SynthEvent [id="); builder.append(id);
builder.append(", timestamp="); builder.append(timestamp);
builder.append(", meta="); builder.append(meta); builder.append("]");
return builder.toString(); }
public String toString() {
StringBuilder builder = new StringBuilder();
builder.append("SynthEvent [id=");
builder.append(id);
builder.append(", timestamp=");
builder.append(timestamp);
builder.append(", meta=");
builder.append(meta);
builder.append("]");
return builder.toString();
}
}
Here's the feeding part of the test class:
private void process(final KieSession session) {
new Thread(){
public void run() {
session.fireUntilHalt();
};
}.start();
}
private void feed(final KieSession session) {
new Thread(){
public void run() {
try {
int counter = 0;
while(true) {
counter++;
session.getEntryPoint("synth").insert(createEvent());
Thread.sleep(getSleepRate());
if ((counter % 1000) == 0) {
logger.debug("Total events: {}", counter);
}
}
} catch (InterruptedException e) {
logger.warn("{}", e);
}
};
}.start();
}
static final int eventThroughput = 300;
static final double variance = 0.2;
protected long getSleepRate() {
return (long) (1000.0 / (eventThroughput * ((1.0 - variance) +
Math.random() * variance * 2)));
}
protected SynthEvent createEvent() {
SynthEvent ret = new SynthEvent();
ret.setId(System.currentTimeMillis());
ret.setTimestamp(new Date());
ret.setMeta(createMeta());
return ret;
}
static final List<String> metas = Arrays.asList("one", "two",
"three",
"four", "five", "six", "seven", "eight",
"nine", "ten");
static final int maxMeta = 4;
static final int metaSize = metas.size();
protected List<String> createMeta() {
List<String> ret = new ArrayList<String>();
int nofItems = (int) (Math.random() * maxMeta);
for (int i=0; i<nofItems; i++) {
ret.add(metas.get((int) (Math.random() * metaSize)));
}
return ret;
}
And here's the drl, using the CronTrigger pattern:
package it.intext.unity.test
import it.intext.unity.test.SynthEvent;
import java.util.Date;
global org.slf4j.Logger logger;
declare SynthEvent
@role( event )
@timestamp( timestamp )
end
declare EventCounter
@role( event )
@timestamp( timestamp )
id : long
key : String
timestamp : Date
end
declare CronTrigger
@role( event )
@timestamp( timestamp )
interval : String
timestamp : Date
end
declare MetricRequest
metric : String
end
declare Subscription
key : String
interval : String
end
declare Entity
key : String
end
// Setup rules
rule "Create subscriptions"
when
then
insert( new Subscription("epm", "10s") );
end
rule "Create meta subscriptions 60s"
when
Entity( $key : key )
then
insert( new Subscription($key, "60s") );
end
// Cron management
rule "Cron trigger 10s"
timer ( cron: 0/10 * * * * ? )
when
then
entryPoints["triggers"].insert( new CronTrigger( "10s", new Date() )
);
end
rule "Cron trigger 60s"
timer ( cron: 0/60 * * * * ? )
when
then
entryPoints["triggers"].insert( new CronTrigger( "60s", new Date() )
);
end
rule "Subscription"
when
CronTrigger( $interval := interval ) from entry-point "triggers"
Subscription( $interval := interval, $key : key )
then
entryPoints["requests"].insert( new MetricRequest($key) );
end
// Business rules
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert( new EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
end
rule "Create meta counter"
when
$e : SynthEvent() from entry-point "synth"
$meta : String( ) from $e.getMeta()
then
entryPoints["counters"].insert( new EventCounter( $e.getId(), $meta,
$e.getTimestamp() ) );
end
rule "Create meta"
when
$e : SynthEvent() from entry-point "synth"
$meta : String( ) from $e.getMeta()
not( Entity( key == $meta ) )
then
insert( new Entity($meta) );
end
rule "Count epm"
when
$req : MetricRequest( metric == "epm" ) from entry-point "requests"
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s ) from
entry-point "counters", count(1) )
then
logger.debug("epm = {}", $count );
retract( $req );
end
rule "Count meta"
when
$req : MetricRequest( $key := metric ) from entry-point "requests"
Number( $count : intValue ) from accumulate(
EventCounter( $key := key ) over window:time( 60s ) from
entry-point "counters", count(1) )
then
logger.debug("{} = {}", $key, $count );
retract( $req );
end
Here's the log of a quick-failing run:
[DEBUG] 2014-03-25 16:28:04.769 (StreamTester.java:run:68) Total events:
1000
[DEBUG] 2014-03-25 16:28:07.774 (StreamTester.java:run:68) Total events:
2000
[DEBUG] 2014-03-25 16:28:10.100
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 2769
[DEBUG] 2014-03-25 16:28:10.723 (StreamTester.java:run:68) Total events:
3000
[DEBUG] 2014-03-25 16:28:13.681 (StreamTester.java:run:68) Total events:
4000
[DEBUG] 2014-03-25 16:28:16.668 (StreamTester.java:run:68) Total events:
5000
[DEBUG] 2014-03-25 16:28:19.541 (StreamTester.java:run:68) Total events:
6000
[DEBUG] 2014-03-25 16:28:20.054
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 6164
[DEBUG] 2014-03-25 16:28:22.421 (StreamTester.java:run:68) Total events:
7000
[DEBUG] 2014-03-25 16:28:25.336 (StreamTester.java:run:68) Total events:
8000
[DEBUG] 2014-03-25 16:28:28.217 (StreamTester.java:run:68) Total events:
9000
[DEBUG] 2014-03-25 16:28:30.030
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 9627
[DEBUG] 2014-03-25 16:28:31.088 (StreamTester.java:run:68) Total events:
10000
[DEBUG] 2014-03-25 16:28:33.968 (StreamTester.java:run:68) Total events:
11000
[DEBUG] 2014-03-25 16:28:36.904 (StreamTester.java:run:68) Total events:
12000
[DEBUG] 2014-03-25 16:28:39.782 (StreamTester.java:run:68) Total events:
13000
[DEBUG] 2014-03-25 16:28:40.024
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 13077
[DEBUG] 2014-03-25 16:28:42.736 (StreamTester.java:run:68) Total events:
14000
[DEBUG] 2014-03-25 16:28:45.615 (StreamTester.java:run:68) Total events:
15000
[DEBUG] 2014-03-25 16:28:48.459 (StreamTester.java:run:68) Total events:
16000
[DEBUG] 2014-03-25 16:28:50.030
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 16538
[DEBUG] 2014-03-25 16:28:51.412 (StreamTester.java:run:68) Total events:
17000
[DEBUG] 2014-03-25 16:28:54.293 (StreamTester.java:run:68) Total events:
18000
[DEBUG] 2014-03-25 16:28:57.549 (StreamTester.java:run:68) Total events:
19000
[DEBUG] 2014-03-25 16:29:00.021
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 19860
[DEBUG] 2014-03-25 16:29:00.211
(Rule_Count_meta1429890510.java:defaultConsequence:14) two = 2972
[DEBUG] 2014-03-25 16:29:00.214
(Rule_Count_meta1429890510.java:defaultConsequence:14) eight = 3099
[DEBUG] 2014-03-25 16:29:00.215
(Rule_Count_meta1429890510.java:defaultConsequence:14) ten = 3008
[DEBUG] 2014-03-25 16:29:00.215
(Rule_Count_meta1429890510.java:defaultConsequence:14) three = 2982
[DEBUG] 2014-03-25 16:29:00.216
(Rule_Count_meta1429890510.java:defaultConsequence:14) six = 3006
[DEBUG] 2014-03-25 16:29:00.216
(Rule_Count_meta1429890510.java:defaultConsequence:14) five = 2959
[DEBUG] 2014-03-25 16:29:00.217
(Rule_Count_meta1429890510.java:defaultConsequence:14) one = 2934
[DEBUG] 2014-03-25 16:29:00.217
(Rule_Count_meta1429890510.java:defaultConsequence:14) seven = 3013
[DEBUG] 2014-03-25 16:29:00.218
(Rule_Count_meta1429890510.java:defaultConsequence:14) four = 2973
[DEBUG] 2014-03-25 16:29:00.218
(Rule_Count_meta1429890510.java:defaultConsequence:14) nine = 3012
[DEBUG] 2014-03-25 16:29:00.510 (StreamTester.java:run:68) Total events:
20000
[DEBUG] 2014-03-25 16:29:03.671 (StreamTester.java:run:68) Total events:
21000
[DEBUG] 2014-03-25 16:29:06.798 (StreamTester.java:run:68) Total events:
22000
[DEBUG] 2014-03-25 16:29:09.969 (StreamTester.java:run:68) Total events:
23000
[DEBUG] 2014-03-25 16:29:10.045
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 20242
[DEBUG] 2014-03-25 16:29:13.362 (StreamTester.java:run:68) Total events:
24000
[DEBUG] 2014-03-25 16:29:16.352 (StreamTester.java:run:68) Total events:
25000
[DEBUG] 2014-03-25 16:29:19.400 (StreamTester.java:run:68) Total events:
26000
[DEBUG] 2014-03-25 16:29:20.849
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 20029
[DEBUG] 2014-03-25 16:29:22.795 (StreamTester.java:run:68) Total events:
27000
[DEBUG] 2014-03-25 16:29:25.785 (StreamTester.java:run:68) Total events:
28000
[DEBUG] 2014-03-25 16:29:28.855 (StreamTester.java:run:68) Total events:
29000
*[DEBUG] 2014-03-25 16:29:30.018
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 18647*
[DEBUG] 2014-03-25 16:29:31.858 (StreamTester.java:run:68) Total events:
30000
[DEBUG] 2014-03-25 16:29:34.983 (StreamTester.java:run:68) Total events:
31000
[DEBUG] 2014-03-25 16:29:37.947 (StreamTester.java:run:68) Total events:
32000
[DEBUG] 2014-03-25 16:29:40.011
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 15201
[DEBUG] 2014-03-25 16:29:40.928 (StreamTester.java:run:68) Total events:
33000
[DEBUG] 2014-03-25 16:29:43.920 (StreamTester.java:run:68) Total events:
34000
[DEBUG] 2014-03-25 16:29:46.911 (StreamTester.java:run:68) Total events:
35000
[DEBUG] 2014-03-25 16:29:50.011
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 11740
[DEBUG] 2014-03-25 16:29:50.023 (StreamTester.java:run:68) Total events:
36000
[DEBUG] 2014-03-25 16:29:52.998 (StreamTester.java:run:68) Total events:
37000
[DEBUG] 2014-03-25 16:29:55.925 (StreamTester.java:run:68) Total events:
38000
[DEBUG] 2014-03-25 16:29:58.845 (StreamTester.java:run:68) Total events:
39000
[DEBUG] 2014-03-25 16:30:00.009
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 8417
[DEBUG] 2014-03-25 16:30:00.038
(Rule_Count_meta1429890510.java:defaultConsequence:14) two = 2606
[DEBUG] 2014-03-25 16:30:00.039
(Rule_Count_meta1429890510.java:defaultConsequence:14) eight = 2534
[DEBUG] 2014-03-25 16:30:00.039
(Rule_Count_meta1429890510.java:defaultConsequence:14) ten = 2763
[DEBUG] 2014-03-25 16:30:00.040
(Rule_Count_meta1429890510.java:defaultConsequence:14) three = 2623
[DEBUG] 2014-03-25 16:30:00.040
(Rule_Count_meta1429890510.java:defaultConsequence:14) six = 2641
[DEBUG] 2014-03-25 16:30:00.040
(Rule_Count_meta1429890510.java:defaultConsequence:14) five = 2579
[DEBUG] 2014-03-25 16:30:00.040
(Rule_Count_meta1429890510.java:defaultConsequence:14) one = 2690
[DEBUG] 2014-03-25 16:30:00.041
(Rule_Count_meta1429890510.java:defaultConsequence:14) seven = 2698
[DEBUG] 2014-03-25 16:30:00.041
(Rule_Count_meta1429890510.java:defaultConsequence:14) four = 2658
[DEBUG] 2014-03-25 16:30:00.041
(Rule_Count_meta1429890510.java:defaultConsequence:14) nine = 2669
[DEBUG] 2014-03-25 16:30:01.735 (StreamTester.java:run:68) Total events:
40000
[DEBUG] 2014-03-25 16:30:04.682 (StreamTester.java:run:68) Total events:
41000
[DEBUG] 2014-03-25 16:30:07.604 (StreamTester.java:run:68) Total events:
42000
[DEBUG] 2014-03-25 16:30:10.011
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 5266
[DEBUG] 2014-03-25 16:30:10.622 (StreamTester.java:run:68) Total events:
43000
[DEBUG] 2014-03-25 16:30:13.493 (StreamTester.java:run:68) Total events:
44000
[DEBUG] 2014-03-25 16:30:16.383 (StreamTester.java:run:68) Total events:
45000
[DEBUG] 2014-03-25 16:30:19.263 (StreamTester.java:run:68) Total events:
46000
[DEBUG] 2014-03-25 16:30:20.012
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 2078
[DEBUG] 2014-03-25 16:30:22.146 (StreamTester.java:run:68) Total events:
47000
[DEBUG] 2014-03-25 16:30:25.036 (StreamTester.java:run:68) Total events:
48000
[DEBUG] 2014-03-25 16:30:27.911 (StreamTester.java:run:68) Total events:
49000
[DEBUG] 2014-03-25 16:30:30.003
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 0
[DEBUG] 2014-03-25 16:30:30.800 (StreamTester.java:run:68) Total events:
50000
At 250 eps it took about 56K events (3'30") to hang (short log below)
[DEBUG] 2014-03-25 16:37:20.013
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 16084
[DEBUG] 2014-03-25 16:37:23.222 (StreamTester.java:run:68) Total events:
52000
[DEBUG] 2014-03-25 16:37:26.751 (StreamTester.java:run:68) Total events:
53000
[DEBUG] 2014-03-25 16:37:30.069
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 16085
[DEBUG] 2014-03-25 16:37:30.510 (StreamTester.java:run:68) Total events:
54000
[DEBUG] 2014-03-25 16:37:34.099 (StreamTester.java:run:68) Total events:
55000
[DEBUG] 2014-03-25 16:37:37.701 (StreamTester.java:run:68) Total events:
56000
*[DEBUG] 2014-03-25 16:37:40.014
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 15381*
[DEBUG] 2014-03-25 16:37:41.381 (StreamTester.java:run:68) Total events:
57000
[DEBUG] 2014-03-25 16:37:44.977 (StreamTester.java:run:68) Total events:
58000
[DEBUG] 2014-03-25 16:37:48.632 (StreamTester.java:run:68) Total events:
59000
[DEBUG] 2014-03-25 16:37:50.011
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 12677
[DEBUG] 2014-03-25 16:37:52.343 (StreamTester.java:run:68) Total events:
60000
[DEBUG] 2014-03-25 16:37:55.958 (StreamTester.java:run:68) Total events:
61000
[DEBUG] 2014-03-25 16:37:59.546 (StreamTester.java:run:68) Total events:
62000
[DEBUG] 2014-03-25 16:38:00.009
(Rule_Count_epm701941061.java:defaultConsequence:14) epm = 10033
At 200 eps the system hanged after 185K events (more than 16 minutes).
More realish examples (e.g. counting how many distinct tweets get at least
one retweet [*far less than 10%, BTW*]) hang in less than 10 minutes even
at 20 events per second or less.
Hope this helps. Please guys, ask me for more details at any moment.
I would be definitely glad to solve this issue and to go on with our Drools
Fusion roadmap ;)
Thanks in advance,
Vieri
On 25 March 2014 14:09, Mario Fusco <mario.fusco(a)gmail.com> wrote:
Hi,
I am trying to reproduce the issue you reported, but so far I couldn't.
This
is drl I am using:
import org.drools.test.SynthEvent
import java.util.Date
declare SynthEvent
@role( event )
@timestamp( timestamp )
end
declare EventCounter
@role( event )
@timestamp( timestamp )
id : long
key : String
timestamp : Date
end
declare CronTrigger end
rule "Trigger Metric"
timer ( cron: 0/10 * * * * ? )\n
when
then
entryPoints["triggers"].insert( new CronTrigger() );
end
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert(new EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
end
rule "Count epm"
when
$trigger : CronTrigger() from entry-point "triggers"
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s
)from entry-point
"counters", count(1) )
then
System.out.println("[" + new Date() + "] epm = " + $count
);
retract($trigger);
end
and this is how I am using it:
final KieSession ksession = kbase.newKieSession();
EntryPoint synthEP = ksession.getEntryPoint("synth");
new Thread(){
public void run() {
ksession.fireUntilHalt();
};
}.start();
long counter = 0;
while(true) {
counter++;
synthEP.insert(new SynthEvent(counter));
try {
Thread.sleep(20L);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
if ((counter % 1000) == 0) {
System.out.println("Total events: " + counter);
}
}
Note that since you mentioned you expected around 3K events per minute I am
doing a sleep of 20 msec between the insertion of 2 consecutive events. Is
that correct?
I let this run for 10 minutes and I got the output I am pasting at the end
of this email, so I think that it is working as expected. Please let me
know
if you'll give a try at my test case and if it works correctly also for
you.
Also if you find any further problem feel free to send a reproducer so I
could give it a try.
Regards,
Mario
[Tue Mar 25 13:37:30 CET 2014] epm = 318
[Tue Mar 25 13:37:40 CET 2014] epm = 774
Total events: 1000
[Tue Mar 25 13:37:50 CET 2014] epm = 1259
[Tue Mar 25 13:38:00 CET 2014] epm = 1746
Total events: 2000
[Tue Mar 25 13:38:10 CET 2014] epm = 2233
[Tue Mar 25 13:38:20 CET 2014] epm = 2720
Total events: 3000
[Tue Mar 25 13:38:30 CET 2014] epm = 2890
[Tue Mar 25 13:38:40 CET 2014] epm = 2922
Total events: 4000
[Tue Mar 25 13:38:50 CET 2014] epm = 2926
[Tue Mar 25 13:39:00 CET 2014] epm = 2929
Total events: 5000
[Tue Mar 25 13:39:10 CET 2014] epm = 2933
[Tue Mar 25 13:39:20 CET 2014] epm = 2938
Total events: 6000
[Tue Mar 25 13:39:30 CET 2014] epm = 2944
[Tue Mar 25 13:39:40 CET 2014] epm = 2948
Total events: 7000
[Tue Mar 25 13:39:50 CET 2014] epm = 2952
[Tue Mar 25 13:40:00 CET 2014] epm = 2956
Total events: 8000
[Tue Mar 25 13:40:10 CET 2014] epm = 2958
[Tue Mar 25 13:40:20 CET 2014] epm = 2959
Total events: 9000
[Tue Mar 25 13:40:30 CET 2014] epm = 2959
[Tue Mar 25 13:40:40 CET 2014] epm = 2960
Total events: 10000
[Tue Mar 25 13:40:50 CET 2014] epm = 2960
[Tue Mar 25 13:41:00 CET 2014] epm = 2960
Total events: 11000
[Tue Mar 25 13:41:10 CET 2014] epm = 2961
[Tue Mar 25 13:41:20 CET 2014] epm = 2963
Total events: 12000
[Tue Mar 25 13:41:30 CET 2014] epm = 2964
[Tue Mar 25 13:41:40 CET 2014] epm = 2964
Total events: 13000
[Tue Mar 25 13:41:50 CET 2014] epm = 2966
[Tue Mar 25 13:42:00 CET 2014] epm = 2966
Total events: 14000
[Tue Mar 25 13:42:10 CET 2014] epm = 2967
[Tue Mar 25 13:42:20 CET 2014] epm = 2964
Total events: 15000
[Tue Mar 25 13:42:30 CET 2014] epm = 2965
[Tue Mar 25 13:42:40 CET 2014] epm = 2966
Total events: 16000
[Tue Mar 25 13:42:50 CET 2014] epm = 2965
[Tue Mar 25 13:43:00 CET 2014] epm = 2967
Total events: 17000
[Tue Mar 25 13:43:10 CET 2014] epm = 2966
[Tue Mar 25 13:43:20 CET 2014] epm = 2969
Total events: 18000
[Tue Mar 25 13:43:30 CET 2014] epm = 2969
[Tue Mar 25 13:43:40 CET 2014] epm = 2969
[Tue Mar 25 13:43:50 CET 2014] epm = 2970
Total events: 19000
[Tue Mar 25 13:44:00 CET 2014] epm = 2969
[Tue Mar 25 13:44:10 CET 2014] epm = 2970
Total events: 20000
[Tue Mar 25 13:44:20 CET 2014] epm = 2969
[Tue Mar 25 13:44:30 CET 2014] epm = 2969
Total events: 21000
[Tue Mar 25 13:44:40 CET 2014] epm = 2969
[Tue Mar 25 13:44:50 CET 2014] epm = 2969
Total events: 22000
[Tue Mar 25 13:45:00 CET 2014] epm = 2969
[Tue Mar 25 13:45:10 CET 2014] epm = 2969
Total events: 23000
[Tue Mar 25 13:45:20 CET 2014] epm = 2969
[Tue Mar 25 13:45:30 CET 2014] epm = 2968
Total events: 24000
[Tue Mar 25 13:45:40 CET 2014] epm = 2969
[Tue Mar 25 13:45:50 CET 2014] epm = 2969
Total events: 25000
[Tue Mar 25 13:46:00 CET 2014] epm = 2969
[Tue Mar 25 13:46:10 CET 2014] epm = 2969
Total events: 26000
[Tue Mar 25 13:46:20 CET 2014] epm = 2968
[Tue Mar 25 13:46:30 CET 2014] epm = 2969
Total events: 27000
[Tue Mar 25 13:46:40 CET 2014] epm = 2968
[Tue Mar 25 13:46:50 CET 2014] epm = 2969
Total events: 28000
[Tue Mar 25 13:47:00 CET 2014] epm = 2969
[Tue Mar 25 13:47:10 CET 2014] epm = 2969
Total events: 29000
[Tue Mar 25 13:47:20 CET 2014] epm = 2969
--
View this message in context:
http://drools.46999.n3.nabble.com/rules-users-Drools-Fusion-inconsistenci...
Sent from the Drools: User forum mailing list archive at Nabble.com.
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
--
Vieri Emiliani
vieri.emiliani(a)gmail.com
+39 335 1293649
10:57 a.m.
we’ve being auditing the code here, and we’ve found an issue on what happens when a rule
is re-matched and the timer updated. Mario is addressing this now, and also re-viewing
dropping of output. He’ll post with an update soon.
Mark
On 25 Mar 2014, at 16:09, Vieri <vieri.emiliani(a)gmail.com> wrote:
First of all, thanks for the support.
Mario, I confirm that the case you provided works fine also at my side. Still, have you
tried my first example (using the cron directly to the counting rule)? Can you confirm it
is not working, since this was my first concern?
As I said in the previous post, using the CronTrigger pattern greatly improves stability
(I managed to run it at 500 eps), but it is not resolutive.
Adding a few rules, it's enough to go back to instability.
Here's the complete test case.
Basically, a SynthEvent is created with the meta list populated randomly with up to 4
values picked from a list of 10 strings ("one" to "ten").
For each meta value an Entity object is created (for enumeration purposes).
Then, rules generate metrics for both events (every 10s) and meta (every 60s).
Test is ran at 300 events per second +/- 20% (our real use case is closer to some
hundreds events per second than some tens).
First of all, the full SynthEvent class:
package it.intext.unity.test;
import java.util.Arrays;
import java.util.Date;
import java.util.List;
public class SynthEvent {
long id;
Date timestamp;
List<String> meta;
public long getId() {
return id;
}
public void setId(long id) {
this.id = id;
}
public Date getTimestamp() {
return timestamp;
}
public void setTimestamp(Date timestamp) {
this.timestamp = timestamp;
}
public List<String> getMeta() {
return meta;
}
public void setMeta(List<String> meta) {
this.meta = meta;
}
public SynthEvent() {
super();
}
@Override
public String toString() {
StringBuilder builder = new StringBuilder();
builder.append("SynthEvent [id=");
builder.append(id);
builder.append(", timestamp=");
builder.append(timestamp);
builder.append(", meta=");
builder.append(meta);
builder.append("]");
return builder.toString();
}
public String toString() {
StringBuilder builder = new StringBuilder();
builder.append("SynthEvent [id=");
builder.append(id);
builder.append(", timestamp=");
builder.append(timestamp);
builder.append(", meta=");
builder.append(meta);
builder.append("]");
return builder.toString();
}
}
Here's the feeding part of the test class:
private void process(final KieSession session) {
new Thread(){
public void run() {
session.fireUntilHalt();
};
}.start();
}
private void feed(final KieSession session) {
new Thread(){
public void run() {
try {
int counter = 0;
while(true) {
counter++;
session.getEntryPoint("synth").insert(createEvent());
Thread.sleep(getSleepRate());
if ((counter % 1000) == 0) {
logger.debug("Total events: {}", counter);
}
}
} catch (InterruptedException e) {
logger.warn("{}", e);
}
};
}.start();
}
static final int eventThroughput = 300;
static final double variance = 0.2;
protected long getSleepRate() {
return (long) (1000.0 / (eventThroughput * ((1.0 - variance) + Math.random() * variance
* 2)));
}
protected SynthEvent createEvent() {
SynthEvent ret = new SynthEvent();
ret.setId(System.currentTimeMillis());
ret.setTimestamp(new Date());
ret.setMeta(createMeta());
return ret;
}
static final List<String> metas = Arrays.asList("one", "two",
"three", "four", "five", "six", "seven",
"eight", "nine", "ten");
static final int maxMeta = 4;
static final int metaSize = metas.size();
protected List<String> createMeta() {
List<String> ret = new ArrayList<String>();
int nofItems = (int) (Math.random() * maxMeta);
for (int i=0; i<nofItems; i++) {
ret.add(metas.get((int) (Math.random() * metaSize)));
}
return ret;
}
And here's the drl, using the CronTrigger pattern:
package it.intext.unity.test
import it.intext.unity.test.SynthEvent;
import java.util.Date;
global org.slf4j.Logger logger;
declare SynthEvent
@role( event )
@timestamp( timestamp )
end
declare EventCounter
@role( event )
@timestamp( timestamp )
id : long
key : String
timestamp : Date
end
declare CronTrigger
@role( event )
@timestamp( timestamp )
interval : String
timestamp : Date
end
declare MetricRequest
metric : String
end
declare Subscription
key : String
interval : String
end
declare Entity
key : String
end
// Setup rules
rule "Create subscriptions"
when
then
insert( new Subscription("epm", "10s") );
end
rule "Create meta subscriptions 60s"
when
Entity( $key : key )
then
insert( new Subscription($key, "60s") );
end
// Cron management
rule "Cron trigger 10s"
timer ( cron: 0/10 * * * * ? )
when
then
entryPoints["triggers"].insert( new CronTrigger( "10s", new Date()
) );
end
rule "Cron trigger 60s"
timer ( cron: 0/60 * * * * ? )
when
then
entryPoints["triggers"].insert( new CronTrigger( "60s", new Date()
) );
end
rule "Subscription"
when
CronTrigger( $interval := interval ) from entry-point "triggers"
Subscription( $interval := interval, $key : key )
then
entryPoints["requests"].insert( new MetricRequest($key) );
end
// Business rules
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert( new EventCounter( $e.getId(),
"event", $e.getTimestamp() ) );
end
rule "Create meta counter"
when
$e : SynthEvent() from entry-point "synth"
$meta : String( ) from $e.getMeta()
then
entryPoints["counters"].insert( new EventCounter( $e.getId(), $meta,
$e.getTimestamp() ) );
end
rule "Create meta"
when
$e : SynthEvent() from entry-point "synth"
$meta : String( ) from $e.getMeta()
not( Entity( key == $meta ) )
then
insert( new Entity($meta) );
end
rule "Count epm"
when
$req : MetricRequest( metric == "epm" ) from entry-point
"requests"
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s ) from
entry-point "counters", count(1) )
then
logger.debug("epm = {}", $count );
retract( $req );
end
rule "Count meta"
when
$req : MetricRequest( $key := metric ) from entry-point "requests"
Number( $count : intValue ) from accumulate(
EventCounter( $key := key ) over window:time( 60s ) from entry-point
"counters", count(1) )
then
logger.debug("{} = {}", $key, $count );
retract( $req );
end
Here's the log of a quick-failing run:
[DEBUG] 2014-03-25 16:28:04.769 (StreamTester.java:run:68) Total events: 1000
[DEBUG] 2014-03-25 16:28:07.774 (StreamTester.java:run:68) Total events: 2000
[DEBUG] 2014-03-25 16:28:10.100 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 2769
[DEBUG] 2014-03-25 16:28:10.723 (StreamTester.java:run:68) Total events: 3000
[DEBUG] 2014-03-25 16:28:13.681 (StreamTester.java:run:68) Total events: 4000
[DEBUG] 2014-03-25 16:28:16.668 (StreamTester.java:run:68) Total events: 5000
[DEBUG] 2014-03-25 16:28:19.541 (StreamTester.java:run:68) Total events: 6000
[DEBUG] 2014-03-25 16:28:20.054 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 6164
[DEBUG] 2014-03-25 16:28:22.421 (StreamTester.java:run:68) Total events: 7000
[DEBUG] 2014-03-25 16:28:25.336 (StreamTester.java:run:68) Total events: 8000
[DEBUG] 2014-03-25 16:28:28.217 (StreamTester.java:run:68) Total events: 9000
[DEBUG] 2014-03-25 16:28:30.030 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 9627
[DEBUG] 2014-03-25 16:28:31.088 (StreamTester.java:run:68) Total events: 10000
[DEBUG] 2014-03-25 16:28:33.968 (StreamTester.java:run:68) Total events: 11000
[DEBUG] 2014-03-25 16:28:36.904 (StreamTester.java:run:68) Total events: 12000
[DEBUG] 2014-03-25 16:28:39.782 (StreamTester.java:run:68) Total events: 13000
[DEBUG] 2014-03-25 16:28:40.024 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 13077
[DEBUG] 2014-03-25 16:28:42.736 (StreamTester.java:run:68) Total events: 14000
[DEBUG] 2014-03-25 16:28:45.615 (StreamTester.java:run:68) Total events: 15000
[DEBUG] 2014-03-25 16:28:48.459 (StreamTester.java:run:68) Total events: 16000
[DEBUG] 2014-03-25 16:28:50.030 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 16538
[DEBUG] 2014-03-25 16:28:51.412 (StreamTester.java:run:68) Total events: 17000
[DEBUG] 2014-03-25 16:28:54.293 (StreamTester.java:run:68) Total events: 18000
[DEBUG] 2014-03-25 16:28:57.549 (StreamTester.java:run:68) Total events: 19000
[DEBUG] 2014-03-25 16:29:00.021 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 19860
[DEBUG] 2014-03-25 16:29:00.211 (Rule_Count_meta1429890510.java:defaultConsequence:14)
two = 2972
[DEBUG] 2014-03-25 16:29:00.214 (Rule_Count_meta1429890510.java:defaultConsequence:14)
eight = 3099
[DEBUG] 2014-03-25 16:29:00.215 (Rule_Count_meta1429890510.java:defaultConsequence:14)
ten = 3008
[DEBUG] 2014-03-25 16:29:00.215 (Rule_Count_meta1429890510.java:defaultConsequence:14)
three = 2982
[DEBUG] 2014-03-25 16:29:00.216 (Rule_Count_meta1429890510.java:defaultConsequence:14)
six = 3006
[DEBUG] 2014-03-25 16:29:00.216 (Rule_Count_meta1429890510.java:defaultConsequence:14)
five = 2959
[DEBUG] 2014-03-25 16:29:00.217 (Rule_Count_meta1429890510.java:defaultConsequence:14)
one = 2934
[DEBUG] 2014-03-25 16:29:00.217 (Rule_Count_meta1429890510.java:defaultConsequence:14)
seven = 3013
[DEBUG] 2014-03-25 16:29:00.218 (Rule_Count_meta1429890510.java:defaultConsequence:14)
four = 2973
[DEBUG] 2014-03-25 16:29:00.218 (Rule_Count_meta1429890510.java:defaultConsequence:14)
nine = 3012
[DEBUG] 2014-03-25 16:29:00.510 (StreamTester.java:run:68) Total events: 20000
[DEBUG] 2014-03-25 16:29:03.671 (StreamTester.java:run:68) Total events: 21000
[DEBUG] 2014-03-25 16:29:06.798 (StreamTester.java:run:68) Total events: 22000
[DEBUG] 2014-03-25 16:29:09.969 (StreamTester.java:run:68) Total events: 23000
[DEBUG] 2014-03-25 16:29:10.045 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 20242
[DEBUG] 2014-03-25 16:29:13.362 (StreamTester.java:run:68) Total events: 24000
[DEBUG] 2014-03-25 16:29:16.352 (StreamTester.java:run:68) Total events: 25000
[DEBUG] 2014-03-25 16:29:19.400 (StreamTester.java:run:68) Total events: 26000
[DEBUG] 2014-03-25 16:29:20.849 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 20029
[DEBUG] 2014-03-25 16:29:22.795 (StreamTester.java:run:68) Total events: 27000
[DEBUG] 2014-03-25 16:29:25.785 (StreamTester.java:run:68) Total events: 28000
[DEBUG] 2014-03-25 16:29:28.855 (StreamTester.java:run:68) Total events: 29000
[DEBUG] 2014-03-25 16:29:30.018 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 18647
[DEBUG] 2014-03-25 16:29:31.858 (StreamTester.java:run:68) Total events: 30000
[DEBUG] 2014-03-25 16:29:34.983 (StreamTester.java:run:68) Total events: 31000
[DEBUG] 2014-03-25 16:29:37.947 (StreamTester.java:run:68) Total events: 32000
[DEBUG] 2014-03-25 16:29:40.011 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 15201
[DEBUG] 2014-03-25 16:29:40.928 (StreamTester.java:run:68) Total events: 33000
[DEBUG] 2014-03-25 16:29:43.920 (StreamTester.java:run:68) Total events: 34000
[DEBUG] 2014-03-25 16:29:46.911 (StreamTester.java:run:68) Total events: 35000
[DEBUG] 2014-03-25 16:29:50.011 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 11740
[DEBUG] 2014-03-25 16:29:50.023 (StreamTester.java:run:68) Total events: 36000
[DEBUG] 2014-03-25 16:29:52.998 (StreamTester.java:run:68) Total events: 37000
[DEBUG] 2014-03-25 16:29:55.925 (StreamTester.java:run:68) Total events: 38000
[DEBUG] 2014-03-25 16:29:58.845 (StreamTester.java:run:68) Total events: 39000
[DEBUG] 2014-03-25 16:30:00.009 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 8417
[DEBUG] 2014-03-25 16:30:00.038 (Rule_Count_meta1429890510.java:defaultConsequence:14)
two = 2606
[DEBUG] 2014-03-25 16:30:00.039 (Rule_Count_meta1429890510.java:defaultConsequence:14)
eight = 2534
[DEBUG] 2014-03-25 16:30:00.039 (Rule_Count_meta1429890510.java:defaultConsequence:14)
ten = 2763
[DEBUG] 2014-03-25 16:30:00.040 (Rule_Count_meta1429890510.java:defaultConsequence:14)
three = 2623
[DEBUG] 2014-03-25 16:30:00.040 (Rule_Count_meta1429890510.java:defaultConsequence:14)
six = 2641
[DEBUG] 2014-03-25 16:30:00.040 (Rule_Count_meta1429890510.java:defaultConsequence:14)
five = 2579
[DEBUG] 2014-03-25 16:30:00.040 (Rule_Count_meta1429890510.java:defaultConsequence:14)
one = 2690
[DEBUG] 2014-03-25 16:30:00.041 (Rule_Count_meta1429890510.java:defaultConsequence:14)
seven = 2698
[DEBUG] 2014-03-25 16:30:00.041 (Rule_Count_meta1429890510.java:defaultConsequence:14)
four = 2658
[DEBUG] 2014-03-25 16:30:00.041 (Rule_Count_meta1429890510.java:defaultConsequence:14)
nine = 2669
[DEBUG] 2014-03-25 16:30:01.735 (StreamTester.java:run:68) Total events: 40000
[DEBUG] 2014-03-25 16:30:04.682 (StreamTester.java:run:68) Total events: 41000
[DEBUG] 2014-03-25 16:30:07.604 (StreamTester.java:run:68) Total events: 42000
[DEBUG] 2014-03-25 16:30:10.011 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 5266
[DEBUG] 2014-03-25 16:30:10.622 (StreamTester.java:run:68) Total events: 43000
[DEBUG] 2014-03-25 16:30:13.493 (StreamTester.java:run:68) Total events: 44000
[DEBUG] 2014-03-25 16:30:16.383 (StreamTester.java:run:68) Total events: 45000
[DEBUG] 2014-03-25 16:30:19.263 (StreamTester.java:run:68) Total events: 46000
[DEBUG] 2014-03-25 16:30:20.012 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 2078
[DEBUG] 2014-03-25 16:30:22.146 (StreamTester.java:run:68) Total events: 47000
[DEBUG] 2014-03-25 16:30:25.036 (StreamTester.java:run:68) Total events: 48000
[DEBUG] 2014-03-25 16:30:27.911 (StreamTester.java:run:68) Total events: 49000
[DEBUG] 2014-03-25 16:30:30.003 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 0
[DEBUG] 2014-03-25 16:30:30.800 (StreamTester.java:run:68) Total events: 50000
At 250 eps it took about 56K events (3'30") to hang (short log below)
[DEBUG] 2014-03-25 16:37:20.013 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 16084
[DEBUG] 2014-03-25 16:37:23.222 (StreamTester.java:run:68) Total events: 52000
[DEBUG] 2014-03-25 16:37:26.751 (StreamTester.java:run:68) Total events: 53000
[DEBUG] 2014-03-25 16:37:30.069 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 16085
[DEBUG] 2014-03-25 16:37:30.510 (StreamTester.java:run:68) Total events: 54000
[DEBUG] 2014-03-25 16:37:34.099 (StreamTester.java:run:68) Total events: 55000
[DEBUG] 2014-03-25 16:37:37.701 (StreamTester.java:run:68) Total events: 56000
[DEBUG] 2014-03-25 16:37:40.014 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 15381
[DEBUG] 2014-03-25 16:37:41.381 (StreamTester.java:run:68) Total events: 57000
[DEBUG] 2014-03-25 16:37:44.977 (StreamTester.java:run:68) Total events: 58000
[DEBUG] 2014-03-25 16:37:48.632 (StreamTester.java:run:68) Total events: 59000
[DEBUG] 2014-03-25 16:37:50.011 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 12677
[DEBUG] 2014-03-25 16:37:52.343 (StreamTester.java:run:68) Total events: 60000
[DEBUG] 2014-03-25 16:37:55.958 (StreamTester.java:run:68) Total events: 61000
[DEBUG] 2014-03-25 16:37:59.546 (StreamTester.java:run:68) Total events: 62000
[DEBUG] 2014-03-25 16:38:00.009 (Rule_Count_epm701941061.java:defaultConsequence:14) epm
= 10033
At 200 eps the system hanged after 185K events (more than 16 minutes).
More realish examples (e.g. counting how many distinct tweets get at least one retweet
[far less than 10%, BTW]) hang in less than 10 minutes even at 20 events per second or
less.
Hope this helps. Please guys, ask me for more details at any moment.
I would be definitely glad to solve this issue and to go on with our Drools Fusion
roadmap ;)
Thanks in advance,
Vieri
On 25 March 2014 14:09, Mario Fusco <mario.fusco(a)gmail.com> wrote:
Hi,
I am trying to reproduce the issue you reported, but so far I couldn't. This
is drl I am using:
import org.drools.test.SynthEvent
import java.util.Date
declare SynthEvent
@role( event )
@timestamp( timestamp )
end
declare EventCounter
@role( event )
@timestamp( timestamp )
id : long
key : String
timestamp : Date
end
declare CronTrigger end
rule "Trigger Metric"
timer ( cron: 0/10 * * * * ? )\n
when
then
entryPoints["triggers"].insert( new CronTrigger() );
end
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert(new EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
end
rule "Count epm"
when
$trigger : CronTrigger() from entry-point "triggers"
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s )from
entry-point
"counters", count(1) )
then
System.out.println("[" + new Date() + "] epm = " + $count
);
retract($trigger);
end
and this is how I am using it:
final KieSession ksession = kbase.newKieSession();
EntryPoint synthEP = ksession.getEntryPoint("synth");
new Thread(){
public void run() {
ksession.fireUntilHalt();
};
}.start();
long counter = 0;
while(true) {
counter++;
synthEP.insert(new SynthEvent(counter));
try {
Thread.sleep(20L);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
if ((counter % 1000) == 0) {
System.out.println("Total events: " + counter);
}
}
Note that since you mentioned you expected around 3K events per minute I am
doing a sleep of 20 msec between the insertion of 2 consecutive events. Is
that correct?
I let this run for 10 minutes and I got the output I am pasting at the end
of this email, so I think that it is working as expected. Please let me know
if you'll give a try at my test case and if it works correctly also for you.
Also if you find any further problem feel free to send a reproducer so I
could give it a try.
Regards,
Mario
[Tue Mar 25 13:37:30 CET 2014] epm = 318
[Tue Mar 25 13:37:40 CET 2014] epm = 774
Total events: 1000
[Tue Mar 25 13:37:50 CET 2014] epm = 1259
[Tue Mar 25 13:38:00 CET 2014] epm = 1746
Total events: 2000
[Tue Mar 25 13:38:10 CET 2014] epm = 2233
[Tue Mar 25 13:38:20 CET 2014] epm = 2720
Total events: 3000
[Tue Mar 25 13:38:30 CET 2014] epm = 2890
[Tue Mar 25 13:38:40 CET 2014] epm = 2922
Total events: 4000
[Tue Mar 25 13:38:50 CET 2014] epm = 2926
[Tue Mar 25 13:39:00 CET 2014] epm = 2929
Total events: 5000
[Tue Mar 25 13:39:10 CET 2014] epm = 2933
[Tue Mar 25 13:39:20 CET 2014] epm = 2938
Total events: 6000
[Tue Mar 25 13:39:30 CET 2014] epm = 2944
[Tue Mar 25 13:39:40 CET 2014] epm = 2948
Total events: 7000
[Tue Mar 25 13:39:50 CET 2014] epm = 2952
[Tue Mar 25 13:40:00 CET 2014] epm = 2956
Total events: 8000
[Tue Mar 25 13:40:10 CET 2014] epm = 2958
[Tue Mar 25 13:40:20 CET 2014] epm = 2959
Total events: 9000
[Tue Mar 25 13:40:30 CET 2014] epm = 2959
[Tue Mar 25 13:40:40 CET 2014] epm = 2960
Total events: 10000
[Tue Mar 25 13:40:50 CET 2014] epm = 2960
[Tue Mar 25 13:41:00 CET 2014] epm = 2960
Total events: 11000
[Tue Mar 25 13:41:10 CET 2014] epm = 2961
[Tue Mar 25 13:41:20 CET 2014] epm = 2963
Total events: 12000
[Tue Mar 25 13:41:30 CET 2014] epm = 2964
[Tue Mar 25 13:41:40 CET 2014] epm = 2964
Total events: 13000
[Tue Mar 25 13:41:50 CET 2014] epm = 2966
[Tue Mar 25 13:42:00 CET 2014] epm = 2966
Total events: 14000
[Tue Mar 25 13:42:10 CET 2014] epm = 2967
[Tue Mar 25 13:42:20 CET 2014] epm = 2964
Total events: 15000
[Tue Mar 25 13:42:30 CET 2014] epm = 2965
[Tue Mar 25 13:42:40 CET 2014] epm = 2966
Total events: 16000
[Tue Mar 25 13:42:50 CET 2014] epm = 2965
[Tue Mar 25 13:43:00 CET 2014] epm = 2967
Total events: 17000
[Tue Mar 25 13:43:10 CET 2014] epm = 2966
[Tue Mar 25 13:43:20 CET 2014] epm = 2969
Total events: 18000
[Tue Mar 25 13:43:30 CET 2014] epm = 2969
[Tue Mar 25 13:43:40 CET 2014] epm = 2969
[Tue Mar 25 13:43:50 CET 2014] epm = 2970
Total events: 19000
[Tue Mar 25 13:44:00 CET 2014] epm = 2969
[Tue Mar 25 13:44:10 CET 2014] epm = 2970
Total events: 20000
[Tue Mar 25 13:44:20 CET 2014] epm = 2969
[Tue Mar 25 13:44:30 CET 2014] epm = 2969
Total events: 21000
[Tue Mar 25 13:44:40 CET 2014] epm = 2969
[Tue Mar 25 13:44:50 CET 2014] epm = 2969
Total events: 22000
[Tue Mar 25 13:45:00 CET 2014] epm = 2969
[Tue Mar 25 13:45:10 CET 2014] epm = 2969
Total events: 23000
[Tue Mar 25 13:45:20 CET 2014] epm = 2969
[Tue Mar 25 13:45:30 CET 2014] epm = 2968
Total events: 24000
[Tue Mar 25 13:45:40 CET 2014] epm = 2969
[Tue Mar 25 13:45:50 CET 2014] epm = 2969
Total events: 25000
[Tue Mar 25 13:46:00 CET 2014] epm = 2969
[Tue Mar 25 13:46:10 CET 2014] epm = 2969
Total events: 26000
[Tue Mar 25 13:46:20 CET 2014] epm = 2968
[Tue Mar 25 13:46:30 CET 2014] epm = 2969
Total events: 27000
[Tue Mar 25 13:46:40 CET 2014] epm = 2968
[Tue Mar 25 13:46:50 CET 2014] epm = 2969
Total events: 28000
[Tue Mar 25 13:47:00 CET 2014] epm = 2969
[Tue Mar 25 13:47:10 CET 2014] epm = 2969
Total events: 29000
[Tue Mar 25 13:47:20 CET 2014] epm = 2969
--
View this message in context:
http://drools.46999.n3.nabble.com/rules-users-Drools-Fusion-inconsistenci...
Sent from the Drools: User forum mailing list archive at Nabble.com.
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
--
Vieri Emiliani
vieri.emiliani(a)gmail.com
+39 335 1293649
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
4 a.m.
Mark,
thanks for your update.
I don't know if this can help, but I added a simple AgendaEventListener to
the test case and it seems that at some point drools stops matching the
"Create event" rule, while facts (well, events) are still inserted and
other rules are triggered properly.
Vieri
On 28 March 2014 16:57, Mark Proctor <mproctor(a)codehaus.org> wrote:
we've being auditing the code here, and we've found an issue
on what
happens when a rule is re-matched and the timer updated. Mario is
addressing this now, and also re-viewing dropping of output. He'll post
with an update soon.
Mark
On 25 Mar 2014, at 16:09, Vieri <vieri.emiliani(a)gmail.com> wrote:
First of all, thanks for the support.
Mario, I confirm that the case you provided works fine also at my side.
Still, have you tried my first example (using the cron directly to the
counting rule)? Can you confirm it is not working, since this was my first
concern?
As I said in the previous post, using the CronTrigger pattern greatly
improves stability (I managed to run it at 500 eps), but it is not
resolutive.
Adding a few rules, it's enough to go back to instability.
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
--
Vieri Emiliani
7:50 a.m.
Mario has found an issue at a sync point, which can happen if it’s trying to schedule a
timer at the same time that it’s firing that same timer from an update. We are trying to
resolve that now. See lines 121 and 394, which later impacts lines 289 and 330.
https://github.com/droolsjbpm/drools/blob/master/drools-core/src/main/jav...
Once we have this solved, we should have expected behaviour. Hopefully you can try this in
the next 6.1 beta, in 2 weeks time.
Mark
On 29 Mar 2014, at 09:00, Vieri <vieri.emiliani(a)gmail.com> wrote:
Mark,
thanks for your update.
I don't know if this can help, but I added a simple AgendaEventListener to the test
case and it seems that at some point drools stops matching the "Create event"
rule, while facts (well, events) are still inserted and other rules are triggered
properly.
Vieri
On 28 March 2014 16:57, Mark Proctor <mproctor(a)codehaus.org> wrote:
we’ve being auditing the code here, and we’ve found an issue on what happens when a rule
is re-matched and the timer updated. Mario is addressing this now, and also re-viewing
dropping of output. He’ll post with an update soon.
Mark
On 25 Mar 2014, at 16:09, Vieri <vieri.emiliani(a)gmail.com> wrote:
> First of all, thanks for the support.
> Mario, I confirm that the case you provided works fine also at my side. Still, have
you tried my first example (using the cron directly to the counting rule)? Can you confirm
it is not working, since this was my first concern?
> As I said in the previous post, using the CronTrigger pattern greatly improves
stability (I managed to run it at 500 eps), but it is not resolutive.
> Adding a few rules, it's enough to go back to instability.
>
>
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
--
Vieri Emiliani
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
8:34 a.m.
We are still working on this, we’ve found a number of related points, as we are doing a
full audit of the code. We’ll post as soon as we have the fixes available in a nightly
build, so that people can test.
Mark
On 29 Mar 2014, at 12:50, Mark Proctor <mproctor(a)codehaus.org> wrote:
Mario has found an issue at a sync point, which can happen if it’s
trying to schedule a timer at the same time that it’s firing that same timer from an
update. We are trying to resolve that now. See lines 121 and 394, which later impacts
lines 289 and 330.
https://github.com/droolsjbpm/drools/blob/master/drools-core/src/main/jav...
Once we have this solved, we should have expected behaviour. Hopefully you can try this
in the next 6.1 beta, in 2 weeks time.
Mark
On 29 Mar 2014, at 09:00, Vieri <vieri.emiliani(a)gmail.com> wrote:
> Mark,
> thanks for your update.
> I don't know if this can help, but I added a simple AgendaEventListener to the
test case and it seems that at some point drools stops matching the "Create
event" rule, while facts (well, events) are still inserted and other rules are
triggered properly.
> Vieri
>
>
>
> On 28 March 2014 16:57, Mark Proctor <mproctor(a)codehaus.org> wrote:
> we’ve being auditing the code here, and we’ve found an issue on what happens when a
rule is re-matched and the timer updated. Mario is addressing this now, and also
re-viewing dropping of output. He’ll post with an update soon.
>
> Mark
> On 25 Mar 2014, at 16:09, Vieri <vieri.emiliani(a)gmail.com> wrote:
>
>> First of all, thanks for the support.
>> Mario, I confirm that the case you provided works fine also at my side. Still,
have you tried my first example (using the cron directly to the counting rule)? Can you
confirm it is not working, since this was my first concern?
>> As I said in the previous post, using the CronTrigger pattern greatly improves
stability (I managed to run it at 500 eps), but it is not resolutive.
>> Adding a few rules, it's enough to go back to instability.
>>
>>
>
> _______________________________________________
> rules-users mailing list
> rules-users(a)lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/rules-users
>
>
>
> --
> Vieri Emiliani
> _______________________________________________
> rules-users mailing list
> rules-users(a)lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/rules-users
9:17 a.m.
We have this fixed now. Hopefully this will be in the nightly build, and available for
testing tomorrow. I’ll ping with a link to the nightly builds once it’s available.
Mark
On 31 Mar 2014, at 14:34, Mark Proctor <mproctor(a)codehaus.org> wrote:
We are still working on this, we’ve found a number of related points,
as we are doing a full audit of the code. We’ll post as soon as we have the fixes
available in a nightly build, so that people can test.
Mark
On 29 Mar 2014, at 12:50, Mark Proctor <mproctor(a)codehaus.org> wrote:
> Mario has found an issue at a sync point, which can happen if it’s trying to schedule
a timer at the same time that it’s firing that same timer from an update. We are trying to
resolve that now. See lines 121 and 394, which later impacts lines 289 and 330.
>
https://github.com/droolsjbpm/drools/blob/master/drools-core/src/main/jav...
>
> Once we have this solved, we should have expected behaviour. Hopefully you can try
this in the next 6.1 beta, in 2 weeks time.
>
> Mark
> On 29 Mar 2014, at 09:00, Vieri <vieri.emiliani(a)gmail.com> wrote:
>
>> Mark,
>> thanks for your update.
>> I don't know if this can help, but I added a simple AgendaEventListener to
the test case and it seems that at some point drools stops matching the "Create
event" rule, while facts (well, events) are still inserted and other rules are
triggered properly.
>> Vieri
>>
>>
>>
>> On 28 March 2014 16:57, Mark Proctor <mproctor(a)codehaus.org> wrote:
>> we’ve being auditing the code here, and we’ve found an issue on what happens when
a rule is re-matched and the timer updated. Mario is addressing this now, and also
re-viewing dropping of output. He’ll post with an update soon.
>>
>> Mark
>> On 25 Mar 2014, at 16:09, Vieri <vieri.emiliani(a)gmail.com> wrote:
>>
>>> First of all, thanks for the support.
>>> Mario, I confirm that the case you provided works fine also at my side.
Still, have you tried my first example (using the cron directly to the counting rule)? Can
you confirm it is not working, since this was my first concern?
>>> As I said in the previous post, using the CronTrigger pattern greatly
improves stability (I managed to run it at 500 eps), but it is not resolutive.
>>> Adding a few rules, it's enough to go back to instability.
>>>
>>>
>>
>> _______________________________________________
>> rules-users mailing list
>> rules-users(a)lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/rules-users
>>
>>
>>
>> --
>> Vieri Emiliani
>> _______________________________________________
>> rules-users mailing list
>> rules-users(a)lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/rules-users
>
9:22 a.m.
Hi again,
I reviewed all our events related code and I just pushed a commit (
https://github.com/droolsjbpm/drools/commit/f415b17cff696136fa83eb9e78376...
) that should fix all the issues you reported. The test cases you provided
have been really precious by the way. Thanks a lot for them.
Also note that, since I fixed the way our timed rules are scheduled, just
using a timer in the rule doing the accumulate as you did in your first
email now works as you expected. I tested it with both cron and interval
timers.
Thanks again for your help,
Mario
--
View this message in context:
http://drools.46999.n3.nabble.com/rules-users-Drools-Fusion-inconsistenci...
Sent from the Drools: User forum mailing list archive at Nabble.com.
3:55 p.m.
Mario,
I am glad the case we provided helped improving Drools.
We'll try to get our hands on your commit in the next days to confirm that
everything's fine.
And let me add that it's been a pleasure to get such a prompt feedback from
you guys,
I am longing to raise the next issue ;)
Thanks again,
Vieri
On 1 April 2014 16:22, Mario Fusco <mario.fusco(a)gmail.com> wrote:
Hi again,
I reviewed all our events related code and I just pushed a commit (
https://github.com/droolsjbpm/drools/commit/f415b17cff696136fa83eb9e78376...
) that should fix all the issues you reported. The test cases you provided
have been really precious by the way. Thanks a lot for them.
Also note that, since I fixed the way our timed rules are scheduled, just
using a timer in the rule doing the accumulate as you did in your first
email now works as you expected. I tested it with both cron and interval
timers.
Thanks again for your help,
Mario
--
View this message in context:
http://drools.46999.n3.nabble.com/rules-users-Drools-Fusion-inconsistenci...
Sent from the Drools: User forum mailing list archive at Nabble.com.
_______________________________________________
rules-users mailing list
rules-users(a)lists.jboss.org
https://lists.jboss.org/mailman/listinfo/rules-users
--
Vieri Emiliani
vieri.emiliani(a)gmail.com
7:33 a.m.
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(a)gmail.com
9:17 a.m.
Hi,
I am sorry but I am not sure I am understanding your last email. You wrote:
"Namely, when usic the basic pattern for counting (i.e. no CronTrigger),
from time to time the "cron triggered" rules won't trigger."
What do you mean with "no CronTrigger"? Can you paste test case you're
using
to reproduce this problem?
Thanks again,
Mario
--
View this message in context:
http://drools.46999.n3.nabble.com/rules-users-Drools-Fusion-inconsistenci...
Sent from the Drools: User forum mailing list archive at Nabble.com.
10:39 a.m.
Mario,
My fault. Here you are the drls:
*Not working *(log #1 in my last mail)
*[This is the drl I included in my first post to the list. The accumulate
occurs in the when clause of the cron based rule.]*
package it.intext.unity.test
import it.intext.unity.test.SynthEvent;
import java.util.Date;
global org.slf4j.Logger logger;
declare SynthEvent // The class is the same you used in previous tests
@role( event )
@timestamp( timestamp )
end
declare EventCounter
@role( event )
@timestamp( timestamp )
id : long
key : String
timestamp : Date
end
// Business rules
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert( new EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
// if (Math.random() < 0.001) logger.debug("New event: {}", $e.getId());
end
// Metrics
rule "Count epm"
timer ( cron: 0/10 * * * * ? )
when
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s ) from
entry-point "counters", count(1) )
then
logger.debug("epm = {}", $count );
end
rule "Count live counters"
timer ( cron: 0/60 * * * * ? )
when
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) from entry-point "counters",
count(1) )
then
logger.debug("Live counters = {}", $count );
end
*Working *(log #3 in my last mail)
*[This is the drl you posted in your reply. Here you can see the
CronTrigger usage. Cron based rule has empty LHS, and RHS inserts a
trigger, accumulate occurs in a standard (not cron based) rule]*
package it.intext.unity.test
import it.intext.unity.test.SynthEvent;
import java.util.Date;
global org.slf4j.Logger logger;
declare SynthEvent
@role( event )
@timestamp( timestamp )
end
declare EventCounter
@role( event )
@timestamp( timestamp )
id : long
key : String
timestamp : Date
end
declare CronTrigger end
rule "Trigger Metric"
timer ( cron: 0/10 * * * * ? )
when
then
entryPoints["triggers"].insert( new CronTrigger() );
end
rule "Create counter"
when
$e : SynthEvent() from entry-point "synth"
then
entryPoints["counters"].insert(new EventCounter( $e.getId(),
"event",
$e.getTimestamp() ) );
end
rule "Count epm"
when
$trigger : CronTrigger() from entry-point "triggers"
Number( $count : intValue ) from accumulate(
EventCounter( key == "event" ) over window:time( 60s )from
entry-point "counters", count(1) )
then
System.out.println("[" + new Date() + "] epm = " + $count );
retract($trigger);
end
The code used to run the tests is the one we both used in our previous test
session. For details you can mail me directly.
Thanks,
Vieri
11:43 a.m.
Hi again,
I've been able to reproduce the last issue with CronTrigger that you
reported (even if not as frequently as you wrote) and I just pushed a very
minor change that should fix also this:
https://github.com/droolsjbpm/drools/commit/94b0c4588
Let me know if you'll have a chance to test this last improvement and tell
me if it works for you.
Thanks,
Mario
--
View this message in context:
http://drools.46999.n3.nabble.com/rules-users-Drools-Fusion-inconsistenci...
Sent from the Drools: User forum mailing list archive at Nabble.com.
3709
days inactive
3718
days old
15 comments
4 participants
participants (4)
-
Mario Fusco -
Mark Proctor -
Vieri -
Wolfgang Laun