[
https://issues.apache.org/jira/browse/METRON-1505?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16422834#comment-16422834
]
ASF GitHub Bot commented on METRON-1505:
----------------------------------------
Github user nickwallen commented on a diff in the pull request:
https://github.com/apache/metron/pull/977#discussion_r178599674
--- Diff:
metron-analytics/metron-profiler-common/src/main/java/org/apache/metron/profiler/DefaultMessageDistributor.java
---
@@ -281,29 +289,45 @@ public DefaultMessageDistributor
withPeriodDuration(int duration, TimeUnit units
/**
* A listener that is notified when profiles expire from the active
cache.
*/
- private class ActiveCacheRemovalListener implements
RemovalListener<String, ProfileBuilder> {
+ private class ActiveCacheRemovalListener implements
RemovalListener<Integer, ProfileBuilder> {
@Override
- public void onRemoval(RemovalNotification<String, ProfileBuilder>
notification) {
+ public void onRemoval(RemovalNotification<Integer, ProfileBuilder>
notification) {
- String key = notification.getKey();
ProfileBuilder expired = notification.getValue();
+ LOG.warn("Profile expired from active cache; profile={}, entity={}",
+ expired.getDefinition().getProfile(),
+ expired.getEntity());
- LOG.warn("Profile expired from active cache; key={}", key);
- expiredCache.put(key, expired);
+ // add the profile to the expired cache
+ expiredCache.put(notification.getKey(), expired);
}
}
/**
* A listener that is notified when profiles expire from the active
cache.
*/
- private class ExpiredCacheRemovalListener implements
RemovalListener<String, ProfileBuilder> {
+ private class ExpiredCacheRemovalListener implements
RemovalListener<Integer, ProfileBuilder> {
@Override
- public void onRemoval(RemovalNotification<String, ProfileBuilder>
notification) {
+ public void onRemoval(RemovalNotification<Integer, ProfileBuilder>
notification) {
+
+ if(notification.wasEvicted()) {
+
+ // the expired profile was NOT flushed in time
--- End diff --
A profile being removed from the expired cache is only 'bad' when it is
evicted. When an eviction occurs, we get a WARN. Otherwise, only a DEBUG is
used. This makes the logging much more useful when troubleshooting.
> Intermittent Profiler Integration Test Failure
> ----------------------------------------------
>
> Key: METRON-1505
> URL: https://issues.apache.org/jira/browse/METRON-1505
> Project: Metron
> Issue Type: Bug
> Reporter: Nick Allen
> Assignee: Nick Allen
> Priority: Major
>
> The Profiler integration tests which use processing time fail intermittently
> when run in Travis CI.
> {code:java}
> 2018-03-22 22:00:35 DEBUG FixedFrequencyFlushSignal:67 - Flush counters reset
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 0 route(s) for
> message with timestamp=1521756035759
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 0 route(s) for
> message with timestamp=1521756035802
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 0 route(s) for
> message with timestamp=1521756035806
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:195 - Found route for message;
> profile=example2, entity=10.0.0.2, timestamp=1521756035807
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 1 route(s) for
> message with timestamp=1521756035807
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:195 - Found route for message;
> profile=example2, entity=10.0.0.2, timestamp=1521756035808
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 1 route(s) for
> message with timestamp=1521756035808
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:195 - Found route for message;
> profile=example2, entity=10.0.0.2, timestamp=1521756035813
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 1 route(s) for
> message with timestamp=1521756035813
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:195 - Found route for message;
> profile=example2, entity=10.0.0.3, timestamp=1521756035814
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 1 route(s) for
> message with timestamp=1521756035814
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:195 - Found route for message;
> profile=example2, entity=10.0.0.3, timestamp=1521756035816
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 1 route(s) for
> message with timestamp=1521756035816
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:195 - Found route for message;
> profile=example2, entity=10.0.0.3, timestamp=1521756035817
> 2018-03-22 22:00:35 DEBUG ProfileSplitterBolt:201 - Found 1 route(s) for
> message with timestamp=1521756035817
> 2018-03-22 22:00:41 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756041122}
> 2018-03-22 22:00:41 DEBUG WindowManager:212 - [6] events expired from window.
> 2018-03-22 22:00:41 DEBUG WindowManager:214 - invoking
> windowLifecycleListener.onExpiry
> 2018-03-22 22:00:41 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:00:46 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756046122}
> 2018-03-22 22:00:46 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:00:46 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:00:51 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756051122}
> 2018-03-22 22:00:51 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:00:51 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:00:56 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756056122}
> 2018-03-22 22:00:56 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:00:56 DEBUG WindowManager:144 - invoking
> windowLifecycleListener onActivation, [1] events in window.
> 2018-03-22 22:00:56 DEBUG ProfileBuilderBolt:276 - Tuple window contains 1
> tuple(s), 0 expired, 1 new
> 2018-03-22 22:00:56 DEBUG ProfileBuilderBolt:365 - Emitted 0 measurement(s).
> 2018-03-22 22:00:56 DEBUG ProfileBuilderBolt:325 - Flushed expired profiles
> and found 0 measurement(s).
> 2018-03-22 22:00:56 DEBUG FixedFrequencyFlushSignal:114 - Flush=false, '0' ms
> until flush; currentTime=0, flushTime=0
> 2018-03-22 22:01:01 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756061122}
> 2018-03-22 22:01:01 DEBUG WindowManager:212 - [1] events expired from window.
> 2018-03-22 22:01:01 DEBUG WindowManager:214 - invoking
> windowLifecycleListener.onExpiry
> 2018-03-22 22:01:01 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:06 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756066122}
> 2018-03-22 22:01:06 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:06 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:11 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756071122}
> 2018-03-22 22:01:11 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:11 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:16 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756076122}
> 2018-03-22 22:01:16 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:16 DEBUG WindowManager:144 - invoking
> windowLifecycleListener onActivation, [1] events in window.
> 2018-03-22 22:01:16 DEBUG ProfileBuilderBolt:276 - Tuple window contains 1
> tuple(s), 0 expired, 1 new
> 2018-03-22 22:01:16 DEBUG ProfileBuilderBolt:365 - Emitted 0 measurement(s).
> 2018-03-22 22:01:16 DEBUG ProfileBuilderBolt:325 - Flushed expired profiles
> and found 0 measurement(s).
> 2018-03-22 22:01:16 DEBUG FixedFrequencyFlushSignal:114 - Flush=false, '0' ms
> until flush; currentTime=0, flushTime=0
> 2018-03-22 22:01:21 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756081122}
> 2018-03-22 22:01:21 DEBUG WindowManager:212 - [1] events expired from window.
> 2018-03-22 22:01:21 DEBUG WindowManager:214 - invoking
> windowLifecycleListener.onExpiry
> 2018-03-22 22:01:21 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:26 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756086122}
> 2018-03-22 22:01:26 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:26 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:31 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756091122}
> 2018-03-22 22:01:31 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:31 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:36 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756096122}
> 2018-03-22 22:01:36 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:36 DEBUG WindowManager:144 - invoking
> windowLifecycleListener onActivation, [1] events in window.
> 2018-03-22 22:01:36 DEBUG ProfileBuilderBolt:276 - Tuple window contains 1
> tuple(s), 0 expired, 1 new
> 2018-03-22 22:01:36 DEBUG ProfileBuilderBolt:365 - Emitted 0 measurement(s).
> 2018-03-22 22:01:36 DEBUG ProfileBuilderBolt:325 - Flushed expired profiles
> and found 0 measurement(s).
> 2018-03-22 22:01:36 DEBUG FixedFrequencyFlushSignal:114 - Flush=false, '0' ms
> until flush; currentTime=0, flushTime=0
> 2018-03-22 22:01:41 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756101122}
> 2018-03-22 22:01:41 DEBUG WindowManager:212 - [1] events expired from window.
> 2018-03-22 22:01:41 DEBUG WindowManager:214 - invoking
> windowLifecycleListener.onExpiry
> 2018-03-22 22:01:41 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:46 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756106122}
> 2018-03-22 22:01:46 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:46 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:51 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756111122}
> 2018-03-22 22:01:51 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:51 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:01:56 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756116122}
> 2018-03-22 22:01:56 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:01:56 DEBUG WindowManager:144 - invoking
> windowLifecycleListener onActivation, [1] events in window.
> 2018-03-22 22:01:56 DEBUG ProfileBuilderBolt:276 - Tuple window contains 1
> tuple(s), 0 expired, 1 new
> 2018-03-22 22:01:56 DEBUG ProfileBuilderBolt:365 - Emitted 0 measurement(s).
> 2018-03-22 22:01:56 DEBUG ProfileBuilderBolt:325 - Flushed expired profiles
> and found 0 measurement(s).
> 2018-03-22 22:01:56 DEBUG FixedFrequencyFlushSignal:114 - Flush=false, '0' ms
> until flush; currentTime=0, flushTime=0
> 2018-03-22 22:02:01 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756121122}
> 2018-03-22 22:02:01 DEBUG WindowManager:212 - [1] events expired from window.
> 2018-03-22 22:02:01 DEBUG WindowManager:214 - invoking
> windowLifecycleListener.onExpiry
> 2018-03-22 22:02:01 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:02:06 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756126122}
> 2018-03-22 22:02:06 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:02:06 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:02:11 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756131122}
> 2018-03-22 22:02:11 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:02:11 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:02:16 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756136122}
> 2018-03-22 22:02:16 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:02:16 DEBUG WindowManager:144 - invoking
> windowLifecycleListener onActivation, [1] events in window.
> 2018-03-22 22:02:16 DEBUG ProfileBuilderBolt:276 - Tuple window contains 1
> tuple(s), 0 expired, 1 new
> 2018-03-22 22:02:16 DEBUG ProfileBuilderBolt:365 - Emitted 0 measurement(s).
> 2018-03-22 22:02:16 DEBUG ProfileBuilderBolt:325 - Flushed expired profiles
> and found 0 measurement(s).
> 2018-03-22 22:02:16 DEBUG FixedFrequencyFlushSignal:114 - Flush=false, '0' ms
> until flush; currentTime=0, flushTime=0
> 2018-03-22 22:02:21 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756141122}
> 2018-03-22 22:02:21 DEBUG WindowManager:212 - [1] events expired from window.
> 2018-03-22 22:02:21 DEBUG WindowManager:214 - invoking
> windowLifecycleListener.onExpiry
> 2018-03-22 22:02:21 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:02:26 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756146122}
> 2018-03-22 22:02:26 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:02:26 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:02:31 DEBUG WindowManager:189 - Scan events, eviction policy
> TimeEvictionPolicy{windowLength=5000, referenceTime=1521756151122}
> 2018-03-22 22:02:31 DEBUG WindowManager:212 - [0] events expired from window.
> 2018-03-22 22:02:31 DEBUG WindowManager:147 - No events in the window,
> skipping onActivation
> 2018-03-22 22:02:34 DEBUG WindowManager:154 - Shutting down WindowManager
> 2018-03-22 22:02:46 DEBUG FixedFrequencyFlushSignal:67 - Flush counters
> reset{code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
