Skip to content

Commit e1f3e38

Browse files
tjwatsontjwatson
authored
Merge pull request #486 from tjwatson/felixLogParams
Stop flooding the scheduled executor with no-op tasks for change count updates
2 parents 7343b00 + ec96dd3 commit e1f3e38

9 files changed

Lines changed: 225 additions & 79 deletions

File tree

‎scr/src/main/java/org/apache/felix/scr/impl/BundleComponentActivator.java‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -145,8 +145,7 @@ public void addServiceListener(String serviceFilterString,
145145
ListenerInfo listenerInfo;
146146
synchronized ( listenerMap )
147147
{
148-
logger.log(Level.DEBUG, "serviceFilterString: " + serviceFilterString,
149-
null);
148+
logger.log(Level.DEBUG, "serviceFilterString: {0}", null, serviceFilterString);
150149
listenerInfo = listenerMap.get( serviceFilterString );
151150
if ( listenerInfo == null )
152151
{

‎scr/src/main/java/org/apache/felix/scr/impl/ComponentActorExecutor.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -56,15 +56,15 @@ public Thread newThread(Runnable r)
5656
@Override
5757
protected void beforeExecute(Thread t, Runnable r)
5858
{
59-
logger.log(Level.DEBUG, "Running task: " + r, null);
59+
logger.log(Level.DEBUG, "Running task: {0}", null, r);
6060
}
6161

6262
@Override
6363
protected void afterExecute(Runnable r, Throwable t)
6464
{
6565
if (t != null)
6666
{
67-
logger.log(Level.ERROR, "Unexpected problem executing task " + r, t);
67+
logger.log(Level.ERROR, "Unexpected problem executing task {0}", t, r);
6868
}
6969
}
7070
}

‎scr/src/main/java/org/apache/felix/scr/impl/ComponentRegistry.java‎

Lines changed: 104 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@
3131
import java.util.concurrent.ConcurrentHashMap;
3232
import java.util.concurrent.ConcurrentMap;
3333
import java.util.concurrent.ScheduledExecutorService;
34+
import java.util.concurrent.ScheduledFuture;
3435
import java.util.concurrent.TimeUnit;
3536
import java.util.concurrent.atomic.AtomicLong;
3637

@@ -132,9 +133,12 @@ public class ComponentRegistry
132133

133134
private final ScheduledExecutorService m_componentActor;
134135

136+
private final UpdateChangeCountProperty m_updateChangeCountPropertyTask;
137+
135138
public ComponentRegistry(final ScrConfiguration scrConfiguration, final ScrLogger logger, final ScheduledExecutorService componentActor )
136139
{
137140
m_configuration = scrConfiguration;
141+
m_updateChangeCountPropertyTask = new UpdateChangeCountProperty(m_configuration.serviceChangecountTimeout(), logger, componentActor);
138142
m_logger = logger;
139143
m_componentActor = componentActor;
140144
m_componentHoldersByName = new HashMap<>();
@@ -704,54 +708,119 @@ public void unregisterRegionConfigurationSupport(
704708

705709
}
706710

707-
private final AtomicLong changeCount = new AtomicLong();
708-
709-
private volatile ServiceRegistration<ServiceComponentRuntime> registration;
710-
711-
public Dictionary<String, Object> getServiceRegistrationProperties()
711+
Dictionary<String, Object> getServiceRegistrationProperties()
712712
{
713-
final Dictionary<String, Object> props = new Hashtable<>();
714-
props.put(PROP_CHANGECOUNT, this.changeCount.get());
715-
716-
return props;
713+
return m_updateChangeCountPropertyTask.getServiceRegistrationProperties();
717714
}
718715

719-
public void setRegistration(final ServiceRegistration<ServiceComponentRuntime> reg)
716+
public void setRegistration(final ServiceRegistration<ServiceComponentRuntime> reg)
720717
{
721-
this.registration = reg;
718+
m_updateChangeCountPropertyTask.setRegistration(reg);
719+
m_updateChangeCountPropertyTask.schedule();
722720
}
723721

724722
public void updateChangeCount()
725723
{
726-
if ( registration != null )
724+
m_updateChangeCountPropertyTask.updateChangeCount();
725+
}
726+
727+
static class UpdateChangeCountProperty implements Runnable {
728+
// TODO 1 seems really low?
729+
private static final long MIN_ALLOWED_DELAY = 1;
730+
private final AtomicLong changeCount = new AtomicLong();
731+
private volatile ServiceRegistration<ServiceComponentRuntime> registration;
732+
private final long maxNumberOfNoChanges;
733+
private final long delay;
734+
private final ScrLogger logger;
735+
private final ScheduledExecutorService executor;
736+
737+
// guarded by this
738+
private int noChangesCount = 0;
739+
// guarded by this
740+
private ScheduledFuture<?> scheduledFuture = null;
741+
742+
UpdateChangeCountProperty(long delay, ScrLogger logger, ScheduledExecutorService executor)
727743
{
728-
final long count = this.changeCount.incrementAndGet();
744+
this.logger = logger;
745+
this.executor = executor;
746+
if (delay < MIN_ALLOWED_DELAY) {
747+
logger.log(Level.INFO,
748+
"The service change count timeout {0} is less than the allowable minimum {1}. Using the allowable minimum instead.", null,
749+
delay, MIN_ALLOWED_DELAY);
750+
delay = MIN_ALLOWED_DELAY;
751+
}
752+
this.delay = delay;
753+
// Calculate the max number of no changes; must be at least 1 to avoid missing events
754+
// The calculation is intended to let at least 10 seconds pass before canceling the scheduledFuture
755+
maxNumberOfNoChanges = Long.max(10000 / delay, 1);
756+
}
729757

730-
try
731-
{
732-
m_componentActor.schedule(new Runnable()
733-
{
758+
void setRegistration(ServiceRegistration<ServiceComponentRuntime> reg)
759+
{
760+
this.registration = reg;
761+
}
734762

735-
@Override
736-
public void run()
737-
{
738-
if ( changeCount.get() == count )
739-
{
740-
try
741-
{
742-
registration.setProperties(getServiceRegistrationProperties());
743-
}
744-
catch ( final IllegalStateException ise)
745-
{
746-
// we ignore this as this might happen on shutdown
747-
}
763+
Dictionary<String, Object> getServiceRegistrationProperties()
764+
{
765+
final Dictionary<String, Object> props = new Hashtable<>();
766+
props.put(PROP_CHANGECOUNT, this.changeCount.get());
767+
768+
return props;
769+
}
770+
771+
public void updateChangeCount() {
772+
this.changeCount.incrementAndGet();
773+
schedule();
774+
}
775+
synchronized void schedule()
776+
{
777+
// reset noChangesCount to ensure task runs at least once more if it exists
778+
noChangesCount = 0;
779+
if (scheduledFuture != null) {
780+
return;
781+
}
782+
scheduledFuture = executor.scheduleWithFixedDelay(this , delay, delay, TimeUnit.MILLISECONDS);
783+
}
784+
785+
@Override
786+
public void run()
787+
{
788+
ServiceRegistration<ServiceComponentRuntime> currentReg = registration;
789+
if (currentReg == null) {
790+
return;
791+
}
792+
try {
793+
Long registeredChangeCount = null;
794+
try {
795+
registeredChangeCount = (Long) currentReg.getReference().getProperty(PROP_CHANGECOUNT);
796+
} catch ( final IllegalStateException ise) {
797+
// we ignore this as this might happen on shutdown
798+
}
799+
if (registeredChangeCount == null || registeredChangeCount.longValue() != changeCount.get()) {
800+
try
801+
{
802+
currentReg.setProperties(getServiceRegistrationProperties());
803+
}
804+
catch ( final IllegalStateException ise)
805+
{
806+
// we ignore this as this might happen on shutdown
807+
}
808+
} else {
809+
synchronized (this) {
810+
noChangesCount++;
811+
if (noChangesCount > maxNumberOfNoChanges) {
812+
// haven't had any changes for max number of tries;
813+
// cancel the scheduled future if it exists.
814+
if (scheduledFuture != null) {
815+
scheduledFuture.cancel(false);
816+
scheduledFuture = null;
748817
}
749818
}
750-
}, m_configuration.serviceChangecountTimeout(), TimeUnit.MILLISECONDS);
751-
}
752-
catch (Exception e) {
753-
m_logger.log(Level.WARN,
754-
"Service changecount Timer for {0} had a problem", e,
819+
}
820+
}
821+
} catch (Exception e) {
822+
logger.log(Level.WARN,
823+
"Service changecount update for {0} had a problem", e,
755824
registration.getReference());
756825
}
757826
}

‎scr/src/main/java/org/apache/felix/scr/impl/helper/ConfigAdminTracker.java‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -58,8 +58,7 @@ public RegionConfigurationSupport addingService(ServiceReference<ConfigurationAd
5858
catch ( final Exception ex)
5959
{
6060
componentActivator.getLogger().log(Level.ERROR,
61-
"Configuration admin API visible to bundle " + componentActivator.getBundleContext().getBundle() +
62-
" is not the same as the Configuration Admin API visible to the SCR implementation.", ex);
61+
"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());
6362
}
6463

6564
if ( !visible )

‎scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BaseMethod.java‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -166,7 +166,7 @@ private MethodInfo<T> findMethod(final ComponentLogger logger) throws Invocation
166166
// This is 'Debug' however, as the class information, where the search
167167
// was conducted, is quite important for the client's own debugging
168168
logger.log(Level.DEBUG,
169-
"Locating method " + getMethodName() + " within class " + theClass.getName(), null );
169+
"Locating method {0} within class {1}", null, getMethodName(), theClass.getName());
170170
}
171171

172172
while (true)
@@ -177,7 +177,7 @@ private MethodInfo<T> findMethod(final ComponentLogger logger) throws Invocation
177177
// Trace as this is going through the whole hierachy and will log for non-existing methods
178178
// a lot of lines for e.g. the class Object not containing an activate method
179179
logger.log(Level.TRACE,
180-
"Locating method " + getMethodName() + " in class " + theClass.getName(), null );
180+
"Locating method {0} in class {1}", null, getMethodName(), theClass.getName());
181181
}
182182

183183
try
@@ -271,7 +271,7 @@ private MethodResult invokeMethod(final Object componentInstance, final P rawPar
271271
catch ( IllegalStateException ise )
272272
{
273273
rawParameter.getComponentContext().getLogger().log(Level.DEBUG,
274-
ise.getMessage(), null);
274+
ise.getMessage(), ise);
275275
return null;
276276
}
277277
catch ( IllegalAccessException ex )

‎scr/src/main/java/org/apache/felix/scr/impl/inject/methods/BindMethod.java‎

Lines changed: 17 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -99,7 +99,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
9999
if (logger.isLogEnabled(Level.DEBUG))
100100
{
101101
logger.log(Level.DEBUG,
102-
"doFindMethod: Looking for method " + targetClass.getName() + "." + getMethodName(), null );
102+
"doFindMethod: Looking for method {0}.{1}", null, targetClass.getName(), getMethodName());
103103
}
104104

105105
// Case 1 - Service reference parameter
@@ -111,8 +111,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
111111
{
112112
if (logger.isLogEnabled(Level.DEBUG))
113113
{
114-
logger.log(Level.DEBUG, "doFindMethod: Found Method " + method,
115-
null);
114+
logger.log(Level.DEBUG, "doFindMethod: Found Method {0}",null, method);
116115
}
117116
return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceReference));
118117
}
@@ -132,8 +131,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
132131
{
133132
if (logger.isLogEnabled(Level.DEBUG))
134133
{
135-
logger.log(Level.DEBUG, "doFindMethod: Found Method " + method,
136-
null);
134+
logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method);
137135
}
138136
return new MethodInfo<>(method, Collections.singletonList(ValueUtils.ValueType.ref_serviceObjects));
139137
}
@@ -153,8 +151,8 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
153151
{
154152
logger.log(
155153
Level.DEBUG,
156-
"doFindMethod: No method taking ServiceReference found, checking method taking "
157-
+ parameterClass.getName(), null );
154+
"doFindMethod: No method taking ServiceReference found, checking method taking {0}",
155+
null, parameterClass.getName() );
158156
}
159157

160158
// Case 3 - Service object parameter
@@ -165,8 +163,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
165163
{
166164
if (logger.isLogEnabled(Level.DEBUG))
167165
{
168-
logger.log(Level.DEBUG, "doFindMethod: Found Method " + method,
169-
null);
166+
logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method);
170167
}
171168
return new MethodInfo<>(method,
172169
Collections.singletonList(ValueUtils.ValueType.ref_serviceType));
@@ -185,8 +182,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
185182
{
186183
if (logger.isLogEnabled(Level.DEBUG))
187184
{
188-
logger.log(Level.DEBUG, "doFindMethod: Found Method " + method,
189-
null);
185+
logger.log(Level.DEBUG, "doFindMethod: Found Method {0}", null, method);
190186
}
191187
return new MethodInfo<>(method,
192188
Collections.singletonList(ValueUtils.ValueType.ref_serviceType));
@@ -208,7 +204,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
208204
if (logger.isLogEnabled(Level.DEBUG))
209205
{
210206
logger.log(Level.DEBUG,
211-
"doFindMethod: Found Method " + method, null);
207+
"doFindMethod: Found Method {0}", null, method);
212208
}
213209
return new MethodInfo<>(method,
214210
Collections.singletonList(ValueUtils.ValueType.ref_map));
@@ -233,7 +229,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
233229
if (logger.isLogEnabled(Level.DEBUG))
234230
{
235231
logger.log(Level.DEBUG,
236-
"doFindMethod: Found Method " + method, null);
232+
"doFindMethod: Found Method {0}", null, method);
237233
}
238234
List<ValueUtils.ValueType> paramTypes = new ArrayList<>(2);
239235
paramTypes.add(ValueUtils.ValueType.ref_serviceType);
@@ -256,7 +252,7 @@ protected MethodInfo<List<ValueUtils.ValueType>> doFindMethod( final Class<?> ta
256252
if (logger.isLogEnabled(Level.DEBUG))
257253
{
258254
logger.log(Level.DEBUG,
259-
"doFindMethod: Found Method " + method, null);
255+
"doFindMethod: Found Method {0}", null, method);
260256
}
261257
List<ValueUtils.ValueType> paramTypes = new ArrayList<>(2);
262258
paramTypes.add(ValueUtils.ValueType.ref_serviceType);
@@ -352,7 +348,7 @@ else if ( paramType.getName().equals(ClassUtils.FORMATTER_LOGGER_CLASS) )
352348
if (logger.isLogEnabled(Level.DEBUG))
353349
{
354350
logger.log(Level.DEBUG,
355-
"doFindMethod: Found Method " + m, null);
351+
"doFindMethod: Found Method {0}", null, m);
356352
}
357353
return new MethodInfo<>(m, paramTypes);
358354
}
@@ -366,8 +362,7 @@ else if (logger.isLogEnabled(Level.WARN))
366362
{
367363
logger.log(
368364
Level.WARN,
369-
"doFindMethod: Cannot check for methods taking parameter class " + m_referenceClassName + ": "
370-
+ targetClass.getName() + " does not see it", null );
365+
"doFindMethod: Cannot check for methods taking parameter class {0}: {1} does not see it", null, m_referenceClassName, targetClass.getName());
371366
}
372367

373368
// if at least one suitable method could be found but none of
@@ -481,8 +476,7 @@ private Method getServiceObjectAssignableMethod( final Class<?> targetClass, fin
481476
{
482477
logger.log(
483478
Level.DEBUG,
484-
"getServiceObjectAssignableMethod: Checking " + candidateBindMethods.length
485-
+ " declared method in class " + targetClass.getName(), null );
479+
"getServiceObjectAssignableMethod: Checking {0} declared method in class {1}", null, candidateBindMethods.length, targetClass.getName());
486480
}
487481

488482
// Iterate over them
@@ -492,7 +486,7 @@ private Method getServiceObjectAssignableMethod( final Class<?> targetClass, fin
492486
if (logger.isLogEnabled(Level.DEBUG))
493487
{
494488
logger.log(Level.DEBUG,
495-
"getServiceObjectAssignableMethod: Checking " + method, null);
489+
"getServiceObjectAssignableMethod: Checking {0}", null, method);
496490
}
497491

498492
// Get the parameters for the current method
@@ -507,7 +501,7 @@ private Method getServiceObjectAssignableMethod( final Class<?> targetClass, fin
507501
if (logger.isLogEnabled(Level.DEBUG))
508502
{
509503
logger.log(Level.DEBUG,
510-
"getServiceObjectAssignableMethod: Considering " + method, null);
504+
"getServiceObjectAssignableMethod: Considering {0}", null, method);
511505
}
512506

513507
// Get the parameter type
@@ -530,8 +524,8 @@ else if (logger.isLogEnabled(Level.DEBUG))
530524
{
531525
logger.log(
532526
Level.DEBUG,
533-
"getServiceObjectAssignableMethod: Parameter failure: Required " + theParameter + "; actual "
534-
+ parameterClass.getName(), null );
527+
"getServiceObjectAssignableMethod: Parameter failure: Required {0}; actual {1}",
528+
null, theParameter, parameterClass.getName());
535529
}
536530

537531
}

0 commit comments

Comments
 (0)