Escribir lapso temporal en java

28 07 2010

A veces necesario poder calcular el tiempo de ejecución de una parte del código. Ello puede ser porque estemos perfilando una aplicación o porque simplemente queramos dejar constancia de ello en algún fichero de log o en alguna consola de debugging.

En particular es algo que necesito muy a menudo así que lo tengo encapsulado en el siguiente método estática en una clase de utilidades:

public class Time {
	/**
	 * @param initial Initial time in milliseconds.
	 * @return a message with the shape: "xxx seconds (YYY millis)"
	 */
	public static String getLapseTimeMessage(long initial) {
		TimeUnit secondsUnit = TimeUnit.SECONDS;
		TimeUnit millisUnit = TimeUnit.MILLISECONDS;

		long timeLapse = System.currentTimeMillis() - initial;
		long seconds = secondsUnit.convert(timeLapse, millisUnit);
		long millis = millisUnit.convert(timeLapse, millisUnit);

		return seconds + " seconds (" + millis + " millis)";
	}
	../..
}

Una clase cliente la utilizaría como sigue:

long initial = 0;
if (logger.isDebugEnabled()) {
	initial = System.currentTimeMillis();
}

Parser parser=new ParserFactory().makeParser();
String text=this.programText;
this.program=parser.parse(text);//ParseException, IOException

logger.debug("Javascript parser needed " + Time.getLapseTimeMessage(initial));

Que dejaría una traza como la siguiente:

Javascript parser needed 1 seconds (1542 millis)

Obviamente esta es una aproximación muy básica que puede ser mejorada y más parametrizada, pero para casos sencillos cumple su cometido.





Capturar excepciones en el AWT Thread de una aplicación Swing

20 02 2010

En java podemos clasificar las excepciones en dos tipos, las “checked” y las que no son “not-checked” (perdonad, pero no sé cómo traducirlo satisfactoriamente).

Los métodos que lanzan excepciones del primer tipo ( cheched ) fuerzan al cliente de dicho métodos a tratarlas con un bloque try/catch o a lanzarlas para que sea un antecesor en la pilla de llamadas quien las trate. En última instancia la excepción alcanza el método principal main, que si no la gestiona la ‘lanza’ al sistema operativo y la aplicación muere con el volcado de pila del lugar donde se produjo.

Las excepciones not-checked no tienen esta restricción: ni es obligatorio capturarlas, ni el método cliente tiene que declarar explícitamente su lanzamiento mediante una cláusula throws en su signatura.

Las excepciones not-checked son todas aquellas que heredan de la clase RuntimeException . Así pues, si un método puede lanzar NullPointerException o IllegalArgumentException (entre otras), no está obligado a declararlo en su signatura ni el cliente a gestionar la excepción. De todos modos, si se produce, su propagación sigue la misma política: van escalando la pila de llamadas hasta que alguien las trate.

A la hora de programar una aplicación somos muy conscientes de las excepciones checked porque su no gestión es un error en tiempo de compilación, sin embargo para las excepciones not checked no tenemos más remedio que prever su posibilidad y hacer la gestión correspondiente donde corresponda. No obstante es posible que mientras estamos desarrollando o depurando no hayamos previsto una situación que desencadene el lanzamiento de una excepción de este tipo (típicamente se nos puede escapar alguna NullPointerException ). En estos casos (y siempre en general) es útil tener un bloque catch que capture el ‘resto’ de excepciones que el programador no previó e intentar hacer algo útil y más elegante que acabar la aplicación abruptamente (como por ejemplo guardar información en los logs que nos permita depurar o hacer un diagnóstico del problema).

¿Cómo y dónde ponemos este bloque “ captura el resto de excepciones”? En aplicaciones con un solo hilo de ejecución es muy fácil: en el main como ilustra el siguiente ejemplo.

public static void main(String[] args) {
try {
	// mi super-programa
} catch (Throwable e) {
	logger.debug("Unexpected exception!", e);
}

¿Pero qué pasa en una aplicación multi-hilo? En este caso el main creará varios hilos que tendrán su propia pila de llamadas por lo que cualquier excepción producida y no capturada en cualquiera de esos hilos no podrá ser capturada por el catch del ejemplo anterior.

En particular, las aplicaciones Swing son siempre multi-hilo. El código de programación de todos los listeners de gestión de eventos producidos por los diferentes elementos de la GUI, se ejecuta dentro del event dispatch thread (el hilo de gestión de eventos) también conocido como “AWT” Thread y que no es el mismo en el que se ejecuta el main del programa.

¿Qué pasa si se produce una excepción not-checked en este hilo? Pues que si no lo hemos previsto en el código y no hay ningún catch que la capture, se pierde irremediablemente. Afortunadamente existe una solución que expondré a continuación y que también está explicada en este post.

La API estándar de Java ofrece la clase ThreadGroup . Cuando creamos un thread podemos hacer que pertenezca a una instancia de esta clase. Dicha clase tiene un método con la siguiente signatura:

void uncaughtException(Thread t, Throwable e)

que es llamado por la máquina virtual de forma automática cuando cualquiera de los threads que forman parte de ese grupo lanza una excepción que nadie captura. Cuando un hilo se crea dentro de un grupo, todos los hilos que pueda crear ese hilo también pertenecen al mismo grupo.

Ahora ya tenemos todos los elementos que solucionan nuestro problema:

  1. Creamos una subclase de ThreadGroup que sobrescriba el método uncaughtException para que haga algo útil en nuestro programa.
  2. En el main construimos una instancia de la clase que acabamos de construir.
  3. Creamos un thread que se encarga de montar toda la GUI que forma parte del grupo recién instanciado.

Con esto conseguimos que todos los threads interesantes de nuestro programa pertenezcan al grupo que es capaz de gestionar las excepciones no capturadas.

Nuestro ThreadGroup podría tener el siguiente aspecto:

class HandleExceptionGroup extends ThreadGroup {
	private static Logger logger = Logger.getLogger(ExceptionGroup.class);

	public HandleExceptionGroup() {
		super("ExceptionGroup");
	}

	@Override
	public void uncaughtException(Thread t, Throwable e) {
		String msg =
			"GUI produced an unexpected exception (thread: " + t.getName() + ") ";

		logger.warn(msg, e);
	}
}

y el main de la clase principal:

public static void main(String[] args) {
        HandleExceptionGroup threadGroup = new HandleExceptionGroup();
	new Thread(threadGroup, "Main Thread"){
		@Override
		public void run() {
			// aquí construyo la GUI
		}
	}.start();
}




Configurar log4j para JUnit

25 05 2009

Es muy habitual que a la hora de programar nuestras aplicaciones utilicemos algún tipo de librería de log. Tradicionalmente hay dos familias log4j (la pionera) y la nativa de Java (java.util.logging) que vino un poco después “inspirándose” bastante en la filosofía del proyecto de Apache.

Personalmente soy usuario de log4j por varios motivos: estuvo disponible antes, es el logging nativo de mi servidor de aplicaciones habitual (JBoss) y me gusta más 😉

Por otro lado, mi manera habitual de desarrollo es TDD, así que el IDE pasa una parte importante del tiempo ejecutando suites de tests JUnit.

Cualquiera de los frameworks de logging que utilicemos tiene el concepto de appender que es el destino en el que se escriben los mensajes. Destinos habituales suelen ser la consola o un fichero, por ejemplo. La configuración de los appenders de una aplicación se suele hacer durante el bootstrap (o la inicialización, si lo preferís) de la misma. Sin embargo cuando estamos corriendo tests, dicha inicialización no se produce así que perdemos todos los mensajes de logging que, si alguien se molestó en escribirlos, seguro que son muy útiles (especialmente cuando estamos desarrollando).

En “modo desarrollo” seguramente tenemos suficiente con una configuración básica en el que todos los mensajes se redirijan a la consola (que obviamente puede estar integrada en nuestro IDE). En el caso de log4j existe el método estático

org.apache.log4j.BasicConfigurator.configure()

que hace precisamente eso (creo recordar que java.util.logging tiene un mecanismo análogo). Ahora sólo resta saber dónde hacer la llamada al método. Obviamente no tiene sentido que lo pongamos en cada TestCase. Como en general agrupamos los diferentes tests en suites, parece que este es un buen lugar para configurarlo. Por ejemplo:

@RunWith(Suite.class)
@Suite.SuiteClasses(value={
    nq.quota.QuotaTest.class,
    nq.quota.FrequencyTest.class,
    })
public class AllTests {
    @BeforeClass
    public static void startup() {
        BasicConfigurator.configure();
    }
}

En el código precedente se ve la configuración de una test suite con JUnit 4 y etiquetamos un método de inicialización como @BeforeClass para asegurarnos que se ejecuta una única vez y antes de que la suite lance todos los tests configurados.

Esta misma idea puede utilizarse para configurar todos aquellos compartidos por los diferentes tests: variables de entorno, conexiones a bases de datos, etc.


				




Problemas desplegando unidades de persistencia en JBoss 5

24 02 2009

En los últimos cursos que he dado sobre tecnologías JEE he utilizado los productos open source de Sun porque se integran bastante bien y además los considero más adecuados para formación que otras posibles alternativas. En particular, he estado utilizando NetBeans y Glassfish para explicar EJB 3.0 y las apis de persistencia y transaccionalidad (JPA y JTA).

Hace unos días me bajé JBoss AS 5 para ver las novedades que presentaba (ya que en el pasado trabajé bastante con él) y al ir a desplegar algún jar que había funcionado perfectamente en Glassfish me ha dado problemas. Como sospechaba, el problema estaba en el context.xml y en que JBoss AS se ha vuelto un poco más pijo.

Veámoslo con un ejemplo. Este es el persistence.xml que funcionaba sin problemas en Glassfish y que reventaba en el JBoss:

<?xml version="1.0" encoding="UTF-8"?>
<persistence>
  <persistence-unit name="Banco" transaction-type="JTA">
    <provider>org.hibernate.ejb.HibernatePersistence</provider>
    <jta-data-source>banco</jta-data-source>
    <exclude-unlisted-classes>false</exclude-unlisted-classes>
    <properties>
      <property name="hibernate.hbm2ddl.auto" value="update"/>
    </properties>
  </persistence-unit>
</persistence>

Esta es la salida que producía en el log del JBoss:

2009-02-24 19:28:42,832 ERROR [org.jboss.kernel.plugins.dependency.AbstractKernelController] (HDScanner) Error installing to Parse: name=vfszip:/home/ivan/jboss-5.0.0.GA/server/all/deploy/titan.jar state=Not Installed mode=Manual requiredState=Parse
org.jboss.deployers.spi.DeploymentException: Error creating managed object for vfszip:/home/ivan/jboss-5.0.0.GA/server/all/deploy/titan.jar
	at org.jboss.deployers.spi.DeploymentException.rethrowAsDeploymentException(DeploymentException.java:49)
	at org.jboss.deployers.spi.deployer.helpers.AbstractParsingDeployerWithOutput.createMetaData(AbstractParsingDeployerWithOutput.java:337)
	at org.jboss.deployers.spi.deployer.helpers.AbstractParsingDeployerWithOutput.createMetaData(AbstractParsingDeployerWithOutput.java:297)
	at org.jboss.deployers.spi.deployer.helpers.AbstractParsingDeployerWithOutput.createMetaData(AbstractParsingDeployerWithOutput.java:269)
	at org.jboss.deployers.spi.deployer.helpers.AbstractParsingDeployerWithOutput.deploy(AbstractParsingDeployerWithOutput.java:230)
	at org.jboss.deployers.plugins.deployers.DeployerWrapper.deploy(DeployerWrapper.java:171)
	at org.jboss.deployers.plugins.deployers.DeployersImpl.doDeploy(DeployersImpl.java:1439)
	at org.jboss.deployers.plugins.deployers.DeployersImpl.doInstallParentFirst(DeployersImpl.java:1157)
	at org.jboss.deployers.plugins.deployers.DeployersImpl.install(DeployersImpl.java:1098)
	at org.jboss.dependency.plugins.AbstractControllerContext.install(AbstractControllerContext.java:348)
	at org.jboss.dependency.plugins.AbstractController.install(AbstractController.java:1598)
	at org.jboss.dependency.plugins.AbstractController.incrementState(AbstractController.java:934)
	at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:1062)
	at org.jboss.dependency.plugins.AbstractController.resolveContexts(AbstractController.java:984)
	at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:822)
	at org.jboss.dependency.plugins.AbstractController.change(AbstractController.java:553)
	at org.jboss.deployers.plugins.deployers.DeployersImpl.process(DeployersImpl.java:781)
	at org.jboss.deployers.plugins.main.MainDeployerImpl.process(MainDeployerImpl.java:545)
	at org.jboss.system.server.profileservice.hotdeploy.HDScanner.scan(HDScanner.java:290)
	at org.jboss.system.server.profileservice.hotdeploy.HDScanner.run(HDScanner.java:221)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:181)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:205)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)
Caused by: org.jboss.xb.binding.JBossXBException: Failed to parse source: Failed to resolve schema nsURI= location=persistence
	at org.jboss.xb.binding.parser.sax.SaxJBossXBParser.parse(SaxJBossXBParser.java:203)
	at org.jboss.xb.binding.UnmarshallerImpl.unmarshal(UnmarshallerImpl.java:168)
	at org.jboss.deployers.vfs.spi.deployer.JBossXBDeployerHelper.parse(JBossXBDeployerHelper.java:199)
	at org.jboss.deployers.vfs.spi.deployer.JBossXBDeployerHelper.parse(JBossXBDeployerHelper.java:170)
	at org.jboss.deployers.vfs.spi.deployer.SchemaResolverDeployer.parse(SchemaResolverDeployer.java:132)
	at org.jboss.deployers.vfs.spi.deployer.SchemaResolverDeployer.parse(SchemaResolverDeployer.java:118)
	at org.jboss.deployers.vfs.spi.deployer.AbstractVFSParsingDeployer.parseAndInit(AbstractVFSParsingDeployer.java:256)
	at org.jboss.deployers.vfs.spi.deployer.AbstractVFSParsingDeployer.parse(AbstractVFSParsingDeployer.java:188)
	at org.jboss.deployers.spi.deployer.helpers.AbstractParsingDeployerWithOutput.createMetaData(AbstractParsingDeployerWithOutput.java:323)
	... 27 more
Caused by: org.jboss.xb.binding.JBossXBRuntimeException: Failed to resolve schema nsURI= location=persistence
	at org.jboss.xb.binding.sunday.unmarshalling.SundayContentHandler.startElement(SundayContentHandler.java:313)
	at org.jboss.xb.binding.parser.sax.SaxJBossXBParser$DelegatingContentHandler.startElement(SaxJBossXBParser.java:401)
	at org.apache.xerces.parsers.AbstractSAXParser.startElement(Unknown Source)
	at org.apache.xerces.impl.xs.XMLSchemaValidator.startElement(Unknown Source)
	at org.apache.xerces.xinclude.XIncludeHandler.startElement(Unknown Source)
	at org.apache.xerces.impl.XMLNSDocumentScannerImpl.scanStartElement(Unknown Source)
	at org.apache.xerces.impl.XMLNSDocumentScannerImpl$NSContentDispatcher.scanRootElementHook(Unknown Source)
	at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl$FragmentContentDispatcher.dispatch(Unknown Source)
	at org.apache.xerces.impl.XMLDocumentFragmentScannerImpl.scanDocument(Unknown Source)
	at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
	at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
	at org.apache.xerces.parsers.XMLParser.parse(Unknown Source)
	at org.apache.xerces.parsers.AbstractSAXParser.parse(Unknown Source)
	at org.apache.xerces.jaxp.SAXParserImpl$JAXPSAXParser.parse(Unknown Source)
	at org.jboss.xb.binding.parser.sax.SaxJBossXBParser.parse(SaxJBossXBParser.java:199)
	... 35 more
2009-02-24 19:28:42,848 WARN  [org.jboss.system.server.profileservice.hotdeploy.HDScanner] (HDScanner) Failed to process changes
org.jboss.deployers.client.spi.IncompleteDeploymentException: Summary of incomplete deployments (SEE PREVIOUS ERRORS FOR DETAILS):

*** CONTEXTS IN ERROR: Name -> Error

vfszip:/home/ivan/jboss-5.0.0.GA/server/all/deploy/titan.jar -> org.jboss.xb.binding.JBossXBRuntimeException: Failed to resolve schema nsURI= location=persistence

	at org.jboss.deployers.plugins.deployers.DeployersImpl.checkComplete(DeployersImpl.java:863)
	at org.jboss.deployers.plugins.main.MainDeployerImpl.checkComplete(MainDeployerImpl.java:665)
	at org.jboss.system.server.profileservice.hotdeploy.HDScanner.scan(HDScanner.java:293)
	at org.jboss.system.server.profileservice.hotdeploy.HDScanner.run(HDScanner.java:221)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
	at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:181)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:205)
	at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
	at java.lang.Thread.run(Thread.java:619)

La solución ha sido más o menos sencilla: definir el espacio de nombres XML tal y como sigue y la unidad de persistencia se ha desplegado sin más problemas:

<?xml version="1.0" encoding="UTF-8"?>
<persistence
    version="1.0"
    xmlns="http://java.sun.com/xml/ns/persistence"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_1_0.xsd">
   <persistence-unit name="titan">
      <jta-data-source>java:/DefaultDS</jta-data-source>
      <properties>
         <property name="hibernate.hbm2ddl.auto" value="create-drop"/>
      </properties>
   </persistence-unit>
</persistence>

Tendré que echar un ojo a la especificación de JPA para ver si definir el espacio de nombres es obligatorio, aunque me parece recordar que esto no era una exigencia en versiones anteriores de JBoss AS…





Configuración de logging global en Java

19 02 2009
Duke, the Java Mascot, in the waving pose. Duk...
Image via Wikipedia

Hoy me he pasado unas cuantas horas peleándome con una tontería. La típica cosa que cuando ves lo que es te da una rabia infinita 😛

Aunque en el pasado había trabajado bastante con JBoss AS aún no me había dado tiempo a probar la versión 5 que se liberó en diciembre, así que he decidido utilizarlo para un pequeño proyectito y así tener la excusa de ver qué novedades presenta.

Mi sorpresa ha sido que al ponerlo en marcha se ha puesto a sacar tal cantidad de información de logging por la consola que el pobre ha tardado más de 10 minutos en arrancar. Cara de póquer. Como me conozco el servidor, me voy a ver la configuración de logging del mismo que está en:

JBOSS_HOME/server/default/conf/jboss-log4j.xml

Si no recuerdo mal en anteriores versiones el fichero se llamaba a secas log4j.xml, pero al echarle un vistazo su estructura es la misma que en versiones anteriores. Sigue utilizando log4j en vez de la api de logging de de la JSE y por defecto configura dos appenders: uno de consola con límite en el nivel WARN y otro de fichero.

Ahora sí que no entendía nada: ¿cómo es posible que la consola esté sacando tanto mensaje de logging y además con un nivel TRACE cuando la configuración limita al nivel a WARN?

Sigo investigando y compruebo que la información de logging que se corresponde con lo que yo voy configurando en dichero fichero sale por la salida estándar y que los mensajes “okupas” en realidad están saliendo por el canal de error… Además otros dos detalles, estos mensajes se corresponden con clases de la JSE y no tienen el mismo formato (pattern) que el resto de mensajes… Es más, parece que tienen formato del paquete de logging estándar de JSE…

Fallo localizado, tengo activado el logging estándar de la JSE (javax.util.logging) al nivel más alto. Ahora sólo falta averiguar por qué. Tras probar una serie de cosas estrambóticas, el fallo estribaba en que en algún momento (que no logro recordar) había cambiado la configuración global del logging estándar; ¿cómo se hace esto? Editando un fichero que se encuentra en la carpeta lib de la JRE instalada, en particular:

JAVA_HOME/jre/lib/logging.properties

En dicho fichero tenía establecido lo que llaman el “Default global logging level” a ALL. Al cambiarlo a WARNING todo volvió a la normalidad.

../..
# Default global logging level.
# This specifies which kinds of events are logged across
# all loggers.  For any given facility this global level
# can be overriden by a facility specific level
# Note that the ConsoleHandler also has a separate level
# setting to limit messages printed to the console.
.level= WARNING
../..
Reblog this post [with Zemanta]