Debug Java Application Issues – Part -2 (Issue Debugging – Application Unresponsive)

In last blog we learned about diff. thread states in java, in this blog we will understand how to use that knowledge to debug application issues using fasthreadanalyzer tool.

Lets take one type of issue we see with Java Applications:

Application Unresponsive Issue

When we say application in unresponsive<it can mean different things to diff. people>, here we mean that application is not responding to external api calls.

Lets take an example of a Spring Boot application not responding to the Http API Calls. There can be several reasons to it:

  • Total Http Thread in tomcat (or whatever container spring is using) are consumed
    • Causes :
      • It could be because of some high cpu consuming work is done in those threads and all those threads are stuck doing that work <now to connect with thread states – those threads consuming cpu would be in RUNNABLE state , so we should be looking for lots of RUNNABLE state thread in the jstack>
      • It could be because of those threads are waiting on some external IO <now to connect with thread states – those threads are logically stuck on some IO to complete, means those threads would be in WAITING/BLOCKED state, we should be looking for threads with such states>
    • How to debug via jstack:
      • Take multiple jstacks
      • Now in every jstack to understand the what diff. thread are doing in which states they are stuck we will use the tool https://fastthreadanalyzer.com/. Just upload your jstack in this tool.
      • They will show you a table like this <thread group (generally http threads are part of group names http-bio-443-exec) vs count (total count of threads in this group) vs thread states(count of each thread state for these threads)>:

Now to make sense of the information above we will first see whether our http threads are available or not

  • if thread count on tool and thread count configured in tomcat.conf (or any other container configuration) ir equal to max thread count , that means all http threads are doing something and new requests cannot be processed
    • Yes
      • Now if stuck we will see what they are doing by seeing their thread states if most of them on running
        • means something in you application is taking long time to complete or system is bombarded with many http calls
      • Now if you see these threads are stuck on waiting/timed waiting/blocked that means most probably these threads are doing some IO and waiting on it
    • No
      • Some other issue may be related to JVM

Now to dig further exactly where the threads are waiting or stuck , you can click on the corresponding thread group and system will show what those threads are doing group by similar stack and their thread state, eg:

Now you can see the threads grouped by State and Stack , using this information you can figure out which service in the application is actually consuming the threads.

There could be many other reasons like JVM stuck , machine unresponsive we are not going in detail for them.

With the fast thread tool you can debug many such issues, we will cover more diff. type of issues in future posts.

Debug Java Application Issues – Part -1 (Understand Java Thread States)

The purpose of this blog series is to learn how to debug your java application issues, for this firstly we will understand what different thread states are there.

Lets understand what all are the different states of java stack :

In the above diagram you can 6 states of Java Thread:

  • New : When a new thread is created, it is in the new state. The thread has not yet started to run when thread is in this state. When a thread lies in the new state, it’s code is yet to be run and hasn’t started to execute.
  • Runnable/Running : A thread that is ready to run is moved to runnable state. In this state, a thread might actually be running or it might be ready run at any instant of time. It is the responsibility of the thread scheduler to give the thread, time to run. A multi-threaded program allocates a fixed amount of time to each individual thread. Each and every thread runs for a short while and then pauses and relinquishes the CPU to another thread, so that other threads can get a chance to run. When this happens, all such threads that are ready to run, waiting for the CPU and the currently running thread lies in runnable state.
  • Timed Waiting : A thread lies in timed waiting state when it calls a method with a time out parameter. A thread lies in this state until the timeout is completed or until a notification is received. For example, when a thread calls sleep or a conditional wait, it is moved to a timed waiting state.
  • Waiting : A thread is in the waiting state when it waits for another thread on a condition. When this condition is fulfilled, the scheduler is notified and the waiting thread is moved to runnable state.
  • Blocked : A thread is in the blocked state when it tries to access a protected section of code that is currently locked by some other thread. When the protected section is unlocked, the schedule picks one of the thread which is blocked for that section and moves it to the runnable state. A thread in this state cannot continue its execution any further until it is moved to runnable state. Any thread in these states does not consume any CPU cycle.
  • Terminated : A thread terminates because of either of the following reasons:
    • Because it exists normally. This happens when the code of thread has entirely executed by the program.
    • Because there occurred some unusual erroneous event, like segmentation fault or an unhandled exception.

Sample Code for creating threads with diff. thread states:

public class ThreadStatesDemo {

    public static class WaitingThread extends Thread {
        @Override
        public void run() {
            Object o = new Object();
            try {
                synchronized (o) {
                    o.wait();
                }
            } catch (InterruptedException e) {
            }
        }
    }

    public static class SleepingThread extends Thread {
        @Override
        public void run() {
            try {
                Thread.sleep(100000);
            } catch (InterruptedException e) {
            }
        }
    }

    public static class RunningThread extends Thread {
        @Override
        public void run() {
            for (int i = 1; i > 0;) {

            }
        }
    }

    public static class TimedWaitingThread extends Thread {
        @Override
        public void run() {
            Object o = new Object();
            try {
                synchronized (o) {
                    o.wait(100000);
                }

            } catch (InterruptedException e) {
            }
        }
    }

    public static Integer mutex = 0;

    public static class BlockedThread extends Thread {
        @Override
        public void run() {
            try {
                Thread.sleep(1000);
                synchronized (mutex) {

                }
            } catch (InterruptedException e) {
            }

        }
    }

    public static class BlockingThread extends Thread {
        @Override
        public void run() {
            synchronized (mutex) {
                for (int i = 1; i > 0;) {

                }
            }
        }
    }

    public static void main(String[] args) {
        Thread wTh = new WaitingThread();
        wTh.setName("waiting");
        wTh.start();
        Thread sTh = new SleepingThread();
        sTh.setName("sleeping");
        sTh.start();

        Thread rTh = new RunningThread();
        rTh.setName("running");
        rTh.start();
        Thread twTh = new TimedWaitingThread();
        twTh.setName("timed waiting");
        twTh.start();
        Thread bldTh = new BlockedThread();
        bldTh.setName("blocked");
        bldTh.start();
        Thread blcTh = new BlockingThread();
        blcTh.setName("blocking");
        blcTh.start();

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

}

When you will run the application , and take a jstack via jstack command , you will get some output like: this:

#command to take jstack 

jstack -l <pid>


2021-10-18 17:20:34
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.221-b11 mixed mode):



"blocking" #15 prio=5 os_prio=0 tid=0x00007f1ee411e800 nid=0xc99 runnable [0x00007f1eae09d000]
   java.lang.Thread.State: RUNNABLE
        at ThreadStatesDemo$BlockingThread.run(ThreadStatesDemo.java:69)
        - locked <0x000000076e5c0bb0> (a java.lang.Integer)

   Locked ownable synchronizers:
        - None

"blocked" #14 prio=5 os_prio=0 tid=0x00007f1ee411c800 nid=0xc98 waiting for monitor entry [0x00007f1eae19e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at ThreadStatesDemo$BlockedThread.run(ThreadStatesDemo.java:56)
        - waiting to lock <0x000000076e5c0bb0> (a java.lang.Integer)

   Locked ownable synchronizers:
        - None

"timed waiting" #13 prio=5 os_prio=0 tid=0x00007f1ee411b000 nid=0xc97 in Object.wait() [0x00007f1eae29f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000076e938550> (a java.lang.Object)
        at ThreadStatesDemo$TimedWaitingThread.run(ThreadStatesDemo.java:41)
        - locked <0x000000076e938550> (a java.lang.Object)

   Locked ownable synchronizers:
        - None

"running" #12 prio=5 os_prio=0 tid=0x00007f1ee4119000 nid=0xc96 runnable [0x00007f1eae3a0000]
   java.lang.Thread.State: RUNNABLE
        at ThreadStatesDemo$RunningThread.run(ThreadStatesDemo.java:29)

   Locked ownable synchronizers:
        - None

"sleeping" #11 prio=5 os_prio=0 tid=0x00007f1ee4117000 nid=0xc95 waiting on condition [0x00007f1eae4a1000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at ThreadStatesDemo$SleepingThread.run(ThreadStatesDemo.java:20)

   Locked ownable synchronizers:
        - None

"waiting" #10 prio=5 os_prio=0 tid=0x00007f1ee4115800 nid=0xc94 in Object.wait() [0x00007f1eae5a2000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x000000076e7fae38> (a java.lang.Object)
        at java.lang.Object.wait(Object.java:502)
        at ThreadStatesDemo$WaitingThread.run(ThreadStatesDemo.java:9)
        - locked <0x000000076e7fae38> (a java.lang.Object)

   Locked ownable synchronizers:
        - None

Now in this stack trace you can see the Thread State via the line:

java.lang.Thread.State: <THREAD STATE>

eg:

java.lang.Thread.State: WAITING (on object monitor)

In the code to create various Thread States a thread a created for each state or multiple thread for same state<representing how a particular thread state is reached>.

Let’s see:

  • Thread State RUNNABLE – a thread with code wise just working in a single loop.
  • Thread State WAITING – a thread with name waiting and code wise called wait() on a Object.
  • Thread State BLOCKED – a thread with name blocked and code wise trying to get into synchronized block on a Object whose lock is already taken by thread with name blocking <blocking thread almost always take the lock first because of sleep in Blocked Thread>
  • Thread State TIMED_WAITING – a thread with name timed_waiting and code wise called wait() with time<100000> on a Object and a thread with name sleeping and code wise called sleep on Thread Object.

Now i think you got an understanding of what all java thread states are there and how thread can end up in such state, there are more ways also apart from them.

Bulk Updation/Insertion of Database Tables in Java using Hibernate – Optimized Way

Hibernate is the most popular orm framework used to interact with databases in java . In this article  we will see what are the various ways using which bulk selection and updation in any table can be done and what is the most effective way when using the hibernate framework in java . 

I  experimented with three ways which are as follows : 

  • Using Hibernate’s Query.list() method.
  • Using ScrollableResults with FORWARD_ONLY scroll mode.
  • Using ScrollableResults with FORWARD_ONLY scroll mode in a StatelessSession.

To decide which one gives best performance for our use case, following tests i performed using the above three ways listed.

  • Select and update 1000 rows.

Let’s see the Code and results by applying above three ways to the operation stated above one by one. 

Using Hibernate’s Query.list() method.

Code Executed : 

   List rows;
        Session session = getSession();
        Transaction transaction = session.beginTransaction();
        try {
            Query query = session.createQuery("FROM PersonEntity WHERE id > :maxId ORDER BY id").setParameter("maxId",
                    MAX_ID_VALUE);
            query.setMaxResults(1000);
            rows = query.list();
            int count = 0;
            for (Object row : rows) {
                PersonEntity personEntity = (PersonEntity) row;
                personEntity.setName(randomAlphaNumeric(30));
                session.saveOrUpdate(personEntity);
                //Always flush and clear the session after updating 50(jdbc_batch_size specified in hibernate.properties) rows
                if (++count % 50 == 0) {
                    session.flush();
                    session.clear();
                }
            }
        } finally {
            if (session != null && session.isOpen()) {
                transaction.commit();
                session.close();
            }
        }

Tests Results : 

  • Time taken:- 360s to 400s
  • Heap Pattern:- gradually increased from 13m to 51m(from jconsole). 

Using ScrollableResults with FORWARD_ONLY scroll mode.

With this we are expecting that it should consume less memory that the 1st approach . Let’s see the results 

Code Executed : 

Session session = getSession();
        Transaction transaction = session.beginTransaction();
        ScrollableResults scrollableResults = session
                .createQuery("FROM PersonEntity WHERE id > " + MAX_ID_VALUE + " ORDER BY id")
                .setMaxResults(1000).scroll(ScrollMode.FORWARD_ONLY);
        int count = 0;
        try {
            while (scrollableResults.next()) {
                PersonEntity personEntity = (PersonEntity) scrollableResults.get(0);
                personEntity.setName(randomAlphaNumeric(30));
                session.saveOrUpdate(personEntity);
                if (++count % 50 == 0) {
                    session.flush();
                    session.clear();
                }
            }
        } finally {
            if (session != null && session.isOpen()) {
                transaction.commit();
                session.close();
            }
        }

Tests Results : 

  • Time taken:- 185s to 200s
  • Heap Pattern:- gradually increased from 13mb to 41mb (measured same using jconsole)

Using ScrollableResults with FORWARD_ONLY scroll mode in a StatelessSession.

A stateless session does not implement a first-level cache nor interact with any second-level cache, nor does it implement transactional write-behind or automatic dirty checking, nor do operations cascade to associated instances. Collections are ignored by a stateless session. Operations performed via a stateless session bypass Hibernate’s event model and interceptors.   

These type of session is always recommended in case of bulk updation as we really do not need these overheads of hibernate features in these type of usecases . 

Code Executed : 

 StatelessSession session = getStatelessSession();
        Transaction transaction = session.beginTransaction();
        ScrollableResults scrollableResults = session
                .createQuery("FROM PersonEntity WHERE id > " + MAX_ID_VALUE + " ORDER BY id")
                .setMaxResults(TRANSACTION_BATCH_SIZE).scroll(ScrollMode.FORWARD_ONLY);
        try {
            while (scrollableResults.next()) {
                PersonEntity personEntity = (PersonEntity) scrollableResults.get(0);
                personEntity.setName(randomAlphaNumeric(20));
                session.update(personEntity);
            }
        } finally {
            if (session != null && session.isOpen()) {
                transaction.commit();
                session.close();
            }
        }

Tests Results : 

  • Time taken:- 185s to 200s
  • Heap Pattern:- gradually increased from 13mb to 39mb

I also performed the same tests with 2000 rows and the results obtained were as follows:-

Results:-

  • Using list():- time taken:- approx 750s, heap pattern:- gradually increased from 13mb to 74 mb
  • Using ScrollableResultSet:- time taken:- approx 380s, heap pattern:- gradually increased from 13mb to 46mb
  • Using Stateless:- time taken:- approx 380s, heap pattern:- gradually increased from 13mb to 43mb

Blocker Problem with all above approaches Tried

ScrollableResults and Stateless ScrollableResults give almost the same performance which is much better than Query.list(). But there is still one problem with all the above approaches. Locking, all the above approaches select and update the data in same transaction, this means for as long as the transaction is running, the rows on which updates have been performed will be locked and any other operations will have to wait for the transaction to finish.

Solution : 

There are two things which we should do here to solve above problem : 

  •  we need to select and update data in different transactions.
  • And updation of these types should be done in Batches

So again I performed the same tests as above but this time update was performed in a different transaction which was commited in batches of 50.

Note:- In case of Scrollable and Stateless we need a different session also, as we need the original session and transaction to scroll through the results.

Results using Batch Processing

  • Using list():- time taken:- approx 400s, heap pattern:- gradually increased from 13mb to 61 mb
  • Using ScrollableResultSet:- time taken:- approx 380s, heap pattern:- gradually increased from 13mb to 51mb
  • Using Stateless:- time taken:- approx 190s, heap pattern:- gradually increased from 13mb to 44mb

Observation:- This temporal performance of ScrollableResults dropped down to become almost equal to Query.list(), but performance of Stateless remained almost same.

Summary and Conclusion

As from all the above experimentation  , in cases where we need to do bulk selection and updation, the best approach in terms of memory consumption and time is as follows : 

  • Use ScrollableResults in a Stateless Session.
  • Perform selection and updation in different transactions in batches of 20 to 50 (Batch Processing) (Note -*-  Batch size  can depend on the case to case basis)

  Sample Code with the best approach

  StatelessSession session = getStatelessSession();
        Transaction transaction = session.beginTransaction();
        ScrollableResults scrollableResults = session
                .createQuery("FROM PersonEntity WHERE id > " + MAX_ID_VALUE + " ORDER BY id")
                .setMaxResults(TRANSACTION_BATCH_SIZE).scroll(ScrollMode.FORWARD_ONLY);
        int count = 0;
        try {
            StatelessSession updateSession = getStatelessSession();
            Transaction updateTransaction = updateSession.beginTransaction();
            while (scrollableResults.next()) {
                PersonEntity personEntity = (PersonEntity) scrollableResults.get(0);
                personEntity.setName(randomAlphaNumeric(5));
                updateSession.update(personEntity);
                if (++count % 50 == 0) {
                    updateTransaction.commit();
                    updateTransaction = updateSession.beginTransaction();
                }
            }
            updateSession.close();
        } finally {
            if (session != null && session.isOpen()) {
                transaction.commit();
                session.close();
            }
        }

With the   java frameworks like spring and others this code may be even more smaller , like one not needing to  take care of session closing etc . Above code is written in plain java using hibernate. 

Please  try with large data and comment us the results , Also if you have some other better approach to do this please comment . 

Thank You for reading the article

The Solution — Too Much Fine Logging Causing Heap Dump

Many times, we face issues of heap dump in our Java server. Heap increases because your system is generating many objects, and if their lifecycle is long and the system keeps on generating these objects, they will consume all the RAM and heap dump may occur. This may occur due to memory leaks, bad coding, etc.

But these are not the only reasons for heap dump. Once, I faced an issue with our customer where heap dump was occurring regularly, and after debugging, I found that the root cause of the issue was fine logging. You may be surprised how logging can cause heap dump. 

Too much logging can cause heap dump even if they are fine level logs, not info logs. A surprising fact is that fine logging was not enabled.

Why it happened is as follows:

Generally, we log fine logging like in this example:

logger.fine("fine logs ") .

Now, what happens behind the scenes (in the JVM) is that even if fine logs are disabled except for the string “fine logs,” objects will be created as it is passed as an argument if the check for fine logging is inside the fine method.

If there are too many fine logs in the system and there are many threads available doing these operations with lots of fine logs, many char[] objects are created and fill the heap/RAM.

The Solution

There are two ways we should do fine logging.

1. Check the “if” condtion before every fine log, as follows:

if (logger.isFineLoggable()) {
logger.fine("your log ");
}

But, this does not look cool (lots of “if” in the code…)

2. With Java 8, Java gives a new API for logger, which does not take string as an argument; it takes function, which returns string as an argument and evaluates it when this function is called inside the fine method. This way, an object is not created until the function is called.

Here is an example:

logger.fine(() -> "fine logs"); .

With functional programming, the code looks nice and the problem was resolved.