3

I'm having a weird problem with some fairly simple Java code.

I have a class LicenseManager, which controls the licensing of a program, and can be controlled dynamically (new licenses can be issued on demand, etc). LicenseManager of course needs to be thread safe, as such, it uses a big lock. However it has one more lock that it uses around controlling apples, which I believe is somehow involved in this deadlock, but I can't really see how. The program also installs a logging handler to support an enterprise logging feature.

Just looking at the code of LicenseManager by itself, I can't see a single issue in it.

import java.util.logging.*;

public class Main {
    public static final LicenseManager licenseManager = new LicenseManager();

    static class LicenseManager {
        private static final Logger logger =
                Logger.getLogger(LicenseManager.class.getName());

        class InsufficientApplesException extends RuntimeException {};
        class InsufficientPiesException extends RuntimeException {};

        private int apples = 10;
        private int pies = 10;
        private boolean enterpriseLoggingEnabled = true;

        // Apples have high contention; so they get their own lock.
        private final Object appleLock = new Object();

        void useApple() {
            checkExpired();
            synchronized (appleLock) {
                logger.info("Using apple. Apples left: " + apples);
                if (apples == 0) throw new InsufficientApplesException();
                apples--;
            }
        }

        /* Examples. There are lots of other operations like this
         * on LicenseManager. We don't have time to prove that
         * they are commutative, so we just use the main object lock
         * around them all. The exception is when we find one with high
         * contention, for example apples. */
        synchronized void usePear() {checkExpired(); /*...*/}
        synchronized void checkExpired() {}

        synchronized void usePie() {
            checkExpired();
            logger.info("Using pie. Pies left: " + pies);
            if (pies == 0) throw new InsufficientPiesException();
            boolean reallyCanUsePie = true; // do expensive pie computation
            if (reallyCanUsePie) {
                useApple(); /* using a pie requires an apple.
                             * TODO: stop putting apples in the pumpkin pie */
                pies--;
            }
        }

        synchronized boolean isEnterpriseLoggingEnabled() {
            return enterpriseLoggingEnabled;
        }
    }

    public static void main(String[] args) {
        // Install enterprise log handler on the root logger
        Logger.getLogger("").addHandler(new Handler() {
            @Override
            public void publish(LogRecord lr) {
                if (licenseManager.isEnterpriseLoggingEnabled())
                    System.out.println("ENTERPRISE ALERT! [" 
                            + lr.getLevel() + "] " + lr.getMessage());
            }
            @Override public void flush() {}
            @Override public void close() throws SecurityException {}
        });

        // Simulate fat user
        new Thread() {
            @Override
            public void run() {
                while (true) {
                    licenseManager.usePie();
                }
            }
        }.start();

        // Simulate fat albeit healthy user
        while (true) {
            licenseManager.useApple();
        }
    }
}

And when I run it:

$ java Main
Apr 25, 2013 3:23:19 PM Main$LicenseManager useApple
INFO: Using apple. Apples left: 10
Apr 25, 2013 3:23:19 PM Main$LicenseManager usePie
INFO: Using pie. Pies left: 10
ENTERPRISE ALERT! [INFO] Using pie. Pies left: 10

You'd expect the pie eaters to both die from running out of pies, but instead both threads deadlock.

Interestingly, removing the logging line in useApple (logger.info("Using apple. Apples left: " + apples);) makes the deadlock not happen (you don't see the log spammed with "using pie", because all the apples so happened to be gone before any pie could be used):

$ java Main
Exception in thread "main" Main$LicenseManager$InsufficientApplesException
    at Main$LicenseManager.useApple(Main.java:24)
    at Main.main(Main.java:79)
Apr 25, 2013 3:23:42 PM Main$LicenseManager usePie
INFO: Using pie. Pies left: 10
ENTERPRISE ALERT! [INFO] Using pie. Pies left: 10
Exception in thread "Thread-1" Main$LicenseManager$InsufficientApplesException
    at Main$LicenseManager.useApple(Main.java:24)
    at Main$LicenseManager.usePie(Main.java:43)
    at Main$2.run(Main.java:72)

Why? How can I fix this without removing the logging?

Dog
  • 7,707
  • 8
  • 40
  • 74
  • Do they really deadlock or do they spin? You've seen deadlock in the stacks traces? – Gray Apr 25 '13 at 21:43
  • Have you tried inserting a little `Thread.sleep()` in your `while(true)`s ? – Fildor Apr 25 '13 at 21:43
  • FYI: The logger may have a synchronized `PrintStream` under the covers which would change the synchronization pattern of your program. – Gray Apr 25 '13 at 21:44
  • If there is a deadlock then somewhere inside of the `synchronized (appleLock)` you must lock your `Main` class with a call to a `synchronized static` method. Any idea if that is being done? – Gray Apr 25 '13 at 21:48
  • did you try some thread monitoring from inside visualvm to see which thread holds which monitor/lock? – Ralf H Apr 25 '13 at 21:50
  • @Gray, I assume it's a deadlock because the VM is using no CPU. – Dog Apr 25 '13 at 23:34

3 Answers3

2

They get into a deadlock because the main thread (the one eating apples) owns the appleLock and is trying to access the synchronized isEnterpriseLoggingEnabled() method and the child thread (the one eating pies) owns the licenseManager object and calls useApple() inside of usePie() (and thus needs appleLock).

The deadlock doesn't happen without the Logger statement because it no longer has to call a synchronized method within licenseManager after taking the appleLock

You can probably fix this by making isEnterpriseLoggingEnabled not synchronized

durron597
  • 31,968
  • 17
  • 99
  • 158
  • `useApple` only accesses the `licenseManager` lock via `checkExpired()`, then **releases** it, then gets `appleLock`, wherein it doesn't do anything that locks `licenseManager`. – Dog Apr 25 '13 at 23:50
  • @Dog I tested this using a debugger. I am 100% sure my answer is what happens. – durron597 Apr 26 '13 at 03:07
  • How can deadlock happen if there is no logging in `useApple`? I think the deadlock is caused by the logging in `useApple`, since it calls the handler which calls back `isEnterpriseLoggingEnabled`, which makes it try to get both locks at once. – Dog Apr 26 '13 at 16:53
  • Oh I didn't notice your edit. Any clue how to fix this without removing the logging? – Dog Apr 26 '13 at 17:18
2

The problem is that your log.info() calls ends up in the Handler's publish() method where licenseManager.isEnterpriseLoggingEnabled() needs a lock on the licenseManager.

So this code can't complete:

   synchronized (appleLock) {
       //this line requires a lock on license manager, and this lock is not 
       //available because is hold by the other thread waiting to get the appleLock
       logger.info("Using apple. Apples left: " + apples);

       if (apples == 0) throw new InsufficientApplesException();
       apples--;
  }

One easy way to get rid of the deadlock is to remove the synchronization on isEnterpriseLoggingEnabled() method. It doesn't seem to be needed as enterpriseLoggingEnabled property is readonly.

dcernahoschi
  • 14,968
  • 5
  • 37
  • 59
  • wait... so the log handler callback is done on the same thread as the `log.info()` call?!? – Dog Apr 26 '13 at 14:23
  • Yeah, it makes sense, why wasting a thread or making a context switch just this ... – dcernahoschi Apr 26 '13 at 14:47
  • Yep, seems they are in the same thread: https://ideone.com/Z6Dqgr . I was thinking the logging stuff in Java has one thread with a queue that all logs go to, and then the handlers would be ran in that one thread. I guess I thought this because the docs for `Logger` say it's thread safe. Is it documented somewhere whether the handlers are called in the same thread? How can I fix my code without removing the logging? – Dog Apr 26 '13 at 16:46
  • `isEnterpriseLoggingEnabled` needs a lock because it's called by multiple threads. I'd like to not remove/split any more locks because it would make the code harder to reason about (The whole reason this problem happened in the first place was because I split the big lock into two locks) – Dog Apr 26 '13 at 17:50
  • Yes, but the value of `enterpriseLoggingEnabled` is always true, you never change it at runtime. No need for synchronization in this case. – dcernahoschi Apr 26 '13 at 17:59
  • Yeah I didn't post the full code, but either way it would be a data race unless that variable was final (example: http://stackoverflow.com/questions/16178020/uninitialized-object-leaked-to-another-thread-despite-no-code-explicitly-leaking). I guess I could just make it always return true, or give it its own lock. – Dog Apr 26 '13 at 18:17
1

Why this happens:

you have a lot of synchronized methods. but they all synchronize on one monitor - youк instance of Main, so you deadlock yourself by calling 2 of the methods simultaneously. To sort it all out you have to make separate monitors (lock objects) for different parts of your code. You do have separate lock for apples (appleLock), but still synchronize above it on Main instance for whatever reason.

Why you don't need sync on isEnterpriseLoggingEnabled():

Despite having contention, if you do not set it like enterpriseLoggingEnabled=!enterpriseLoggingEnabled;, it is ok to not sync. You just have to update the value on read. To do it, make enterpriseLoggingEnabled volatile. This should eliminate unnecessary lock and the whole lock problem. If you really need the lock here or in another method that contents with the aplle consumers, make a separate lock for it. Maybe a ReentrantLock.

Imaskar
  • 2,773
  • 24
  • 35