Java synchronized: just keep critical sections small?

Question

I'm doing some basic experiments to evaluate synchronized blocks' overhead. I'm quite perplexes about the results, hence the question.

In the code below, a number of threads test and increment a global counter (up to a goal number) in a so called critical section. Moreover, an additional configurable load of work can be executed inside or outside the critical section.

Playing with constants, particularly with LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION and LOAD_OF_WORK_INSIDE_CRITICAL_SECTION, what I'm observing is that the overhead introduced by the synchronized block can be appreciated only for big amounts of work INSIDE the critical section. See these two output examples:

Processors: 4
NUM_OF_THREADS: 4
LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION: 1000000
LOAD_OF_WORK_INSIDE_CRITICAL_SECTION: 100
NUM_OF_JOBS_GOAL: 10000
Non synchronized - Goal reached, elapsed time: 6370 milliseconds.
Synchronized - Goal reached, elapsed time: 6355 milliseconds.

and

Processors: 4
NUM_OF_THREADS: 4
LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION: 100
LOAD_OF_WORK_INSIDE_CRITICAL_SECTION: 1000000
NUM_OF_JOBS_GOAL: 10000
Non synchronized - Goal reached, elapsed time: 6351 milliseconds.
Synchronized - Goal reached, elapsed time: 18629 milliseconds.

As you can see, the synchronization overhead seems to happen only for high LOAD_OF_WORK_INSIDE_CRITICAL_SECTION. This is not confusing per se and, of course, confirms that keeping critical sections small is a good practice. But given that, for the good practice, it is uncommon to have big critical sections, this result clashes with the common opinion of avoiding the synchronized keyword in code as much as possible. I would say instead that synchronization keyword is always safe for small amount of work in the critical section.

So I'm afraid I'm doing something wrong, in my code or in my head. Could you please help me to clarify?

Below is the code I've used for testing. Thanks and sorry for my bad english.

Best Regards, John

OS: Windows 7 Java version: 1.7.0_67 (32 bit)

public class MainClass {

    public static void main(String[] args) throws Exception {

        long startMilliseconds = System.currentTimeMillis();
        final long NUM_OF_JOBS_GOAL = 10000L;
        final int LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION = 1000000;
        final int LOAD_OF_WORK_INSIDE_CRITICAL_SECTION = 100;
        final int NUM_OF_THREADS = Runtime.getRuntime().availableProcessors();

        System.out.println("Processors: " + Runtime.getRuntime().availableProcessors());
        System.out.println("NUM_OF_THREADS: " + NUM_OF_THREADS);
        System.out.println("LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION: " + LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION);
        System.out.println("LOAD_OF_WORK_INSIDE_CRITICAL_SECTION: " + LOAD_OF_WORK_INSIDE_CRITICAL_SECTION);
        System.out.println("NUM_OF_JOBS_GOAL: " + NUM_OF_JOBS_GOAL);

        doConcurrentJob(NUM_OF_THREADS, startMilliseconds, NUM_OF_JOBS_GOAL, LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION, LOAD_OF_WORK_INSIDE_CRITICAL_SECTION);

        //Reset state
        startMilliseconds = System.currentTimeMillis();
        CounterThread.goalGlobalCounter = 0;
        CounterThread.goalReached = false;

        doConcurrentSynchronizedJob(NUM_OF_THREADS, startMilliseconds, NUM_OF_JOBS_GOAL, LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION, LOAD_OF_WORK_INSIDE_CRITICAL_SECTION);

    }

    static void doConcurrentJob(int numOfThreads, long startMilliseconds, long numOfJobsGoal, int loadOfWorkOutsideCriticalSection, int loadOfWorkInsideCriticalSection) throws Exception {
        CounterThread[] counterThreads = new CounterThread[numOfThreads];
        while (!CounterThread.goalReached) {
            for (int i = 0; i < counterThreads.length; i++) {
                if (counterThreads[i] == null || !counterThreads[i].isAlive()) {
                    counterThreads[i] = new CounterThread(numOfJobsGoal, loadOfWorkOutsideCriticalSection, loadOfWorkInsideCriticalSection);
                    counterThreads[i].start();
                }
            }
        }
        System.out.println("Non synchronized - Goal reached, elapsed time: " + (System.currentTimeMillis() - startMilliseconds) + " milliseconds.");
        System.out.flush();
        for (int i = 0; i < counterThreads.length; i++) {
            counterThreads[i].join();
        }
    }

    static void doConcurrentSynchronizedJob(int numOfThreads, long startMilliseconds, long numOfJobsGoal, int loadOfWorkOutsideCriticalSection, int loadOfWorkInsideCriticalSection) throws Exception {
        CounterThreadSynchronized[] counterThreadsSyncronized = new CounterThreadSynchronized[numOfThreads];
        while (!CounterThread.goalReached) {
            for (int i = 0; i < counterThreadsSyncronized.length; i++) {
                if (counterThreadsSyncronized[i] == null || !counterThreadsSyncronized[i].isAlive()) {
                    counterThreadsSyncronized[i] = new CounterThreadSynchronized(startMilliseconds, numOfJobsGoal, loadOfWorkOutsideCriticalSection, loadOfWorkInsideCriticalSection);
                    counterThreadsSyncronized[i].start();
                }
            }
        }
        System.out.println("Synchronized - Goal reached, elapsed time: " + (System.currentTimeMillis() - startMilliseconds) + " milliseconds.");
        System.out.flush();
        for (int i = 0; i < counterThreadsSyncronized.length; i++) {
            counterThreadsSyncronized[i].join();
        }
    }
}

class CounterThread extends Thread {

    public static int goalGlobalCounter = 0;
    public static boolean goalReached;

    public final long GOAL;
    protected final int LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION;
    private final int LOAD_OF_WORK_INSIDE_CRITICAL_SECTION;

    protected int fooSpinner;

    public CounterThread(long numOfJobsGoal, int loadOfWorkOutsideCriticalSection, int loadOfWorkInsideCriticalSection) {
        this.GOAL = numOfJobsGoal;
        this.LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION = loadOfWorkOutsideCriticalSection;
        this.LOAD_OF_WORK_INSIDE_CRITICAL_SECTION = loadOfWorkInsideCriticalSection;
    }

    public void run() {
        for (long i = 0; i < LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION; i++) {
            fooSpinner++;
        }
        executeCriticalSection();
    }

    public void executeCriticalSection() {

        for (long i = 0; i < LOAD_OF_WORK_INSIDE_CRITICAL_SECTION; i++) {
            fooSpinner++;
        }
        if (goalGlobalCounter < GOAL) {
            goalGlobalCounter++;
        } else {
            goalReached = true;

        }
    }

}

class CounterThreadSynchronized extends CounterThread {

    protected static final Object globalMutex = new Object();

    public CounterThreadSynchronized(long startMilliseconds, long numOfJobsGoal, int loadOfWorkOutsideCriticalSection, int loadOfWorkInsideCriticalSection) {
        super(numOfJobsGoal, loadOfWorkOutsideCriticalSection, loadOfWorkInsideCriticalSection);
    }

    @Override
    public void run() {
        for (long i = 0; i < LOAD_OF_WORK_OUTSIDE_CRITICAL_SECTION; i++) {
            fooSpinner++;
        }
        synchronized (globalMutex) {
            executeCriticalSection();
        }
    }
}

EDIT

Mike Nakis: I've copy-pasted your code and don't have the same kind of results as yours. Below are the logs of 10 consecutive runs with TEST_DURATION = 1000.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  494682730
  10000  |      10  |    true   |  515156056
     10  |   10000  |   false   |  520437287
     10  |   10000  |    true   |  135192560
     10  |      10  |   false   |  499448540
     10  |      10  |    true   |   64254608
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  519790639
  10000  |      10  |    true   |  507597477
     10  |   10000  |   false   |  520784275
     10  |   10000  |    true   |  133563124
     10  |      10  |   false   |  510318548
     10  |      10  |    true   |   66006750
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  512302804
  10000  |      10  |    true   |  514999373
     10  |   10000  |   false   |  526430883
     10  |   10000  |    true   |  132596432
     10  |      10  |   false   |  506235601
     10  |      10  |    true   |   66220700
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  505257231
  10000  |      10  |    true   |  512668300
     10  |   10000  |   false   |  528309859
     10  |   10000  |    true   |  133947238
     10  |      10  |   false   |  518984983
     10  |      10  |    true   |   63617110
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  522235388
  10000  |      10  |    true   |  502896342
     10  |   10000  |   false   |  515668568
     10  |   10000  |    true   |  130705136
     10  |      10  |   false   |  514470943
     10  |      10  |    true   |   60617050
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  517828858
  10000  |      10  |    true   |  515355048
     10  |   10000  |   false   |  512963551
     10  |   10000  |    true   |  134235958
     10  |      10  |   false   |  515017236
     10  |      10  |    true   |   62228490
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  521690615
  10000  |      10  |    true   |  527830725
     10  |   10000  |   false   |  512735126
     10  |   10000  |    true   |  134278503
     10  |      10  |   false   |  507281283
     10  |      10  |    true   |   63333950
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  515604517
  10000  |      10  |    true   |  529685270
     10  |   10000  |   false   |  520260430
     10  |   10000  |    true   |  131993844
     10  |      10  |   false   |  505190996
     10  |      10  |    true   |   66865140
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  522747273
  10000  |      10  |    true   |  530824975
     10  |   10000  |   false   |  536263165
     10  |   10000  |    true   |  131938210
     10  |      10  |   false   |  502281027
     10  |      10  |    true   |   64480710
Done.

Processors: 4 Threads: 4
Outside  |  Inside  |  Locking  |  Work Done
  10000  |      10  |   false   |  523386208
  10000  |      10  |    true   |  511467042
     10  |   10000  |   false   |  512778324
     10  |   10000  |    true   |  133751262
     10  |      10  |   false   |  513257782
     10  |      10  |    true   |   61573350
Done.

As the title of my question suggests, I'm mainly interested in low "inside"/"outside" ratio, that is to say the first two configurations of the output. Looking at the output, can't honestly say that in any case locking is slower than non-locking.

Answer 1

It really depends because the definition of "small" is very different from problem to problem. Fortunately there's Amdahl's law to give you clarity on this.

Amdahl's law states that if P is the proportion of a program that can be made parallel, and (1 − P) is the proportion that cannot be parallelized, then the maximum speedup that can be achieved by using N processors is S(N) = 1 / ((1-P) + P/N)

"critical session" would constitute "proportion that cannot be parallelized", hence the longer you make it, the lower the potential throughput gain you could potentially achieve through parallelization.

In practice this isn't so clear cut. For example, the overhead of locking may be greater than the theoretical gain. For this reason, JVMs sometime perform "lock coarsening" which will actually make the critical section longer, but reduce the overall overhead.