[Javier Ader]

Buenas. Me puse a investigar un poco las diferencias a nivel de performance de usar CPreparedStatement vs PStatemets normales y entre otras cosas me puse a sniffear (con Wireshark) un poco la de red con la idea de comparar el trafico de red generado entre estas dos sentencias. No llege a ninguna conclusión por ahora en este tema, pero descubri que cada vez que se crea un CPreparedStatement o CStatement sin pasarle una transacción (directamente o lo que es más común indirectamente via DB.prepareStatement) se genera un acceso a la base de datos para verificar el TransactionIsolation de una de las conexiones elegidas del pool de conexiones en DB (que me falta investigar un poco cual es la idea, pero a priori no entiedo bien porque se chequea el nivel de aislación de una conexión; se supone que no debería cambiar de nivel).
En el caso de CPreparedStatement la que pasa es :
CPreparedStatement.CPreparedStatement(int,int,string,string,boolean): si trxName es null o si Trx.get(trxName) evalua a null, tiene que usar una conexión del pool; esto se lo pide a DB, invocando a DB.getConectionRO() o DB.getConnectionRW() dependiendo del parámetro resultSetConcurrency (lineas 95-98).
Ahora bien, DB.getConectionRO() o DB.getCoonectionRW(), antes de retornar una de la conexiones verifica si su nivel de aislación no es READ_COMMITED; si no lo setea a este nivel (lineas 352-353 de DB). El tema es que al ejecutar connection.getTransactionIsolation() el driver JDBC de postgres (al menos la versión que esta en uno actualmente) termina ejecutando la sentencia SQL “SHOW TRANSACTION ISOLATION LEVEL” sobre el server, AbstractJdbc2Connection.getTransactionIsolation() (por alguna razón no cachea esta información… pero si por ej si es read only; AbstractJdbc2Connection.isReadOnly()). Asi por ej

Code:

PreparedStatement pstmt = DB.prearedStatement(
“SELECT * FROM AD_Client”);

ResultSet rs = pstmt.executeQuery();

//proceso rs

rs.close();
pstmt.close();

Genera dos accesos al servidor; estos dos accesos representan dos interrupciones a nivel de SO (llamadas bloqueantes) y el respectivo round-trip de red (a nivel de IP se se ven cerca de 8 paquetes en total).
Bueno, el tema es que el anterior patron (crear un PreparedStatement sin transacción, ejecutarlo y cerrarlo inmediatamente) parece la norma, al menos a nivel ventanas normales y ademas hay potencialmente muchas instancias del mismo. Por ej: MWindowVO.create(…) se llama cada vez que se instancia una ventana y la cantidad de “executeQuery” son potencialmente muchas dependiendo de la complejidad de la ventana (la ventana de entidades comerciales debe generar tranquilamente 200 de estas sentencias; y esto solo para crear un modelo en memoria de los metadatos relacionados con la ventana). En conclusión: se duplica el número de accesos al servidor.
Mi pregunta si hay alguna forma de evitar que DB verifique el nivel de aislación. En realidad no entiendo porque lo hace; se supone que el nivel de aislación no debería ser cambiado desde otros puntos del sistema sobre estas “conexiones por defecto” de DB; y si esto es posible (ya que las apis de JDBC lo permiten) se podría solucionar con una clase “wraper” o “proxy” que no permita cambiar el nivel a otra cosa que no sea READ_COMMITED (aunque no se si funcionaria… ya que puede traer problemas a nivel de JDBC) o si no… meter mano en el driver y que AbstractJdbc2Connection.getTransactionIsolation() cachee el nivel de aislación como lo hace en el caso de readOnly().

PD : las fuentes de la versión del driver JDBC que está usando libertya actualmente si no me equivoco son estas (lo son?) http://jdbc.postgresql.org/download/postgresql-jdbc-8.1-405.src.tar.gz por si quieren debuggear(me costo un tiempo darme cuenta que era esta versión especifica). Dicho sea de paso, ese build especifico es bastante viejo http://jdbc.postgresql.org/changes.html#version_8.1-405 y parece que se le corrigieron bastantes bugs (el build mas reciente de la misma versión es de julio del año pasado; igual parecen ser bugs muy específicos y es muy poco probable que afecten a libertya)

PD 2: Bueno, con respecto a CPreparedStatement vs CStatement si llegue una conclusión: generan las mismas cantidades de acceso al servidor en contra de la idea que tenia (esto es debido a que el driver de postgres no hace un acceso al servidor cuando en PreparedStatement es creado; lo hace la primera vez que es ejecutado y el mismo acceso envía la sentencia SQL junto con los parámetros).

[Federico Cristina]

Javier,

Este thread da para charlar bastante al respecto!

Quisiera enfocarme en un tema específico, sobre las líneas de DB… parece que estamos frente a un caso de “miedo al setter”. Lo he visto en algunos beforeSaves de POs que vienen de las viejas versiones, en los cuales es un error seguro. Aquí no estaría seguro de afirmar que está mal, si la operación setTransactionIsolation fuese mucho mas costosa en tiempo que el getTransationIsolation, entonces estaría bien evitar hacer el set lo mas posible.

En definitiva, ¿notaste una diferencia en la performance al forzar el set, en lugar de consultar todas las veces? El siguiente paso sería debatir sobre el set propiamente dicho… pero bueno, un paso a la vez

Saludos,
Federico

[Javier Ader]

Bueno, mi idea era evitar directamente tanto el get como el set; si se supone que las conexiones en el pool que busca getConnectionRO ya son readonly y READ_COMMITED, porque habría que hacer el “rechequeo y reseteo”.
La única forma que veo que estas conexiones pierdan estas características es que desde otro punto código haya algo como

Connection conn = DB.getConnectionRO();
conn.setReadOnly(false); O
conn.setTransactionIsolation(algo distinto a READ_COMMITED).

Pero no entiendo porque se habría de hacer esto (si se necesita una conexión con parámetros especiales, entonces ese código especifico la debería crear de manera excepcional y no andar tocando las que están en el pool de DB).
Haciendo una búsqueda de llamadas a Connection.setTransactionIsolation se ve que es llamada solamente en las clases DB_Orable, DB_Sybase (que no deben estar en uso supongo), DB_Posgres , CConnection, DB (getConnectionRO y getConnectionRW) [no termino de entender bien estas clases, pero parece que las conexiones son cacheadas en mas de un lugar]. A Connection.setReadOnly es solo llamado desde DB.getConnectionRO (y seguro que es ejecutado solo una vez por cada conexión creada). DB.getConnectionRO es llamada a su vez en pocos puntos.

Ahora me pongo a hacer un test: básicamente voy a comentar
la siguientes lineas en DB.getConnectionRO
if( !connection.isReadOnly()) {
connection.setReadOnly( true );
}

if( connection.getTransactionIsolation() != Connection.TRANSACTION_READ_COMMITTED ) {
connection.setTransactionIsolation( Connection.TRANSACTION_READ_COMMITTED );
}

y agregar un setReadOnly(true) al momento de crear el pool (porque eso si es necesario hacerlo al menos una vez). Si no me equivoco casi todas (por no decir todos) los accesos generados en al carga de ventanas usan la conexiones RO de DB.
Después voy a hacer un test de tiempo de carga de la ventana Endidades comerciales. Supongo que accediendo a un server en la misma maquina que usa el cliente (como es mi caso) tal vez no haya tanta diferencia (cuando hice el sniffeo, los paquetes generados por el “SHOW TRANSACTION…” tardan relativamente poco en la red; son paquetes chicos); ahora, en un red local, las cosas se deben hacer un poco más graves.

PD : no entendí bien el miedo al setter que comentas (jajaj pero si, en algún momento lo vi en el código como comentario), pero el setReadOnly y el setIsolationLevel si hay que tenerles un poco de “miedo”; disparan excepciones cuando hay una transacción en curso (http://cvs.pgfoundry.org/cgi-bin/cvsweb.cgi/jdbc/pgjdbc/org/postgresql/jdbc2/AbstractJdbc2Connection.java?rev=1.54&content-type=text/x-cvsweb-markup ) pero no creo que te refieras a esto ya que las conexiones en el pool de DB son “autocommit” (y ahí nunca ha problemas… creo)

[Javier Ader]

Ok, ahí hice el test… no parece haber “terribles” diferencias salvo que haya hecho algo mal…
El testing lo hice principalemnte a travez de AWIndow.initWindow y Env.getgetMWindowVO (este ultimo siempre es invoda indirectametne por initWindow; asi que el tiempo que este leva es siempre un parte de lo que lleva initWindow).
Lo hice en 3 pasos:
1) modificar DB para mantener contadores de rechequeos
DB.java

Code:

//se agregan estos campos para el testin
public static int vecesRechequeosConnRO = 0;
public static int vecesConnRONoEsReadOnly =0;
public static int vecesConnRONoEsReadCommited = 0;

//cambiar el codigo origianal en DB.getConnectionRO()
else{
if( !connection.isReadOnly()) {
connection.setReadOnly( true );
}
if( connection.getTransactionIsolation() !=
Connection.TRANSACTION_READ_COMMITTED ) {
connection.setTransactionIsolation(
Connection.TRANSACTION_READ_COMMITTED );
}
}

//por lo sig para llevar lo contadores y mostrar
//cuando se cambia realemten readOnly o el nivel de aislacion
else{
DB.vecesRechequeosConnRO++;
if( !connection.isReadOnly()) {
DB.vecesConnRONoEsReadOnly++;
System.out.println(“ConnRO NO isReadOnly”);
connection.setReadOnly( true );
}

if( connection.getTransactionIsolation() !=
Connection.TRANSACTION_READ_COMMITTED ) {
System.out.println(“ConnRO NO READ_COMMITED”);
DB.vecesConnRONoEsReadCommited++;
connection.setTransactionIsolation(
Connection.TRANSACTION_READ_COMMITTED );
}
}

Cargue una vez libertya para ver realemtne cuantas veces
se llamaba a connection.setReadOnly() y connection.setTransactionIsolation () y esto se ve que es llamado solo en tiempo de logueo y una sola vez (bueno, a mi me pararecion 5 veces “ConnRO NO isReadOnly” en la consola; no entendi muy bien porque fueron 5 y no 3 que creo que es el numero de conexiones RO en el pool…. raro, despues debuggueo un poco). En cualquier caso setTransactionIsolation no es llamado ni una sola vez (e.d, la conexiones son creadads en modo READ_COMMITED y esta propiedad no es cambiada mas; al menos despues de cargar liberyta y abrir un par de ventanas).
Esto me llevo a la siguiente modificacion para crear la conexiones del pool en modo read only de entrada (al principio de DB.getConnectionRO):

Code:

synchronized( s_cc ) // use as mutex as s_connection is null the first time
{
if( s_connections == null ) {
s_connections = createConnections(
Connection.TRANSACTION_READ_COMMITTED ); / see below

//EDIT: este for tiene que estar dento del if anterior… si no todo el tiempo se setan a readonly…
//test: modificaciones para crear en modo read only de entrada
for (int i = 0; i

Volví a cargar libertya y ahora no aparecio ni un solo “ConnRO NO isReadOnly”; lo cual me “probo” que las conexiones RO una vez que son creadas no pasan a ser de “escritura”.

Bueno, ahora agregue el sig. codigo para que me muestre por pantalla cuando acceso inncesarios se producen por getTransactionIsolation(), tanto a partir de Env.getMWIndowsVO como AWIndows.initWindow:

AWindow.initWindow (lo nuevo entre comentarios “test”)

Code:

public boolean initWindow( int AD_Window_ID,MQuery query ) {
this.setName( “AWindow_” + AD_Window_ID );

//test
long miliInicio = System.currentTimeMillis();
int vecesRechequeosConnROInicio = DB.vecesRechequeosConnRO;
//fin test

boolean loadedOK = m_APanel.initPanel( 0,AD_Window_ID,query, m_realFrame );

commonInit();

//test
long miliFin = System.currentTimeMillis();
int vecesRechequeosConnROFin = DB.vecesRechequeosConnRO;
System.out.println(“Tiempo de carga de AWindow.initWindow (mls): ” +
(miliFin – miliInicio));
System.out.println(“Cantidades de recheos en DB.getConnectionRO: ” +
(vecesRechequeosConnROFin – vecesRechequeosConnROInicio) );
//fin test

return loadedOK;
} // initWindow

Para testear Env.getMWIndowVO modificando APanel.initPanel (linea 670 mas o menos)

Code:

//test
long miliInicio = System.currentTimeMillis();
int vecesRechequeosConnROInicio = DB.vecesRechequeosConnRO;
//fin test

MWindowVO wVO = AEnv.getMWindowVO( m_curWindowNo,m_mWorkbench.getWindowID( wb ),0 );

//test
long miliFin = System.currentTimeMillis();
int vecesRechequeosConnROFin = DB.vecesRechequeosConnRO;
System.out.println(“Tiempo de carga de AEnv.getMWindowVO (mls): ” +
(miliFin – miliInicio));
System.out.println(“Cantidades de recheos en DB.getConnectionRO: ” +
(vecesRechequeosConnROFin – vecesRechequeosConnROInicio) );
//fin test

Bueno, recompile y cargue libertya; abri 4 veces la ventana Entidades Comerciales (previamente seteando “mostrar pestañas contables” asi se cargaban mas pestañas) y los resultados que me mostro al consola estan en *1

Ahora, para testear la mejora de no hacer los rechequeos simplemente comente en DB.getConnectionRO las siguientes lineas

Code:

else{
DB.vecesRechequeosConnRO++;
/* COMENTADO PARA TESTEAR POSIBLES MEJORAS de no rechequear
if( !connection.isReadOnly()) {
DB.vecesConnRONoEsReadOnly++;
System.out.println(“ConnRO NO isReadOnly”);
connection.setReadOnly( true );
}

if( connection.getTransactionIsolation() !=
Connection.TRANSACTION_READ_COMMITTED ) {
System.out.println(“ConnRO NO READ_COMMITED”);
DB.vecesConnRONoEsReadCommited++;
connection.setTransactionIsolation(
Connection.TRANSACTION_READ_COMMITTED );
}

FIN DE COMENTARIO*/
}

(DB.vecesRechequeosConnRO++; no lo comento)

Recompile y volvi a correr libertya y a abrir 4 veces seguidas la ventana entidad comerciales, los resultados en *2

Datos de testeo:
-XP Home; Celeron 2 Ghz, 640mb de ram (bastante viejita…)
-cliente y servidor en la misma maquina
-acceso via ip privada de red local (NO localhost; aunque es probable que usando localhost tarde mas; Windows es poco serio para ciertas cosas… )
-versión libertya 10.03, loc AR, loqueando en perfil Administrador, con lenguaje ES-AR
-carga del servidor: mínima (solo un cliente accediendo; servidor de aplicaciones no cargado)

Resultados

*1) Permitiendo recheos (como se hace actualmente, salvo que las conexiones del pool se crea read only de entrada)

Entidades comerciales
1)
Tiempo de carga de AEnv.getMWindowVO (mls): 8453
Cantidades de recheos en DB.getConnectionRO: 252
Tiempo de carga de AWindow.initWindow (mls): 21703
Cantidades de recheos en DB.getConnectionRO: 421
2)
Tiempo de carga de AEnv.getMWindowVO (mls): 4000
Cantidades de recheos en DB.getConnectionRO: 238
Tiempo de carga de AWindow.initWindow (mls): 11735
Cantidades de recheos en DB.getConnectionRO: 414

3)
Tiempo de carga de AEnv.getMWindowVO (mls): 4016
Cantidades de recheos en DB.getConnectionRO: 240
Tiempo de carga de AWindow.initWindow (mls): 13000
Cantidades de recheos en DB.getConnectionRO: 407

4)
Tiempo de carga de AEnv.getMWindowVO (mls): 3578
Cantidades de recheos en DB.getConnectionRO: 238
Tiempo de carga de AWindow.initWindow (mls): 10047
Cantidades de recheos en DB.getConnectionRO: 407

Promedio de initWindow a partir de 2 (ya que la carga de la primer ventana hace accesos a datos que luego son cacheados; por ej AD_Msg si mal no recuero es leído y cacheado por completo):
((11735 +13000 + 10047) /3) = 11594 milisegundos
(e.d, 11,594 segundos)

*2)Evitando rechequeos
1)
Tiempo de carga de AEnv.getMWindowVO (mls): 6282
Cantidades de recheos en DB.getConnectionRO: 252
Tiempo de carga de AWindow.initWindow (mls): 17782
Cantidades de recheos en DB.getConnectionRO: 422
2)
Tiempo de carga de AEnv.getMWindowVO (mls): 3281
Cantidades de recheos en DB.getConnectionRO: 238
Tiempo de carga de AWindow.initWindow (mls): 9906
Cantidades de recheos en DB.getConnectionRO: 408
3)
Tiempo de carga de AEnv.getMWindowVO (mls): 3203
Cantidades de recheos en DB.getConnectionRO: 238
Tiempo de carga de AWindow.initWindow (mls): 9984
Cantidades de recheos en DB.getConnectionRO: 407
4)
Tiempo de carga de AEnv.getMWindowVO (mls): 2843
Cantidades de recheos en DB.getConnectionRO: 238
Tiempo de carga de AWindow.initWindow (mls): 9140
Cantidades de recheos en DB.getConnectionRO: 407
promedio a partir de 2:
(9906 + 9984 + 9140)/ 3=9676

Conclusiones (medio apresuradas; lo debería haber ejecutado mas veces…):

-en promedio, para la ventana entidades comerciales se generan cerca de 410 accesos a la base de datos que bajo mi hipótesis son innecesarios (el valor varia en los tests al parecer por que existen otros threads corriendo concurrente que también usan el pool de conexiones esporadicamente para obtener info de la base de datos; esto incrementa el contador de manera variable, pero muy pocas veces)[obivamente estos accesos dependende de la “complejidad” de la ventana; en particular cada uno del campos que son de tipo table, tabledir, busqueda generan uno o dos accesos cada uno; testar cuantas veces se llama a MLookupFactory.getLookupInfo por ej).

-evitando los rechequeos bajo las condiciones dadas (y sin contar la primer carga), AWindow.initWindow da un mejora de aproximada de 11594 – 9676 = 1918 milisegundos; esto es un mejora en rendimiento del 1918 / 11594 = 16 %

Observaciones sobre otros escenarios de testeo:

-es posible que bajo las siguientes condiciones las diferencias sean mas visibles
a) mayor carga en el servidor (esto es, bajo mi escenario, el servidor respondía casi inmediatamente a los accesos generados por los rechequeos; no se si sera el caso cuando se le conecten concurretemente digamos 10 clientes y el servidor de aplicaciones)
b) clientes en otra maquina distinta a la que corre el posgress; bajo estas condiciones los accesos de rechequeo son mas costosos ya que entra a jugar el round-trip de la red (el cual es si mismo es peor cuando bajo la red hay mucha carga en general… ni hablar si el cliente corre externamente, por ej, desde Internet)

– yo me enfoque solo en la carga inicial de las ventanas, pero esta situación muy probablemente exista en otros casos en haya un acceso masivo al servidor (excluyendo las partes en que se usan transacciones “not null”, ya que como puse al principio, usarlas implica que DB saltee “naturalmente” los chequeos); se me viene a la cabeza la generación de informe (aca los accesos innecesarios pueden ser mucho mas variables y depender principalmente del tamaño del informe y no tanto de su complejidad), sería interesante testear estos otros puntos “criticos”.

PD: En cuanto a la carga de ventanas se me viene ocurriendo una forma de recachear la info necesaria para cargar una ventana dada; por ej, los objetos MWIndowVO los veo “potencialmente” cacheables (la complejidad proviene de cuando dejar de cachearlos…. me imagine enfoques un par de enfoques, por ej usar triggers a nivel de base de datos que mantengan contadores que se incrementen cada vez que se modifica de alguna manera alguna de estas tablas, pero no los veo para nada simples); esto evita TODOs los acceso necesarios a los metadatos para generar la ventana en si (pero en este caso; me imagino incluso otra forma mas simple: que las ventanas por defecto no se cierren; se minimicen o se oculten; al querer reabrir otra vez una ventana anterior, simpelemente se muestra la ventana anterior, posiblemente dandole la info para que rellea los datos y se posiciones en la primer pestaña)… pero bueno, esto es un poco más ambicioso y no lo pense mucho (el tema es que si anduviese todo este tema de accesos innecesarios tendría mucho menos impacto, al menos con respecto a la carga de ventanas)

PD 2: espero que alguien realice estos testeos en sus propias instalaciones… por alguna razón tengo la sensación que mi escenario no es el más apropiado (principalmente por lo lento de mi maquina… entre esperar 11 segundos a esperar 9 no hay diferencia desde el punto de vista del usuario; hay un punto en que da lo mismo desde el punto de vista subjetivo… otra cosa sería entre esperar 3 segundos vs esperar 1)

[Federico Cristina]

Muchas gracias por los tomarte el tiempo de realizar todos estos testeos!

Muy probablemente en conexiones de acceso remoto a la aplicación, o incluso en una lan con un servidor bastante “atareado”, se note la diferencia.

Las optimizaciones en cuanto a performance siempre vienen bien, y estoy seguro que a lo largo de todo el proyecto hay bastante para mejorar a fin de minimizar los tiempos de respuesta. Esperemos poder aplicar estos conocimientos para el próximo release!

Saludos!
Federico

[Autor]

Entradas