Skip to content

Stop flooding the scheduled executor with no-op tasks for change count updates #486

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
tjwatson wants to merge 2 commits into
base: master
Choose a base branch
from
+67 −74
Open

Stop flooding the scheduled executor with no-op tasks for change count updates #486

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
4d68c01
Use messages with parameters
tjwatson Mar 11, 2026
a07a307
Use repeating task to update change count service property
tjwatson Mar 12, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 1 addition & 2 deletions scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 )
{
Expand Down
4 changes: 2 additions & 2 deletions scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -56,15 +56,15 @@ 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
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);
}
}
}
60 changes: 30 additions & 30 deletions scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -706,8 +706,6 @@ public void unregisterRegionConfigurationSupport(

private final AtomicLong changeCount = new AtomicLong();

private volatile ServiceRegistration<ServiceComponentRuntime> registration;

public Dictionary<String, Object> getServiceRegistrationProperties()
{
final Dictionary<String, Object> props = new Hashtable<>();
Expand All @@ -718,42 +716,44 @@ public Dictionary<String, Object> getServiceRegistrationProperties()

public void setRegistration(final ServiceRegistration<ServiceComponentRuntime> reg)
{
this.registration = reg;
long delay = m_configuration.serviceChangecountTimeout();
m_componentActor.scheduleWithFixedDelay(new UpdateChangeCountProperty(reg), delay, delay, TimeUnit.MILLISECONDS);
Copy link
Contributor

@glimmerveen glimmerveen Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With this change though, the UpdateChangeCountProperty Runnable will be continuously scheduled, rather than the current approach that only schedules the task if there is a change. Especially with a low serviceChangecountTimeout value I expect that this change's continuous nature will introduce a lot of unnecessary processing, even when no changes need to be announced.

Copy link
Member Author

@tjwatson tjwatson Mar 13, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a reason to have a small timeout? I wanted performance tests with the original change. I only got to doing that now and the current approach is expensive. It adds over 5% CPU time to initial startup. It would be nice ro see how expensive it really is to check the value of a long once every 5 seconds.

We could consider an enhancement that cancels the repeating task after a set amount of retries. Then reschedules as needed. But we should not prematurely optimize with out performance numbers that prove a problem.

Copy link
Contributor

@glimmerveen glimmerveen Mar 14, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In my use-case I have a monitoring function that uses the update to the changecount property as a trigger to inspect the state of the configurations within SCR to see if any of them changed state. A low timeout helps to have this trigger each my monitoring function in a timely manner. Having a large(r) timeout still eventually reaches my monitoring function, but I have seen it misses state changes in case a stream of changes continue to "invalidate" the property update, and thus not reaching my monitoring function.

The previous implementation, which relied on creating and cancelling Timers, was quite expensive with a low timeout value, as it would create a lot of short-lived Threads during startup. I offered a change to move this as task to the already existing ExecutorService (#419) which avoids the creation of threads during startup. What still happens as you rightfully pointed out is that each changecount update results in a task, and that task being scheduled for execution and executing, and the evaluation if the task was invalidated happens within the task's execution.

I think your suggestion of cancelling the task when a new one is about to be scheduled can reduce the unnecessary execution of unneeded tasks. Looking at the original approach with Timers, it appears to me that also in that case each changecount update would be scheduled on the timer, similar to what is happening right now. Though not as efficient as it perhaps can be, it looks to me similar when a Timer was still being used, but as you report an additional 5% CPU time there is clearly something going on.

I remember you in the review voicing a concern on adding these changecount update on the already existing component actor thread. I am not very familiar with what other types of tasks are executed there, but perhaps you are observing different types of tasks scheduled on the same thread interfering with each other?

Copy link
Contributor

@glimmerveen glimmerveen Mar 14, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@tjwatson I took the liberty of implementing the suggestion you made on cancelling uncompleted tasks when a new needs to be scheduled (#487). Could you have a look if that approach provides an improvement?

}

public void updateChangeCount()
{
if ( registration != null )
class UpdateChangeCountProperty implements Runnable {
private final ServiceRegistration<ServiceComponentRuntime> registration;

public UpdateChangeCountProperty(ServiceRegistration<ServiceComponentRuntime> 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();
}
}
3 changes: 1 addition & 2 deletions scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,8 +58,7 @@ public RegionConfigurationSupport addingService(ServiceReference<ConfigurationAd
catch ( final Exception ex)
{
componentActivator.getLogger().log(Level.ERROR,
"Configuration admin API visible to bundle " + componentActivator.getBundleContext().getBundle() +
" is not the same as the Configuration Admin API visible to the SCR implementation.", ex);
"Configuration admin API visible to bundle {0} is not the same as the Configuration Admin API visible to the SCR implementation.", ex, componentActivator.getBundleContext().getBundle());
}

if ( !visible )
Expand Down
6 changes: 3 additions & 3 deletions scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BaseMethod.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -166,7 +166,7 @@ private MethodInfo<T> 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());
Copy link
Contributor

@stbischof stbischof Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

is that with null as parem not one param to much?

Copy link
Contributor

@stbischof stbischof Mar 12, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ah, its not slf4j

}

while (true)
Expand All @@ -177,7 +177,7 @@ private MethodInfo<T> 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
Expand Down Expand Up @@ -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 )
Expand Down
40 changes: 17 additions & 23 deletions scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -99,7 +99,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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
Expand All @@ -111,8 +111,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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));
}
Expand All @@ -132,8 +131,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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));
}
Expand All @@ -153,8 +151,8 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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
Expand All @@ -165,8 +163,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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));
Expand All @@ -185,8 +182,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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));
Expand All @@ -208,7 +204,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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));
Expand All @@ -233,7 +229,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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<ValueUtils.ValueType> paramTypes = new ArrayList<>(2);
paramTypes.add(ValueUtils.ValueType.ref_serviceType);
Expand All @@ -256,7 +252,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> 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<ValueUtils.ValueType> paramTypes = new ArrayList<>(2);
paramTypes.add(ValueUtils.ValueType.ref_serviceType);
Expand Down Expand Up @@ -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);
}
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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());
}

}
Expand Down
20 changes: 11 additions & 9 deletions scr/src/main/java/org/apache/felix/scr/impl/manager/AbstractComponentManager.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
}

Expand Down Expand Up @@ -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();
}
}
Expand Down
5 changes: 2 additions & 3 deletions scr/src/main/java/org/apache/felix/scr/impl/manager/SingleComponentManager.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down
Loading