Saturday, December 10, 2011

... not using isDebugEnabled() or isInfoEnabled()

The log4j API and other ones provide the methods isDebugEnabled(), isInfoEnabled() or isTraceEnabled() to determine if this log level is enabled (see also: http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/Logger.html).

Most of the developers know about this feature of course, but anyway I have often seen code where it would have also made sense to make use of them. If you do debug logging for statements which are called very often and have expensive implementations of toString() methods you can loose performance if you log without the corresponding is...Enabled() methods.

In the following test I run the code which calls a method 1.000.000 times and logs a message with isDebugEnabled() and without it - I turned the log level to info - so no output is produced.

Using isDebugEnabled() took 25 ms without using it. It took 2.5 seconds - which is a factor of 100.

The reason of that is of course simple - if you do not use isDebugEnabled() the String argument of the log.debug() has to be created. Sometimes like in this example the log statements are "hidden" inside a bean - and maybe you don't think about how often the method will be called afterwards.

Btw the isDebugEnabled() statement also consumes time - 20 ms in this case. Without logging the code would have taken 5 ms.

Another option - to make the code more readable - would be to use SLF4J: http://www.slf4j.org/faq.html#logging_performance


package org.kix;


import org.apache.commons.lang3.builder.ToStringBuilder;
import org.apache.commons.lang3.time.StopWatch;
import org.apache.log4j.Logger;


public class SomeBean {
private static Logger log = Logger.getLogger(SomeBean.class);
private int id;
private String text;

public static void main(String[] args) {
StopWatch sw = new StopWatch();
sw.start();
for (int i=0; i<1000000; i++) {
new SomeBean(i).doSth();
}
sw.stop();

log.info(sw);
}



public SomeBean(int id) {
super();
this.id = id;
this.text = "TEXT";
}

public void doSth() {
if (log.isDebugEnabled()) 
                    log.debug("doSth() "+this);
}


@Override
public String toString() {
return new ToStringBuilder(this)
.append("id", id)
.append("text",text)
.toString();
}
}

Tuesday, December 6, 2011

Logging the stacktrace

Some developers do not pay much attention on what is logged and how the log files look like. Often I've seen a code like this:
...
private Logger log = Logger.getLogger(MyClass.class);
...

try {
   .... some code
} catch (Exception e) {
   log.error(e);
}

The code above does not print the whole stacktrace, it just calls the toString() method of the Exception Object a prints the error message. A problem will be very difficult to detect using this log file. The correct way to log ist to use the 2nd paramter of the Logger methods:

try {
   .... some code
} catch (Exception e) {
   log.error("Error occured during...", e);

}

The first parameter is a String. A question which often arises is what to write in this string. I personally prefer to write the arguments of the method call. I think this is a good practice to do this. So you can identify the circumstances under which this exception raised in a production environment easily.

Monday, December 5, 2011

Releasing resources in the finalize() method

Releasing resources in the finalize() method can lead to big problems in your code. The finalize() method of an object is called by the garbage collector. The behavior of the garbage collector depends on the JVM implementation and hence the application can behave differently on different VMs. Consider the following really bad implementation of a DAO:

import java.sql.Connection; 
import java.sql.ResultSet; 
import java.sql.SQLException; 
import java.sql.Statement; 


public class SomeDao 
{ 
        Statement stmt = null; 
        Connection conn = null; 
        ResultSet rs = null; 
        
        public static class MyBean { 
                // members 
        } 
        
        public SomeDao(Connection conn) throws SQLException { 
                this.conn = conn; 
                stmt = this.conn.createStatement(); 


                rs = stmt.executeQuery("select ...."); 
        } 
        
        public MyBean getNext() throws SQLException { 
                if (rs.next()) { 
                        // read from rs and create MyBean 
                        return new MyBean(); 
                } else { 
                        return null; 
                } 
        } 
        
        @Override 
        public void finalize() { 
                if (rs != null) { 
                        try { rs.close(); } catch(Exception e) {}; 
                } 
                if (stmt != null) { 
                        try { stmt.close(); } catch(Exception e) {}; 
                } 
        } 
} 


The problem is that is not guaranteed that finalize() is called at all. If you create a lot of instances of the class than this could lead to a "maximum open cursor exeeded" error (on Oracle). The cursors stay open even if the objects are "ready for garbage collection".


Another problem in this code is the constructor - I will write about constructors in a future article.

Wednesday, November 30, 2011

Surrogate primary keys without thinking about the natural primary key

During my last project I worked together with a great database expert and this was an excellent experience for me. We usually design our database tables using a surrogate key as primary key. (Nearly) every table has an id column and the id columns are typically filled using a sequence.

This is a common practice, but it often leads to an other error: people (including me) do not think about the natural primary key of the table and what is far more important do not make the natural key unique.

Here is a very simplified example from our last project.
A user should be able to take actions on a document. I leave out the details here. We had a table called "action" with following attributes:

  • id (surrogate primary key)
  • action_text
  • actiontype_id  (foreign key to a particular action type) 
  • document_id    (foreign key to the document)
  • insert_time    (the time when the record is written to database)
  • insert_user    (the user who inserted the record)

My colleague designed the database and added the following unique index: document_id + insert_time

We implemented the code allowing a user to insert actions and soon had unique key violations, because we inserted records at the same time. After investigating a little bit we discovered that we had used a date datatype for the insert_time column which has an accuracy of seconds only (in Oracle). We changed it to an Oracle timestamp which has a precision of nanoseconds and is sufficient for our needs.

You might wonder what is the point here. The point was a new requirement to display a list of actions taken on a document - in the correct order. Done by simple showing the result of the statement select * from action where document_id=? order by insert_time. If we had not used a timestamp datatype, the order of the select would not have been predictable and led to a bug which maybe was not discovered until going to production (and then a fix gets really expensive).


I think it was this unique key definition which helped us to find the problem quickly - even before it was really there. This is just one example where a good database design helped us to save a lot of problems!


Comparing constant string literals

Consider the following code:

if (str != null && str.equals("TEXT")) {
  // do something
}


There is nothing wrong with it and it works... But if you write it like this, it is easier to read and saves the null test:


if ("TEXT".equals(str)) {
  // do something
}

Tuesday, November 29, 2011

Be aware when using the double datatype

I have seen a lot of applications written by professional Java programmers which use the double datatype in a wrong way. The double datatype is not suitable when exact precision is required, e.g. for currency amounts. If you use doubles in your application, you should really know what you do! Consider the following code (the unit test will pass!):

public class DoubleTest {
  @Test
  public void testAddDoubles() {
    double d=0.2;
    d+=0.1;
    // this expression is false!!!
    // the value of d is now 0.30000000000000004 !!!
    assertFalse(d==0.3);
  }
}

The result of the code snipped is not as one might expect 0.3 but 0.30000000000000004. The reason behind this is the internal representation of a double in IEEE 754 format (see also: http://en.wikipedia.org/wiki/IEEE_754-2008 - by the way this is not only a Java topic but a general floating point issue).

I will not recalculate all floating points calculations here - you can look at wikipedia how to do it. But just illustrate why the floating point calculation is not precise. So if you convert 0.1 to a binary value you will get 0.00011001100110011... or 1.100110011... B-4. It is a periodic number and for a 64 bit double the number is truncated after 52 digits and hence gets in-precise.

For currency amounts or other precise values (or for reading decimal or numeric values with a fixed-precision decimal value from a database) you really should use the BigDecimal datatype. This will save you from a lot of problems or bugs (which will be hard to find in production). If your code is too performance critical to use a BigDecimal (I never had this problem so far) use a long datatype maybe and store Cent values into it.

Consider a requirement where you shall select what to do depending on a threshold. If the amount is above 0.3 do that otherwise do this... The code above will not fulfill this one...