Wednesday 18 April 2018

Performance Conscious Logging

There are few things to consider when you decide your logging philosophy to make it performance conscious. First let us breakdown the resources spent on logging.

  • CPU time spent on writing to the destination (I/O), can be file, console, network etc.
  • CPU time spent on appending or assembling a particular log line & garbage collection
  • Working memory spent on appending or assembling a particular log line
  • Wall time spent on waiting or fighting on a shared resource or shared destination. This may be a file on disk or a synchronous method inside the logging framework.
  • Disk space or any other storage occupied to persist the log file
Following are the things that you can do to minimize the above.
  • Have controls over logging. Have proper log levels so can only INFO,WARN,ERROR will be used in production, and DEBUG, TRACE will be used in development. Most importantly levels should not control writing the logs to the destination, but it should also control assembling log lines as well. To achieve this, use parameterized logging ( https://www.slf4j.org/faq.html#logging_performance ) or simply check the log level is enabled before assembling the log line. Using a lambda is an alternative as well.
  • Avoid costly formatting. If pretty printing is needed write a log extraction tool convert raw log lines to pretty log lines, which will happen offline, and on demand. There are lot of useful things that can be easily done if the logs are forwarded a tool like Splunk or ElasticSearch.
  • Minimize log size. Use shorthand codes to minimize the size of a log lines while preserving the readability.
  • Minimize log frequency. When deciding to log something, roughly estimate on how much log size/transaction or how many log lines/ transaction. If it is more than 1:100, then that is too much logging, well it depends.
  • Try asynchronous logging. In other words do not write to the destination (I/O) in the transaction thread, rather add it to a buffer and tackle it in the background. RandomAccessFileAppender is such facility provided by Log4J
  • Divide and conquer. Have the logs segmented. Later in production, this can be used to spread the load on destinations (I/O) by having different destinations (files) for different logs




Sunday 8 December 2013

Java ConcurrentList

Recently I was looking for a efficient and thread safe List implementation within the JDK 6. After having a look at the source, I was not satisfied with the available implementations like,
  • java.util.Vector 
  • java.util.Collections.synchronizedList()   
This was mainly due to the fact that both of these implementations makes both read ( get ) and write ( set ) operations to the List object critical by gaining the object level lock, which is unnecessary. So I looked for the implementations given in java.concurrent package. I was looking for something like "ConcurrentList"  like the "Concurrent Map", however, what I found was "CopyOnWriteArrayList". 

CopyOnWriteArrayList has a performance drawback because it creates a copy of the underlying array of the list on write operations. The array copying is making the write operations slow and it looks disadvantageous in the point of view of memory usage as well. Having said that, CopyOnWriteArrayList looks advantageous for a usage of a List with high read rate and low write rate.      

Eventually I started coding my own implementation using the java.util.concurrent.locks,ReadWriteLock. I did my implementation simply by maintaining object level ReadWriteLock instance, and gaining the read lock in the read operations and gaining the write lock in the write operations. The code looks like this.

public class ConcurrentList< T > implements List< T >
{
    private final ReadWriteLock  readWriteLock = new ReentrantReadWriteLock();
    private final List< T > list;

    public ConcurrentList( List<T> list )
    {
        this.list = list;
    }

    public boolean remove( Object o )
    {
        readWriteLock.writeLock().lock();
        boolean ret;
        try
        {
            ret = list.remove( o );
        }
        finally
        {
            readWriteLock.writeLock().unlock();
        }
        return ret;
    }

    public boolean add( T t )
    {
        readWriteLock.writeLock().lock();
        boolean ret;
        try
        {
            ret = list.add( t );
        }
        finally
        {
            readWriteLock.writeLock().unlock();
        }
        return ret;
    }

    public void clear()
    {
        readWriteLock.writeLock().lock();
        try
        {
            list.clear();
        }
        finally
        {
            readWriteLock.writeLock().unlock();
        }
    }


    public int size()
    {
        readWriteLock.readLock().lock();
        try
        {
            return list.size();
        }
        finally
        {
            readWriteLock.readLock().unlock();
        }
    }

    public boolean isEmpty()
    {
        readWriteLock.readLock().lock();
        try
        {
            return list.isEmpty();
        }
        finally
        {
            readWriteLock.readLock().unlock();
        }
    }

    public boolean contains( Object o )
    {
        readWriteLock.readLock().lock();
        try
        {
            return list.contains( o );
        }
        finally
        {
            readWriteLock.readLock().unlock();
        }
    }

    public T get( int index )
    {
        readWriteLock.readLock().lock();
        try
        {
            return list.get( index );
        }
        finally
        {
            readWriteLock.readLock().unlock();
        }
    }

    public int indexOf( Object o )
    {
        readWriteLock.readLock().lock();
        try
        {
            return list.indexOf( o );
        }
        finally
        {
            readWriteLock.readLock().unlock();
        }
    }

//etc
}

Well, obviously, I had to avoid ConcurrentModificationException when using Iterator. When one thread is Iterating over an ArrayList and any other thread does a write operation then the above Exception is thrown. For that I did like this.

public Iterator<T> iterator()
    {
        readWriteLock.readLock().lock();
        try
        {
            return new ArrayList<T>( list ).iterator();
        }
        finally
        {
            readWriteLock.readLock().unlock();
        }
    }

I just created a copy of the current array list and returned the iterator of that. This means this list does not return and Iterator which can modify the original List. Well, for me, this is o.k. for the moment, and may be looking forward to resolve this in future.     

Irrespective of above point, the performance improvement observed was notable.

Total time taken for 5000 reads + 5000 write by 10 threads were
ArrayList - 16450 ns( not thread safe)
ConcurrentList - 20999 ns
Vector -35696 ns
CopyOnWriteArrayList - 197032 ns

My simple test case looks like this

final List<Object> concurrentList = new -- Concrete Type --;

        for( int i = 0; i < 5; i++ )
        {
            Runnable reader = new Runnable()
            {
                public void run()
                {
                    System.out.println( "reader started " );
                    long time = 0;

                    for( int i = 0; i < 1000; i++ )
                    {
                        long n1 = System.nanoTime();
                        concurrentList.size();
                        time =+ System.nanoTime() - n1;

                        try
                        {
                            Thread.sleep( 50 );
                        }
                        catch( InterruptedException e )
                        {
                            e.printStackTrace();
                        }
                    }

                    System.out.println( "reader = " + time);
                }

            };

            new Thread( reader ).start();
        }

        for( int i = 0; i < 5; i++ )
        {
            Runnable writer = new Runnable()
            {
                public void run()
                {
                    System.out.println( "writer started " );
                    long time = 0;

                    for( int i = 0; i < 1000; i++ )
                    {
                        long n1 = System.nanoTime();
                        concurrentList.add( new Object() );
                        time =+ System.nanoTime() - n1;

                        try
                        {
                            Thread.sleep( 50 );
                        }
                        catch( InterruptedException e )
                        {
                            e.printStackTrace();
                        }

                    }

                    System.out.println( "writer = " + time);
                }
            };

            new Thread( writer ).start();
        }