Archivo mensual: febrero 2010

DirectJNgine 1.2 final is out

Today I am releasing DirectJNgine 1.2 final. You can download it from http://code.google.com/p/directjngine/.

For detailed info, check the User’s Guide, which has been updated and has additional chapters devoted to the new functionality.

New in DJN 1.2: Support for stateful actions
It is possible to have session and application scoped actions, that will remember their state between requests.

To make an action stateful, use the @ActionScope annotation.

Take a look at the new chapter in the User’s Guide to get more information about stateful actions.

Sample code:


@ActionScope(scope=Scope.SESSION)
public class SessionStatefulActionTest {
  int count;
  String value;
  // ...
}

Once the SessionStatefulActionTest action is declared to be session scoped, it will be stored in the user session: this means that its count and value fields will be remembered across request belonging to the same user session.

New in DJN 1.2: Support for accessing the current session, etc. from within action methods
Now it is possible to get access to the current session, servlet context, servlet configuration, etc., from within action methods.
To do that, just use the new WebContext and WebContextManager classes.

Take a look at the new chapter in the User’s Guide to get more information about WebContext.

Sample code:


@DirectMethod
public WebContextInfo test_webContext() {
  WebContext context = WebContextManager.get();
  HttpSession session = context.getSession();
  ServletContext application = context.getServletContext();
    
  // Keep a counter of how many times we have called this method
  // in this session
  Integer callsInSession=(Integer)session.getAttribute("callsInSession");
  if( callsInSession == null ) {
    callsInSession = new Integer(0);
  }
  callsInSession = new Integer(callsInSession.intValue() + 1);
  session.setAttribute("callsInSession", callsInSession);

  // ...
}

You will probably find that using session/application scoped actions might be an easier way to accomplish your goals, though.

New in DJN 1.2: Support for multiple action instances
Now that actions can be stateful, it makes sense to have more than one action instance for a given Java class, each instance manging its own state.

Other additions/improvements

· All bugs reported against DJN 1.1 have been fixed.· We have added more tests, including those needed to ensure bug fixes work: we have crossed the one hundred automated tests barrier!

· We have moved to ExtJs 3.1.1 for testing to ensure that we remain up to date. While 3.1 and 3.0 should work fine, the “officially” supported version will be 3.1.1.

· Licensing has been “fixed”: we are LGPL v3 -the way it was intended to be from the beginning.

Code breaking changes
· The programmatic API has been modified so that poll methods belong to actions, instead of being global. This was a must to support stateful actions.

· The suggested workaround for handling “\n” and “\r” characters in DJN 1.1 does not work anymore: instead you should pass them “as-is”.

Tested browsers
· Internet Explorer 8 (8.0.6001.18702)

· Firefox 3.5.6 (Gecko 20100115)

· Safari 4.0.4 (531.21.10)

· Google Chrome 4.0.249.89

To all, thank you for your encouragement and criticism: I hope this new release of DJN helps you make bettter software.

Anuncios

Hibernate SQL Logging: log4jdbc / Haciendo log de SQL con Hibernate: log4jdbc

This is the second part of Hibernate: logging SQL.

Using log4jdbc instead of Hibernate SQL logging

Hibernate logs a lot of information we can exploit to get the SQL is it generating in the end. That said, I miss some things:

•    Get the SQL prepared statements with the parameter values right there, instead of getting each parameter in a different log line.
•    Know how much time it took to execute every SQL statement (sigh!).
•    Know what line in my code caused the SQL statement to be executed (not the line in Hibernate’s code)

Now, what if we could get this log,

DEBUG: jdbc.sqltiming - " com.softwarementors.hibernate.util.DataAccess.persistAll( DataAccess.java:40)
1. /* insert com.softwarementors.demo1.Article */
insert into Article (id, version, currentPrice, name) values (null, 0, 27.2, 'Article_1')  {executed in 15 msec}"

instead of this one?

DEBUG: org.hibernate.SQL - "/* insert com.softwarementors.demo1.Article */
insert into Article (id, version, currentPrice, name)
values (null, ?, ?, ?)"
TRACE: org.hibernate.type.IntegerType - "binding '0' to parameter: 1"
TRACE: org.hibernate.type.BigDecimalType - "binding '27.2' to parameter: 2"
TRACE: org.hibernate.type.StringType - "binding 'Article_1' to parameter: 3"

This last version is what Hibernate will log for us for a given SQL statement, while the first version is what log4jdbc will log for that same statement. Log4jdbc is an open source library that logs all JDBC calls for a given application. What does the log4jdbc log provide that the Hibernate log does not?

•    Log4Jdbc logs all SQL statements, whereas Hibernate only logs the SQL statements it generates. If we call SQL directly in some place, we might miss some SQL being executed if we rely on Hibernate logs to tell us the whole truth.
•    Log4jdbc logs the time spent by every statement, 15 milliseconds in our example. That is great!
•    Log4jdbc logs the SQL and writes the parameter values right there for prepared statements, whereas Hibernate logs them in separated lines, and is much more verbose.
•    Log4jdbc can log the function in our code that caused the statement to be executed, in our case the persistAll method.
This deserves to be repeated: log4jdbc can log the line in our code, instead of the one deep down in Hibernate. It provides the name of the function, the file and the line number!
Of course, you need to compile your code enabling line number and file name information generation for your classes.
•    Log4jdbc generates a logical connection number that identifies the connection that was used to execute a statement (or JDBC API call). That can be great to debug threading or pooling problems, because it helps us to know what statements belong together and what connection is really being used to execute a given statement.

That is the “1” that appears in the first log, just before “/* insert…”.

And, even if it does show not in our example, log4jdbc allows us to log slow statements as warning or errors: we can set how many milliseconds make us consider a statement slow (and generate a warning log) or very slow (and generate an error log).

However, Hibernate logging has a definite advantage: it logs human readable SQL. For complex queries, which tend to be the interesting ones, this is a definite plus.

Please, note that because Hibernate generates comments at the SQL level, log4jdbc can see and log them as well. Therefore, do not forget to set the hibernate.use_sql_comments Hibernate property to true.

Basic log4jdbc configuration

Now, how do we get all those benefits? Here are the steps I undertook to add logt4jdbc 1.1 to my existing project:

1.    Add the required jars:

1.1.    The log4jdbc jar itself. It is log4jdbc3-1.1.jar for version 1.1 and JDBC 3, because I’m using a JDBC3 capable driver.
1.2.    The jars for libraries used by log4jdbc, in this version the Simple Logging Façade for Java, SLFJ4, version 1.5: this means slf4j-api-1.5.0.jar and sl4j-log4j12-1.5.0.jar, because we use log4j for logging, and this is the bridge between SLFJ4 and log4j 1.2. If you use a different logging tool, you’ll need to use a different jar.

2.    Modify the Hibernate configuration so that it uses log4jdbc interceptor. I did that by modifying hibernate.properties as follows:

2.1.    Set hibernate.connection.driver_class to net.sf.log4jdbc.DriverSpy.
2.2.    Modify hibernate.connection.url, prepending jdbc:log4 to the existing connection url.
In my case, my old url was jdbc:hsqldb:hsql://localhost:9200/demo1_db. Therefore, the new url was jdbc:log4jdbc:hsqldb:hsql://localhost:9200/demo1_db.

3.    Modify log4j.properties so that we get the desired logging information from log4jdbc:

3.1.    Deactivate Hibernate SQL logging: comment the log4j.logger.org.hibernate.SQL=ALL and log4j.logger.org.hibernate.type=ALL entries.
But leave the hibernate.use_sql_comments Hibernate property set to true please: log4jdbc will log those comments too, and that will be nice.
3.2.    Configure log4jdbc logging: just set the  log4j.logger.jdbc.sqltiming category to ALL.
There are other logging categories, but that’s what I used to get the prior log, and most likely all you will need.

4.    Help log4jdbc in determining the line in our source code that caused the SQL statement to be executed.
To do this, log4jdbc traverses the call stack when an statement is executed, looking for the first function that belong to one of our classes. It will know that because we will tell it what is the root package for our classes. In my case, this is com.softwarementors. I just set the  system property to com.softwarementors passing it as a parameter to the JVM when executing my program, as follows:

-Dlog4jdbc.debug.stack.prefix=com.softwarementors.

That’s it: we are done!

Other goodies in the jdbc.sqltiming logger

We mentioned that log4jdbc allows us to mark a SQL statement as slow or very slow, logging it at the warn or error level, respectively. How do we do that? Well, if we consider a statements that takes 1000 milliseconds or more to deserve being logged as an error, and another one that takes 200 or more to deserve being logged as a warning, we will have to set two system properties, log4jdbc.sqltiming.warn.threshold=200 and log4jdbc.sqltiming.error.threshold=1000 The easiest way to do this is passing the following command line to the Java Virtual Machine, using the –D option, as follows:

-Dlog4jdbc.sqltiming.warn.threshold=200 -Dlog4jdbc.sqltiming.error.threshold=1000

I think you should almost always use this capability!

Understanding what “the line that caused the statement to be executed” means

Getting the line in my code that caused the SQL statement to be executed is really cool. However, some discussion is needed to understand what “the line that caused the SQL statement to be executed” means! As you probably know, Hibernate can delay the execution of SQL in order to get better performance. That means that the logical line that caused an SQL DELETE to be executed can be this one

entityManager.remove( myObject);

whereas the physical line that caused the DELETE statement to be executed might be this,

entitManager.getTransaction().commit();

That happens because Hibernate might have delayed the statement execution until commit time. What log4jdbc logs is the physical line.

Configuring Hibernate and getting human readable SQL

As I said before, Hibernate has the edge when it comes to statement readability. Therefore, you might want to activate Hibernate logging just to get a nicely formatted SQL, while at the same time logging the information provided by log4jdbc. To do that, set the hibernate.format_sql Hibernate property to true in the hibernate.properties file (or wherever you happen to specify those Hibernate properties). Then set enable the hibernate.SQL logger level to ALL. Of course, you will get duplicated logs for every SQL statement, but that will be easy to handle, because they will be consecutive and therefore easy to spot. And, if you use a tool like Chainsaw for viewing the logs, you can filter out the Hibernate logs and look at them only when you want to dig into the SQL itself!

More log4jdbc logging

As always, your logs are good only if you know and understand the existing logging categories provided by the library you want to monitor. There are four logging categories in log4jdbc. But just let me tell you that using jdbc.sqltiming will be enough if all you want to know is about the SQL statements that are executed. These are the logging categories provided by log4jdbc:

•    jdbc.sqlonly: logs every SQL statement the program executes, but just the SQL itself. It shows the parameter values when using prepared statements.

•    jdbc.sqltiming: as far as I know, it is exactly like jdbc.sqlonly, but adding the time the statement took to execute. I usually use this, instead of jdbc.sqlonly, and you should never use both at the same time unless you love to get almost duplicated logs.

•    jdbc.audit: logs all JDBC API calls, except those for the ResultSet interface. This can generate a lot of information, use it with care.

•    jdbc.resultset: this logs the ResultSet API calls only, so it does not overlap with jdbc.audit. This can generate massive amounts of information (lots of calls per returned row!), and I think you will rarely use this. Just to illustrate what kind of logging you can get out of jdbc.sqltiming, jdbc.audit and jdbc.resultset when combined, let’s see the log generated when the following line of code is executed:

InvoiceLine line = entityManager.find( InvoiceLine.class, lineId );

Well, here is the generated log:

DEBUG: jdbc.audit - "1. Connection.prepareStatement(/* load com.softwarementors.demo1.InvoiceLine */ select invoicelin0_.id as id3_0_, invoicelin0_.version as version3_0_, invoicelin0_.article_id as article5_3_0_, invoicelin0_.pricePerUnit as pricePer3_3_0_, invoicelin0_.quantity as quantity3_0_ from InvoiceLine invoicelin0_ where invoicelin0_.id=?) returned net.sf.log4jdbc.PreparedStatementSpy@1b18235  com.softwarementors.demo1.Main.main(Main.java:159)"

DEBUG: jdbc.audit - "1. PreparedStatement.setLong(1, 3) returned   com.softwarementors.demo1.Main.main(Main.java:159)"

DEBUG: jdbc.sqltiming - " com.softwarementors.demo1.Main.main(Main.java:159)
1. /* load com.softwarementors.demo1.InvoiceLine */ select invoicelin0_.id
as id3_0_, invoicelin0_.version as version3_0_, invoicelin0_.article_id as article5_3_0_, invoicelin0_.pricePerUnit
as pricePer3_3_0_, invoicelin0_.quantity as quantity3_0_ from InvoiceLine invoicelin0_ where
invoicelin0_.id=3  {executed in 0 msec}"

DEBUG: jdbc.audit - "1. PreparedStatement.executeQuery() returned net.sf.log4jdbc.ResultSetSpy@46a09b  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.next() returned true  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getInt(version3_0_) returned 0  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getLong(article5_3_0_) returned 1  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getBigDecimal(pricePer3_3_0_) returned 27.2  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.getInt(quantity3_0_) returned 4  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.wasNull() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.next() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.resultset - "1. ResultSet.close() returned   com.softwarementors.demo1.Main.main(Main.java:159)"

DEBUG: jdbc.audit - "1. PreparedStatement.getMaxRows() returned 0  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. PreparedStatement.getQueryTimeout() returned 0  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. PreparedStatement.close() returned   com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. Connection.isClosed() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"
DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"

As you can see, jdbc.audit adds tons of data, and jdbc.resultset adds even more. Just imagine the log had we executed a query returning 100 objects! It is very likely that you will want to enable this kind of logging for very little sections of code, programmatically, to avoid drowning in data. All these loggers provide different information depending on the level to which they are set:

•    DEBUG: logs the method, file and line number at which the JDBC API method was called (if possible). Of course, log the SQL or other applicable information, such as “Connection.isClosed() returned false”.

•    INFO: like DEBUG, omitting the method file and line number.

•    ERROR: log data about SQL exceptions only. If you want no log for a given logger, set its level to FATAL. As an example, if a logger logs this when its level is set to DEBUG,

DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false  com.softwarementors.demo1.Main.main(Main.java:159)"

it will log this when it is set to INFO:

DEBUG: jdbc.audit - "1. Connection.getAutoCommit() returned false"

This can be much more manageable sometimes. By all means, if you are stepping through code with the debugger, set your logging level to INFO. You already know in which line you are (!), and you just want to focus in what JDBC methods are called at that moment: you don’t want to get that information in the middle of a lot of useless text. Finally, to log information about log4jdbc itself, you can use the log4jdbc.debug logging category. I always set it to ALL, because I find the information provided to be rather small and manageable (I’m talking about version 1.1 of log4jdbc all the time, so your mileage might vary). This is all logging I get in my sample application:

DEBUG: log4jdbc.debug - "... log4jdbc initializing ..."
DEBUG: log4jdbc.debug - "  log4jdbc.debug.stack.prefix = com.softwarementors"
DEBUG: log4jdbc.debug - "  log4jdbc.sqltiming.warn.threshold = 100"
DEBUG: log4jdbc.debug - "  log4jdbc.sqltiming.error.threshold = 500"
DEBUG: log4jdbc.debug - "x log4jdbc.drivers is not defined"
DEBUG: log4jdbc.debug - "  FOUND DRIVER org.hsqldb.jdbcDriver"
DEBUG: log4jdbc.debug - "... log4jdbc initialized! ..."

But it does not work with my JDBC driver!

Log4jdbc automatically recognizes and loads the more popular JDBC drivers, such as those for Oracle, HSQL, MySQL, the JTDS drivers for SQLServer and Sybase, etc. However, if your database driver is not directly recognized by log4jdbc, you still can integrate it with log4jdbc setting the following system property,

log4jdbc.drivers=<driver>[,<driver>,...]

Again, the easiest way might be to pass it to the JVM using the –D option, as follows:

-Dlog4jdbc.drivers=<driver>[,<driver>,...]

We want more!

Now, to the “wouldn’t it be nice?” department… I think it might be nice to be able to control logging per JDBC interface/class, i.e., Connection or PreparedStatement. An additional level of finer grained loggers might be nice too: I can imagine wanting to get logs for transaction related operations, but not the other Connection function calls. As always, the sky is the limit, but log4jdbc is a great library that you can put to good use with a minimal effort. As always, you should check newer log4jdbc versions for additional functionality.

Acknowledgements

I would like to thank José María Martínez for his criticism of this article.

DirectJNgine 1.2 RC 1 disponible

Hoy he publicado la RC1 de DirectJNgine 1.2.

El único cambio relevante con respecto a la beta 3 es que la versión oficialmente soportada de ExtJs pasa a ser la 3.1.1.

Los tests automatizados (¡ya contamos con 102!) se ejecutan a partir de ahora contra esta versión.

La versión final de DirectJNgine aparecerá probablemente la próxima semana: en este momento lo único pendiente es obtener feedback de usuarios utilizando otros entornos, especialmente Linux.

Hibernate SQL Logging / Haciendo log de SQL con Hibernate

Here is the link to a (rather short ) article about SQL logging in Hibernate, Hibernate: logging SQL.

DirectJNgine 1.2 beta 3 ya está disponible

Hoy he hecho pública la beta 3 de DirectJNgine 1.2, un proyecto Open Source que se puede descargar desde http://code.google.com/p/directjngine/.

Para aquellos que no conozcais DirectJNgine (también llamada DJN), es una librería Java que permite llamar directamente a objetos Java desde Javascript vía Ajax.

Básicamente, uno escribe el siguiente código Java,

public class Action1 {
  @DirectMethod
  public String sayHello( String name) {
    return “Hello, ” + name + “. Nice to meet you!”;
  }
}

 y lo invoca desde Javascript como sigue:

Action1.sayHello( “Pedro”,
  function(p, response) {
    Ext.MessageBox.alert( “Greetings”, response.result );
  }
);

Tan simple como puede serlo.

DirectJNgine funciona como back-end de ExtJs, una librería de interface de usuario que quizá sea la más potente que se puede encontrar a día de hoy. Vale la pena verla en acción.

DirectJNgine se ha desarrollado en mi tiempo libre, aunque con los criterios con que llevamos a cabo los desarrollos profesionales. Por tanto no es una librería, sino un producto que cuenta con características poco comunes en proyectos Open Source de tamaño similar:

  • Incluye una guía de usuario actualizada en cada versión, de casi 50 páginas.
  • Cuenta con más de 100 tests automatizados, ya que se ha desarrollado utilizando desarrollo basado en tests, TDD.
  • Se testea contra Internet Explorer, Firefox, Safari, Chrome y Opera antes de cada release (final, beta o alpha).
  • Incluye más ejemplos que los protocolos implementados por el propio ExtJs para PHP, NET, etc.(!) .
  • Incluye características muy avanzadas orientadas a aplicaciones de alto rendimiento: soporte para peticiones batched atendidas por múltiples threads, minificación del código Javascript, unificación de múltiples APIs en un único archivo, etc.
  • Su licencia es LGPL v3, con lo que se puede usar en productos comerciales.

En el momento de escribir esto, el thread de DirectJNgine es el más visitado (¡más de 25.000 visitas!) y con más entradas de todos los existentes en el forum dedicado a ExtDirect, superando incluso a los protocolos implementados por el equipo de ExtJs.

¡Una lástima que tan solo sea un hobby!

Escribir Código Correcto en Java

En mi último post abordé la problemática de la escritura de código robusto en presencia de errores, redirigiéndoos a un artículo sobre código exception-safe.

Hoy quiero hablar de código correcto, tema sobre el que también he escrito este artículo.

Antes de comenzar a hablar de corrección vale la pena recordar la siguiente frase de Bertrand Meyer,

“La corrección del Software es una noción relativa”

Y ello es así porque

Un sistema o elemento de software no es correcto o incorrecto por sí mismo; es correcto o incorrecto con respecto a una cierta especificación. Hablando estrictamente, no deberíamos discutir si ciertos elementos de software son correctos, sino si son consistentes con su especificación.

Esto se corresponde con mi experiencia real, y es que en la práctica el principal motivo por el que el software no es correcto es simplemente que no se define con claridad qué debe hacer.

Dicho de otro modo, no se establece un contrato.

Debo insistir en que utilicemos la palabra contrato en adelante. 

Porque, contrato suena a cosa seria. Y es que escribir código correcto requiere una cierta actitud.

En un contrato uno debería plasmar no sólo qué se debe hacer, sino qué precondiciones se deben cumplir para poder hacerlo (lo siento, no puedo llegar al pueblo de al lado con mi coche si me lo dejas sin gasolina, o al menos no tan fácilmente), y qué se garantiza (quizá llegar con mi coche con las cuatro ruedas pinchadas sea llegar, pero quizá no sea suficiente).

En el artículo se aborda la cuestión de cómo verificar los contratos de nuestro código Java mediante el uso de aserciones, una característica que está presente en Java desde la versión 1.4 del JDK.

Pero también se abordan cuestiones tales como cuán exigentes debemos ser en nuestro contrato, cómo asegurarnos de que no exigimos más de lo razonable (no hay nada más estúpido y a la vez frustrante que exigir algo que no se puede hacer), etc.

Vale la pena resaltar que el artículo pone el énfasis en técnicas concretas de programación, sin las que, desde mi punto de vista, la corrección del código no es más que una ficción.

High Quality Java Code: Contracts & Assertions

Here is the link to High Quality Java Code: Contracts & Assertions!