add additional (debug) logging to AbstractStreamWriterGenerator

* LOG.debug() in generateSerializer() to see if in a load test
scenario that ever gets called twice for the same type (it should not)
due to a concurrency bug I'm not seeing.

* reduce the only other LOG.debug() in that class to trace()
because that one will happen more often (constantly?) and make it hard
to see the other one.

* log onBindingRuntimeContextUpdated() on the off chance
that changing the BindingRuntimeContext somehow could cause this
suspected concurrency issue.

* log constructor to better understand the lifecycle of
AbstractStreamWriterGenerator in production.

* add Guava Cache removalListener with logging to see if this is caused
by eviction by GC due to .weakKeys() - ACK to tpantelis for this hunch.

JIRA: MDSAL-213
Change-Id: I2416131fe140ee483cc93740480ee0e37f0ce130
Signed-off-by: Michael Vorburger <vorburger@redhat.com>

diff --git a/binding/mdsal-binding-dom-codec/src/main/java/org/opendaylight/mdsal/binding/dom/codec/gen/impl/AbstractStreamWriterGenerator.java b/binding/mdsal-binding-dom-codec/src/main/java/org/opendaylight/mdsal/binding/dom/codec/gen/impl/AbstractStreamWriterGenerator.java
index 1b1be4125e065798b6da45a7f8b310cda245e7dc..149bca706ba851a74b2038fb50b1b4878e54c3c8 100644 (file)
--- a/binding/mdsal-binding-dom-codec/src/main/java/org/opendaylight/mdsal/binding/dom/codec/gen/impl/AbstractStreamWriterGenerator.java
+++ b/binding/mdsal-binding-dom-codec/src/main/java/org/opendaylight/mdsal/binding/dom/codec/gen/impl/AbstractStreamWriterGenerator.java
@@ -80,7 +80,11 @@ abstract class AbstractStreamWriterGenerator extends AbstractGenerator implement
                 javassist.asCtClass(BindingStreamEventWriter.class),
         };
         javassist.appendClassLoaderIfMissing(DataObjectSerializerPrototype.class.getClassLoader());
-        this.implementations = CacheBuilder.newBuilder().weakKeys().build(new SerializerImplementationLoader());
+        this.implementations = CacheBuilder.newBuilder()
+                .removalListener(notification -> LOG.debug("onRemoval: cause={}, wasEvicted={}",
+                        notification.getCause(), notification.wasEvicted()))
+                .weakKeys().build(new SerializerImplementationLoader());
+        LOG.debug("AbstractStreamWriterGenerator constructor, new instance: {}", this);
     }
 
     @Override
@@ -91,6 +95,7 @@ abstract class AbstractStreamWriterGenerator extends AbstractGenerator implement
     @Override
     public final void onBindingRuntimeContextUpdated(final BindingRuntimeContext runtime) {
         this.context = runtime;
+        LOG.debug("onBindingRuntimeContextUpdated() : {}", runtime);
     }
 
     @Override
@@ -127,7 +132,7 @@ abstract class AbstractStreamWriterGenerator extends AbstractGenerator implement
 
             final DataObjectSerializerImplementation obj =
                     (DataObjectSerializerImplementation) cls.getDeclaredMethod(GETINSTANCE_METHOD_NAME).invoke(null);
-            LOG.debug("Loaded serializer {} for class {}", obj, type);
+            LOG.trace("Loaded serializer {} for class {}", obj, type);
             return obj;
         }
 
@@ -135,6 +140,8 @@ abstract class AbstractStreamWriterGenerator extends AbstractGenerator implement
                 final String serializerName) throws CannotCompileException, IllegalAccessException,
                 IllegalArgumentException, InvocationTargetException, NoSuchMethodException, SecurityException,
                 NoSuchFieldException {
+            LOG.debug("generateSerializer() due to Cache miss: typeName={}, typeClassLoader={}, serializerName={}",
+                    type.getTypeName(), type.getClassLoader(), serializerName);
             final DataObjectSerializerSource source = generateEmitterSource(type, serializerName);
             final CtClass poolClass = generateEmitter0(type, source, serializerName);
             @SuppressWarnings("unchecked")