Trying to debug why LRU swap can be stuck in livelock

[simantics/platform.git] / bundles / org.simantics.acorn / src / org / simantics / acorn / lru / LRU.java

diff --git a/bundles/org.simantics.acorn/src/org/simantics/acorn/lru/LRU.java b/bundles/org.simantics.acorn/src/org/simantics/acorn/lru/LRU.java
index 690ba426f209afd52035ac875530b1f7e2b3d763..205b79906d2d9acdf8da600669bbe2fa51d200fb 100644 (file)
--- a/bundles/org.simantics.acorn/src/org/simantics/acorn/lru/LRU.java
+++ b/bundles/org.simantics.acorn/src/org/simantics/acorn/lru/LRU.java
@@ -62,7 +62,7 @@ public class LRU<MapKey,MapValue extends LRUObject<MapKey, MapValue>> {
        public void acquireMutex() throws IllegalAcornStateException {
                try {
                        while(!mutex.tryAcquire(3, TimeUnit.SECONDS)) {
-                               System.err.println("Mutex is taking a long time to acquire - owner is " + mutexOwner);
+                               LOGGER.info("Mutex is taking a long time to acquire - owner is " + mutexOwner);
                        }
                        if(VERIFY)
                                mutexOwner = Thread.currentThread();
@@ -78,7 +78,7 @@ public class LRU<MapKey,MapValue extends LRUObject<MapKey, MapValue>> {
 
        public void shutdown() {
            if (GraphClientImpl2.DEBUG)
-               System.err.println("Shutting down LRU writers " + writers);
+               LOGGER.info("Shutting down LRU writers " + writers);
                writers.shutdown();
                try {
                        writers.awaitTermination(60, TimeUnit.SECONDS);
@@ -97,7 +97,7 @@ public class LRU<MapKey,MapValue extends LRUObject<MapKey, MapValue>> {
                        }
                });
                if (GraphClientImpl2.DEBUG)
-                   System.err.println("Resuming LRU writers " + writers);
+                   LOGGER.info("Resuming LRU writers " + writers);
        }
 
        /*
@@ -293,8 +293,19 @@ public class LRU<MapKey,MapValue extends LRUObject<MapKey, MapValue>> {
                        if(valueToSwap.tryAcquireMutex()) {
                                try {
                                        if(valueToSwap.canBePersisted()) {
-                                               valueToSwap.persist();
-                                               return true;
+                                               boolean persist = valueToSwap.persist();
+                                               if (!persist) {
+                                                       LOGGER.error("\n Somehow valueToSwap {} could not be persisted even though canBePersisted returned true\n", valueToSwap);
+                                                       LOGGER.error("priorityQueue.size() {}", priorityQueue.size());
+                                                       if (priorityQueue.size() > 0) {
+                                                               LOGGER.error("priorityQueue first entry {}", priorityQueue.entrySet().iterator().next());
+                                                       }
+                                                       LOGGER.error("map.size() {}", map.size());
+                                                       if (map.size() > 0) {
+                                                               LOGGER.error("map first entry {}", map.entrySet().iterator().next());
+                                                       }
+                                               }
+                                               return persist;
                                        }
                                } catch (Throwable t) {
                                        throw new IllegalAcornStateException(t);
@@ -556,18 +567,28 @@ public class LRU<MapKey,MapValue extends LRUObject<MapKey, MapValue>> {
                 boolean gotMutex = impl.tryAcquireMutex();
 
                 boolean done = false;
-                // TODO: fix this properly pleease
                 int count = 0;
+                long startTime = 0;
                 while (!done) {
 
                     if (gotMutex || borrowMutex) {
                         runWithMutex();
                         done = true;
                     } else {
-                        if (count % 100 == 0)
+                        if (count % 10 == 0) {
+                            // Taking too long, sleep for a while.
                             LOGGER.warn("Retry mutex acquire");
+                            try {
+                                Thread.sleep(10);
+                            } catch (InterruptedException e) {
+                            }
+                        }
                         gotMutex = impl.tryAcquireMutex();
-                        count++;
+                        long currentTime = System.currentTimeMillis();
+                        if ((currentTime - startTime) > 10) {
+                            startTime = currentTime;
+                            count++;
+                        }
                     }
 
                 }