From 4d68c013719384157543e1ddf9fee576054019b5 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Wed, 11 Mar 2026 13:53:06 -0500 Subject: [PATCH 1/5] Use messages with parameters --- .../scr/impl/BundleComponentActivator.java | 3 +- .../scr/impl/ComponentActorExecutor.java | 4 +- .../scr/impl/helper/ConfigAdminTracker.java | 3 +- .../scr/impl/inject/methods/BaseMethod.java | 6 +-- .../scr/impl/inject/methods/BindMethod.java | 40 ++++++++----------- .../manager/AbstractComponentManager.java | 20 +++++----- .../impl/manager/SingleComponentManager.java | 5 +-- 7 files changed, 37 insertions(+), 44 deletions(-) diff --git a/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java b/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java index 4ff4869792..e942d3bebc 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java @@ -145,8 +145,7 @@ public void addServiceListener(String serviceFilterString, ListenerInfo listenerInfo; synchronized ( listenerMap ) { - logger.log(Level.DEBUG, "serviceFilterString: " + serviceFilterString, - null); + logger.log(Level.DEBUG, "serviceFilterString: {0}", null, serviceFilterString); listenerInfo = listenerMap.get( serviceFilterString ); if ( listenerInfo == null ) { diff --git a/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java b/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java index 67786694bf..cf080f697a 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java @@ -56,7 +56,7 @@ public Thread newThread(Runnable r) @Override protected void beforeExecute(Thread t, Runnable r) { - logger.log(Level.DEBUG, "Running task: " + r, null); + logger.log(Level.DEBUG, "Running task: {0}", null, r); } @Override @@ -64,7 +64,7 @@ protected void afterExecute(Runnable r, Throwable t) { if (t != null) { - logger.log(Level.ERROR, "Unexpected problem executing task " + r, t); + logger.log(Level.ERROR, "Unexpected problem executing task {0}", t, r); } } } diff --git a/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java b/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java index 577823dac2..fcda5059b9 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java @@ -58,8 +58,7 @@ public RegionConfigurationSupport addingService(ServiceReference findMethod(final ComponentLogger logger) throws Invocation // This is 'Debug' however, as the class information, where the search // was conducted, is quite important for the client's own debugging logger.log(Level.DEBUG, - "Locating method " + getMethodName() + " within class " + theClass.getName(), null ); + "Locating method {0} within class {1}", null, getMethodName(), theClass.getName()); } while (true) @@ -177,7 +177,7 @@ private MethodInfo findMethod(final ComponentLogger logger) throws Invocation // Trace as this is going through the whole hierachy and will log for non-existing methods // a lot of lines for e.g. the class Object not containing an activate method logger.log(Level.TRACE, - "Locating method " + getMethodName() + " in class " + theClass.getName(), null ); + "Locating method {0} in class {1}", null, getMethodName(), theClass.getName()); } try @@ -271,7 +271,7 @@ private MethodResult invokeMethod(final Object componentInstance, final P rawPar catch ( IllegalStateException ise ) { rawParameter.getComponentContext().getLogger().log(Level.DEBUG, - ise.getMessage(), null); + ise.getMessage(), ise); return null; } catch ( IllegalAccessException ex ) diff --git a/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java b/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java index 9886894bf3..4775fd41fe 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java @@ -99,7 +99,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Looking for method " + targetClass.getName() + "." + getMethodName(), null ); + "doFindMethod: Looking for method {0}.{1}", null, targetClass.getName(), getMethodName()); } // Case 1 - Service reference parameter @@ -111,8 +111,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}",null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceReference)); } @@ -132,8 +131,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceObjects)); } @@ -153,8 +151,8 @@ protected MethodInfo> doFindMethod( final Class ta { logger.log( Level.DEBUG, - "doFindMethod: No method taking ServiceReference found, checking method taking " - + parameterClass.getName(), null ); + "doFindMethod: No method taking ServiceReference found, checking method taking {0}", + null, parameterClass.getName() ); } // Case 3 - Service object parameter @@ -165,8 +163,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceType)); @@ -185,8 +182,7 @@ protected MethodInfo> doFindMethod( final Class ta { if (logger.isLogEnabled(Level.DEBUG)) { - logger.log(Level.DEBUG, "doFindMethod: Found Method " + method, - null); + logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceType)); @@ -208,7 +204,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + method, null); + "doFindMethod: Found Method {0}", null, method); } return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_map)); @@ -233,7 +229,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + method, null); + "doFindMethod: Found Method {0}", null, method); } List paramTypes = new ArrayList<>(2); paramTypes.add(ValueUtils.ValueType.ref_serviceType); @@ -256,7 +252,7 @@ protected MethodInfo> doFindMethod( final Class ta if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + method, null); + "doFindMethod: Found Method {0}", null, method); } List paramTypes = new ArrayList<>(2); paramTypes.add(ValueUtils.ValueType.ref_serviceType); @@ -352,7 +348,7 @@ else if ( paramType.getName().equals(ClassUtils.FORMATTER_LOGGER_CLASS) ) if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "doFindMethod: Found Method " + m, null); + "doFindMethod: Found Method {0}", null, m); } return new MethodInfo<>(m, paramTypes); } @@ -366,8 +362,7 @@ else if (logger.isLogEnabled(Level.WARN)) { logger.log( Level.WARN, - "doFindMethod: Cannot check for methods taking parameter class " + m_referenceClassName + ": " - + targetClass.getName() + " does not see it", null ); + "doFindMethod: Cannot check for methods taking parameter class {0}: {1} does not see it", null, m_referenceClassName, targetClass.getName()); } // if at least one suitable method could be found but none of @@ -481,8 +476,7 @@ private Method getServiceObjectAssignableMethod( final Class targetClass, fin { logger.log( Level.DEBUG, - "getServiceObjectAssignableMethod: Checking " + candidateBindMethods.length - + " declared method in class " + targetClass.getName(), null ); + "getServiceObjectAssignableMethod: Checking {0} declared method in class {1}", null, candidateBindMethods.length, targetClass.getName()); } // Iterate over them @@ -492,7 +486,7 @@ private Method getServiceObjectAssignableMethod( final Class targetClass, fin if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "getServiceObjectAssignableMethod: Checking " + method, null); + "getServiceObjectAssignableMethod: Checking {0}", null, method); } // Get the parameters for the current method @@ -507,7 +501,7 @@ private Method getServiceObjectAssignableMethod( final Class targetClass, fin if (logger.isLogEnabled(Level.DEBUG)) { logger.log(Level.DEBUG, - "getServiceObjectAssignableMethod: Considering " + method, null); + "getServiceObjectAssignableMethod: Considering {0}", null, method); } // Get the parameter type @@ -530,8 +524,8 @@ else if (logger.isLogEnabled(Level.DEBUG)) { logger.log( Level.DEBUG, - "getServiceObjectAssignableMethod: Parameter failure: Required " + theParameter + "; actual " - + parameterClass.getName(), null ); + "getServiceObjectAssignableMethod: Parameter failure: Required {0}; actual {1}", + null, theParameter, parameterClass.getName()); } } diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java index b8aff475c1..a6864dad87 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java @@ -301,14 +301,16 @@ final boolean isStateLocked() final void dumpThreads() { - try - { - String dump = new ThreadDump().call(); - m_container.getLogger().log(Level.DEBUG, dump, null); - } - catch (Throwable t) - { - m_container.getLogger().log(Level.DEBUG, "Could not dump threads", t); + if (m_container.getLogger().isLogEnabled(Level.DEBUG)) { + try + { + String dump = new ThreadDump().call(); + m_container.getLogger().log(Level.DEBUG, dump, null); + } + catch (Throwable t) + { + m_container.getLogger().log(Level.DEBUG, "Could not dump threads", t); + } } } @@ -832,7 +834,7 @@ final void deactivateInternal(int reason, boolean disable, boolean dispose) if (isFactory() || m_factoryInstance || dispose) { m_container.getLogger().log(Level.DEBUG, - "Disposing component (reason: " + reason + ")", null); + "Disposing component (reason: {0})", null, reason); clear(); } } diff --git a/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java b/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java index f98601fc9e..9a61a98c55 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java @@ -292,9 +292,8 @@ protected S createImplementationObject( Bundle usingBundle, SetImplementationObj { // we don't need to log the stack trace getLogger().log(Level.ERROR, - "Error during instantiation of the implementation object: " - + ie.getMessage(), - null); + "Error during instantiation of the implementation object: {0}", + null, ie.getMessage()); this.setFailureReason(ie); return null; } From a07a3078ee0f78e9e177166028171eb569d28fd7 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Thu, 12 Mar 2026 10:46:25 -0500 Subject: [PATCH 2/5] Use repeating task to update change count service property On startup SCR will blast change count updates for each component it satisfies and activates etc. This resulted in a very large number of task being submitted to the scheduled executor. Prior to using an executor a Timer was used. In both cases the tasks would wait a default of 5 seconds before updating the change count service property. Every task submitted would be a no-op except the very last one which had the "final" change count value. This behavior is to avoid flooding the system with service modified events. The issue is that now we are flooding the scheduled executor with a significant number of task that most all do nothing. Since moving to an executor we noticed a non-trivial bump in our CPU usage when the default 5 seconds passes to run all the queued tasks. It turns out that on the JVM we are using the Timer is actually more efficient than the scheduled executor for popping off all the tasks and running them when the delay timeout is hit. The overall design here is sub-optimal regardless. Flooding a queue with all but one task that do nothing is not efficient. This change moves to using a simple repeating task that just updates the change count service property, if needed, every delay period (defaults to every 5 seconds). --- .../felix/scr/impl/ComponentRegistry.java | 60 +++++++++---------- 1 file changed, 30 insertions(+), 30 deletions(-) diff --git a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java index 718c18361c..16a121c555 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java @@ -706,8 +706,6 @@ public void unregisterRegionConfigurationSupport( private final AtomicLong changeCount = new AtomicLong(); - private volatile ServiceRegistration registration; - public Dictionary getServiceRegistrationProperties() { final Dictionary props = new Hashtable<>(); @@ -718,42 +716,44 @@ public Dictionary getServiceRegistrationProperties() public void setRegistration(final ServiceRegistration reg) { - this.registration = reg; + long delay = m_configuration.serviceChangecountTimeout(); + m_componentActor.scheduleWithFixedDelay(new UpdateChangeCountProperty(reg), delay, delay, TimeUnit.MILLISECONDS); } - public void updateChangeCount() - { - if ( registration != null ) + class UpdateChangeCountProperty implements Runnable { + private final ServiceRegistration registration; + + public UpdateChangeCountProperty(ServiceRegistration registration) { - final long count = this.changeCount.incrementAndGet(); + this.registration = registration; + } - try - { - m_componentActor.schedule(new Runnable() + @Override + public void run() + { + try { + Long registeredChangeCount = (Long) registration.getReference().getProperty(PROP_CHANGECOUNT); + if (registeredChangeCount == null || registeredChangeCount.longValue() != changeCount.get()) { + try { - - @Override - public void run() - { - if ( changeCount.get() == count ) - { - try - { - registration.setProperties(getServiceRegistrationProperties()); - } - catch ( final IllegalStateException ise) - { - // we ignore this as this might happen on shutdown - } - } - } - }, m_configuration.serviceChangecountTimeout(), TimeUnit.MILLISECONDS); - } - catch (Exception e) { + registration.setProperties(getServiceRegistrationProperties()); + } + catch ( final IllegalStateException ise) + { + // we ignore this as this might happen on shutdown + } + } + } catch (Exception e) { m_logger.log(Level.WARN, - "Service changecount Timer for {0} had a problem", e, + "Service changecount update for {0} had a problem", e, registration.getReference()); } } + + } + + public void updateChangeCount() + { + this.changeCount.incrementAndGet(); } } From 51de0a8b6eed404da350822d8aa0c85f01ea7f3f Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Tue, 24 Mar 2026 12:41:33 -0500 Subject: [PATCH 3/5] Cancel scheduled task for change count update when inactive After at least 10 seconds of inactivity this will cancel the ScheduledFuture for updating the change count service property. If later the change count is updated then a new ScheduledFuture is submitted. --- .../felix/scr/impl/ComponentRegistry.java | 60 ++++++++++++++++--- 1 file changed, 52 insertions(+), 8 deletions(-) diff --git a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java index 16a121c555..310a1385ac 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java @@ -31,6 +31,7 @@ import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentMap; import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; @@ -132,9 +133,12 @@ public class ComponentRegistry private final ScheduledExecutorService m_componentActor; + private final UpdateChangeCountProperty m_updateChangeCountPropertyTask; + public ComponentRegistry(final ScrConfiguration scrConfiguration, final ScrLogger logger, final ScheduledExecutorService componentActor ) { m_configuration = scrConfiguration; + m_updateChangeCountPropertyTask = new UpdateChangeCountProperty(m_configuration.serviceChangecountTimeout()); m_logger = logger; m_componentActor = componentActor; m_componentHoldersByName = new HashMap<>(); @@ -716,32 +720,72 @@ public Dictionary getServiceRegistrationProperties() public void setRegistration(final ServiceRegistration reg) { - long delay = m_configuration.serviceChangecountTimeout(); - m_componentActor.scheduleWithFixedDelay(new UpdateChangeCountProperty(reg), delay, delay, TimeUnit.MILLISECONDS); + m_updateChangeCountPropertyTask.setRegistration(reg); + m_updateChangeCountPropertyTask.schedule(); } class UpdateChangeCountProperty implements Runnable { - private final ServiceRegistration registration; + private volatile ServiceRegistration registration; + private final long maxNumberOfNoChanges; + private final long delay; + + // guarded by this + private int noChangesCount = 0; + // guarded by this + private ScheduledFuture scheduledFuture = null; - public UpdateChangeCountProperty(ServiceRegistration registration) + public UpdateChangeCountProperty(long delay) { - this.registration = registration; + this.delay = delay; + // calculate the max number of no changes; must be at least 1 to avoid missing events + maxNumberOfNoChanges = Long.max(10000 / delay, 1); + } + + public void setRegistration(ServiceRegistration reg) + { + this.registration = reg; + } + + public synchronized void schedule() + { + // reset noChangesCount to ensure task runs at least once more if it exists + noChangesCount = 0; + if (scheduledFuture != null) { + return; + } + scheduledFuture = m_componentActor.scheduleWithFixedDelay(this , delay, delay, TimeUnit.MILLISECONDS); } @Override public void run() { + ServiceRegistration currentReg = registration; + if (currentReg == null) { + return; + } try { - Long registeredChangeCount = (Long) registration.getReference().getProperty(PROP_CHANGECOUNT); + Long registeredChangeCount = (Long) currentReg.getReference().getProperty(PROP_CHANGECOUNT); if (registeredChangeCount == null || registeredChangeCount.longValue() != changeCount.get()) { try { - registration.setProperties(getServiceRegistrationProperties()); + currentReg.setProperties(getServiceRegistrationProperties()); } catch ( final IllegalStateException ise) { // we ignore this as this might happen on shutdown } + } else { + synchronized (this) { + noChangesCount++; + if (noChangesCount > maxNumberOfNoChanges) { + // haven't had any changes for max number of tries; + // cancel the scheduled future if it exists. + if (scheduledFuture != null) { + scheduledFuture.cancel(false); + scheduledFuture = null; + } + } + } } } catch (Exception e) { m_logger.log(Level.WARN, @@ -749,11 +793,11 @@ public void run() registration.getReference()); } } - } public void updateChangeCount() { this.changeCount.incrementAndGet(); + m_updateChangeCountPropertyTask.schedule(); } } From e7862546f0cb2e7f38ea58989f0d83c96f874ef6 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Wed, 25 Mar 2026 10:33:36 -0500 Subject: [PATCH 4/5] Use an allowable min delay of 100 ms Also protected against IllegalStateException on getReference --- .../felix/scr/impl/ComponentRegistry.java | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java index 310a1385ac..3bff2bfc45 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java @@ -725,6 +725,8 @@ public void setRegistration(final ServiceRegistration r } class UpdateChangeCountProperty implements Runnable { + // TODO Is 100 ms an appropriate minimum? + private static final long MIN_ALLOWED_DELAY = 100; private volatile ServiceRegistration registration; private final long maxNumberOfNoChanges; private final long delay; @@ -736,8 +738,15 @@ class UpdateChangeCountProperty implements Runnable { public UpdateChangeCountProperty(long delay) { + if (delay < MIN_ALLOWED_DELAY) { + m_logger.log(Level.INFO, + "The service change count timeout {0} is less than the allowable minimum {1}. Using the allowable minimum instead.", null, + delay, MIN_ALLOWED_DELAY); + delay = MIN_ALLOWED_DELAY; + } this.delay = delay; - // calculate the max number of no changes; must be at least 1 to avoid missing events + // Calculate the max number of no changes; must be at least 1 to avoid missing events + // The calculation is intended to let at least 10 seconds pass before canceling the scheduledFuture maxNumberOfNoChanges = Long.max(10000 / delay, 1); } @@ -764,7 +773,12 @@ public void run() return; } try { - Long registeredChangeCount = (Long) currentReg.getReference().getProperty(PROP_CHANGECOUNT); + Long registeredChangeCount = null; + try { + registeredChangeCount = (Long) currentReg.getReference().getProperty(PROP_CHANGECOUNT); + } catch ( final IllegalStateException ise) { + // we ignore this as this might happen on shutdown + } if (registeredChangeCount == null || registeredChangeCount.longValue() != changeCount.get()) { try { From ec96dd33bbe3ec90ed11e08d2c0d2a807b6816cf Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Thu, 26 Mar 2026 10:14:46 -0500 Subject: [PATCH 5/5] Add test for min timeout for change count update Also fix logging for when timeout is less than 1 --- .../felix/scr/impl/ComponentRegistry.java | 59 +++++++------ .../scr/integration/GithubPR486Test.java | 84 +++++++++++++++++++ 2 files changed, 119 insertions(+), 24 deletions(-) create mode 100644 scr/src/test/java/org/apache/felix/scr/integration/GithubPR486Test.java diff --git a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java index 3bff2bfc45..247e3e0f36 100644 --- a/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java +++ b/scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java @@ -138,7 +138,7 @@ public class ComponentRegistry public ComponentRegistry(final ScrConfiguration scrConfiguration, final ScrLogger logger, final ScheduledExecutorService componentActor ) { m_configuration = scrConfiguration; - m_updateChangeCountPropertyTask = new UpdateChangeCountProperty(m_configuration.serviceChangecountTimeout()); + m_updateChangeCountPropertyTask = new UpdateChangeCountProperty(m_configuration.serviceChangecountTimeout(), logger, componentActor); m_logger = logger; m_componentActor = componentActor; m_componentHoldersByName = new HashMap<>(); @@ -708,38 +708,43 @@ public void unregisterRegionConfigurationSupport( } - private final AtomicLong changeCount = new AtomicLong(); - - public Dictionary getServiceRegistrationProperties() + Dictionary getServiceRegistrationProperties() { - final Dictionary props = new Hashtable<>(); - props.put(PROP_CHANGECOUNT, this.changeCount.get()); - - return props; + return m_updateChangeCountPropertyTask.getServiceRegistrationProperties(); } - public void setRegistration(final ServiceRegistration reg) + public void setRegistration(final ServiceRegistration reg) { m_updateChangeCountPropertyTask.setRegistration(reg); m_updateChangeCountPropertyTask.schedule(); } - class UpdateChangeCountProperty implements Runnable { - // TODO Is 100 ms an appropriate minimum? - private static final long MIN_ALLOWED_DELAY = 100; + public void updateChangeCount() + { + m_updateChangeCountPropertyTask.updateChangeCount(); + } + + static class UpdateChangeCountProperty implements Runnable { + // TODO 1 seems really low? + private static final long MIN_ALLOWED_DELAY = 1; + private final AtomicLong changeCount = new AtomicLong(); private volatile ServiceRegistration registration; private final long maxNumberOfNoChanges; private final long delay; + private final ScrLogger logger; + private final ScheduledExecutorService executor; // guarded by this private int noChangesCount = 0; // guarded by this private ScheduledFuture scheduledFuture = null; - public UpdateChangeCountProperty(long delay) + UpdateChangeCountProperty(long delay, ScrLogger logger, ScheduledExecutorService executor) { + this.logger = logger; + this.executor = executor; if (delay < MIN_ALLOWED_DELAY) { - m_logger.log(Level.INFO, + logger.log(Level.INFO, "The service change count timeout {0} is less than the allowable minimum {1}. Using the allowable minimum instead.", null, delay, MIN_ALLOWED_DELAY); delay = MIN_ALLOWED_DELAY; @@ -750,19 +755,31 @@ public UpdateChangeCountProperty(long delay) maxNumberOfNoChanges = Long.max(10000 / delay, 1); } - public void setRegistration(ServiceRegistration reg) + void setRegistration(ServiceRegistration reg) { this.registration = reg; } - public synchronized void schedule() + Dictionary getServiceRegistrationProperties() + { + final Dictionary props = new Hashtable<>(); + props.put(PROP_CHANGECOUNT, this.changeCount.get()); + + return props; + } + + public void updateChangeCount() { + this.changeCount.incrementAndGet(); + schedule(); + } + synchronized void schedule() { // reset noChangesCount to ensure task runs at least once more if it exists noChangesCount = 0; if (scheduledFuture != null) { return; } - scheduledFuture = m_componentActor.scheduleWithFixedDelay(this , delay, delay, TimeUnit.MILLISECONDS); + scheduledFuture = executor.scheduleWithFixedDelay(this , delay, delay, TimeUnit.MILLISECONDS); } @Override @@ -802,16 +819,10 @@ public void run() } } } catch (Exception e) { - m_logger.log(Level.WARN, + logger.log(Level.WARN, "Service changecount update for {0} had a problem", e, registration.getReference()); } } } - - public void updateChangeCount() - { - this.changeCount.incrementAndGet(); - m_updateChangeCountPropertyTask.schedule(); - } } diff --git a/scr/src/test/java/org/apache/felix/scr/integration/GithubPR486Test.java b/scr/src/test/java/org/apache/felix/scr/integration/GithubPR486Test.java new file mode 100644 index 0000000000..ead0dd4ffb --- /dev/null +++ b/scr/src/test/java/org/apache/felix/scr/integration/GithubPR486Test.java @@ -0,0 +1,84 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ +package org.apache.felix.scr.integration; + +import static org.junit.Assert.assertEquals; +import static org.ops4j.pax.exam.CoreOptions.systemProperty; + +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.RunWith; +import org.ops4j.pax.exam.Configuration; +import org.ops4j.pax.exam.Option; +import org.ops4j.pax.exam.OptionUtils; +import org.ops4j.pax.exam.junit.PaxExam; +import org.osgi.framework.BundleException; +import org.osgi.framework.Constants; +import org.osgi.framework.InvalidSyntaxException; +import org.osgi.framework.ServiceReference; +import org.osgi.service.component.runtime.ServiceComponentRuntime; + +@RunWith(PaxExam.class) +public class GithubPR486Test extends ComponentTestBase +{ + + // test min timeout checking + private static final long DS_SERVICE_CHANGECOUNT_TIMEOUT = 0; + + static + { + descriptorFile = "/integration_test_simple_components.xml"; + // uncomment to enable debugging of this test class + //paxRunnerVmOption = DEBUG_VM_OPTION; + } + + @Configuration + public static Option[] configuration() + { + return OptionUtils.combine(ComponentTestBase.configuration(), + systemProperty( "ds.service.changecount.timeout" ).value( Long.toString(DS_SERVICE_CHANGECOUNT_TIMEOUT) )); + } + + + private ServiceReference scrRef; + @Before + public void addServiceListener() throws InvalidSyntaxException + { + scrRef = bundleContext.getServiceReference(ServiceComponentRuntime.class); + } + + @Test + public void verify_changecount_updates_with_min_timeout() throws InterruptedException, BundleException + { + // Wait a second the changecount timeout`to account for the asynchronous service.changecount property update + Thread.sleep(1000); + + // Check that the service.changecount update was recorded + assertEquals(13L, scrRef.getProperty(Constants.SERVICE_CHANGECOUNT)); + + // Trigger a change by stopping the bundle with components + bundle.stop(); + + // Wait a second the changecount timeout`to account for the asynchronous service.changecount property update + Thread.sleep(1000); + + // Check that another service.changecount update was recorded + assertEquals(26L, scrRef.getProperty(Constants.SERVICE_CHANGECOUNT)); + } +}