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 d8ade5e43954c887140b4a2a2a42833e5e8b7c70..325446040e5b7259972c6e1828c73bbc0cfaa8c1 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
@@ -83,7 +83,11 @@ abstract class AbstractStreamWriterGenerator extends AbstractGenerator implement
             };
             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
@@ -94,6 +98,7 @@ abstract class AbstractStreamWriterGenerator extends AbstractGenerator implement
     @Override
     public final void onBindingRuntimeContextUpdated(final BindingRuntimeContext runtime) {
         this.context = runtime;
+        LOG.debug("onBindingRuntimeContextUpdated() : {}", runtime);
     }
 
     @Override
@@ -130,7 +135,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;
         }
 
@@ -138,6 +143,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")