Java: counting/profiling synchronization calls

Question

I am searching for a way to list all synchronization calls of a running parallel java application, in order to detect scalability problems (in terms of threads/cores). To my understanding, each time a synchronized block is entered, the machine needs to synchronize caches. This affects all CPUs running (in several ways, like memory bandwidth), even if the running tasks are not blocked by entering a synchronized region.

The setting:

I have a large application that is parallelized on a higher level, i.e. it has complex tasks that are executed in parallel. The parallelization works in the term, that all cores are under load and i have no blocked threads. Still the performance is not scaling with the cores, which may have several reasons. The particular possible reason I am interested in, is if there are a lot of synchronization calls (e.g. entering a synchronized block, using a lock, etc).

The Task

I would like to find out which places in my code (that are actually executed) have such a synchronization call and how often each synchronization is actually performed. There are many referenced libraries, therefore it is not possible to just use a regular code search on the synchronized keyword or something like that, becuase this will search a lot of never executed code and bring up a lot of false positives. The perfect solution would be to have a profiler, that lists all executed synchronization places and the number of calls. However, the profilers i tried out only allow method calls to be counted. Therefore, the problem here is to find all methods, that are actually relevant.

Alternatively, it would also help if i can just find the synchronization places referenced by some entry point (main method). I.e. by recursively going through the code and check all referenced methods, classes, etc for such synchronization. In this case it would be possible to find out the frequency later by using a regular profiler.

The Question

Are there tools or workflows, that are able to archive the task above for a larger project.

THX in advance for your answers.

Answer 1

You can use a CPU profiler to do this. If you have a synchronized method which is taking a long time to get a lock it will appear to be taking a long time. If it is not taking a long time, you shouldn't care about it.

Now, if a method is taking a long time, it might not be clear as to whether it is the synchronized lock or not. If you really can't tell run reading the code, you can have the implementation moved to a private method and all the public method does is acquire the lock. This will make it much clearer as to whether the delay is in obtaining the lock or running the code.

Another reason to use a profiler; when you guess at what the problem might be, it is almost never what you first thought, even if you have been performance tuning Java programs for ten years, what you think of first might be in the top 5 or top 10 but is rarely the biggest problem you have.

Answer 2

Entering and leaving synchronized block is rather cheap operation unless there is a contention on this block. In uncontended case synchronized is just an atomic CAS or almost a no-op if UseBiasedLocking optimization succeeds. Though it looks possible to do a synchronization profiler using Instrumentation API, this won't make much sense.

The problem for multithreaded application is a contended synchronization. JVM has some internal counters to monitor lock contention (see this question). Or you can even write a simple ad-hoc tool to track all contended locks using JVMTI events.

However, not only locks can cause contention. Even non-blocking algorithms can suffer from competition for a shared resource. Here is a good example of such scalability problem. So, I would agree with @PeterLawrey that it's better to start with CPU profiler as it is usually more handy in finding performance problems.

Answer 3

It's a java application so you can use jdk tools in jdk1.8.XX.XX\bin. With visualVM or jmc (java mission control) you can visualize threads, lock. And you can add logs in the application (log4j or other tool) to count execution time.

Answer 4

The follow very simple sample show that synchronized with a single monitor can cost some time also in single thread algorithm. It show that the synchronized BufferedOutputStream in this sample is approximate 1/4 slower. It streamed 100 MB to a nop stream. More complex code can produce more performance decrements.

import java.io.BufferedOutputStream;
import java.io.IOException;
import java.io.OutputStream;

public class BenchmarkTest {

    public static void main( String[] args ) throws IOException {
        while( true ) {
//            testNop();
            testSync();
            testNoSync();
        }
    }

    static void testNop() throws IOException {
        BenchmarkTest test = new BenchmarkTest();
        test.out = new OutputStream() {
            @Override
            public void write( int b ) throws IOException {
                // nop
            }
        };
        test.run( "            nop OutputStream" );
    }

    static void testSync() throws IOException {
        BenchmarkTest test = new BenchmarkTest();
        test.out = new BufferedOutputStream( new OutputStream() {
            @Override
            public void write( int b ) throws IOException {
                // nop
            }
        }, 32768 );
        test.run( "   sync BufferedOutputStream" );
    }

    static void testNoSync() throws IOException {
        BenchmarkTest test = new BenchmarkTest();
        test.out = new FastBufferedOutputStream( new OutputStream() {
            @Override
            public void write( int b ) throws IOException {
                // nop
            }
        }, 32768 );
        test.run( "no sync BufferedOutputStream" );
    }

    private OutputStream out;

    void run( String testName ) throws IOException {
        long time = System.currentTimeMillis();
        for( int i = 0; i < 100_000_000; i++ ) {
            out.write( i );
        }
        System.out.println( testName + " time: " + (System.currentTimeMillis() - time) );
    }

    static public class FastBufferedOutputStream extends OutputStream {
        private byte[]       buf;

        private int          count;

        private OutputStream out;

        /**
         * Creates a BufferedOutputStream without synchronized.
         *
         * @param out the underlying output stream.
         */
        public FastBufferedOutputStream( OutputStream out ) {
            this( out, 8192 );
        }

        /**
         * Creates a BufferedOutputStream without synchronized.
         *
         * @param out the underlying output stream.
         * @param size the buffer size.
         * @exception IllegalArgumentException if size &lt;= 0.
         */
        public FastBufferedOutputStream( OutputStream out, int size ) {
            this.out = out;
            this.buf = new byte[size];
        }

        /**
         * Flush the internal buffer
         * 
         * @throws IOException if any I/O error occur
         */
        private void flushBuffer() throws IOException {
            if( count > 0 ) {
                out.write( buf, 0, count );
                count = 0;
            }
        }

        /**
         * {@inheritDoc}
         */
        @Override
        public void write( int b ) throws IOException {
            if( count >= buf.length ) {
                flushBuffer();
            }
            buf[count++] = (byte)b;
        }

        /**
         * {@inheritDoc}
         */
        @Override
        public void write( byte[] b, int off, int len ) throws IOException {
            if( len >= buf.length ) {
                /* If the request length exceeds the size of the output buffer,
                   flush the output buffer and then write the data directly.
                   In this way buffered streams will cascade harmlessly. */
                flushBuffer();
                out.write( b, off, len );
                return;
            }
            if( len > buf.length - count ) {
                flushBuffer();
            }
            System.arraycopy( b, off, buf, count, len );
            count += len;
        }

        /**
         * {@inheritDoc}
         */
        @Override
        public void flush() throws IOException {
            flushBuffer();
            out.flush();
        }

        /**
         * {@inheritDoc}
         */
        @Override
        public void close() throws IOException {
            flushBuffer();
            out.close();
        }
    }
}