From 4d68c013719384157543e1ddf9fee576054019b5 Mon Sep 17 00:00:00 2001 From: Thomas Watson Date: Wed, 11 Mar 2026 13:53:06 -0500 Subject: [PATCH 1/2] 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/2] 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(); } }