I am experiencing a strange behaviour with a PostgreSQL database and JDBC driver (in a J2EE application).
To keep it simple, let's say I have two tables :
SHIP_MESSAGE(id, datetime, latitude, longitude)
SUBMARINE_MESSAGE(id, datetime, latitude, longitude, immersion)
Each one of them contains messages that have been emited at a given datetime. Now I have to replay these informations on a website.
I am using AJAX to request the infos around every 300-500ms. The request is something like : select id, datetime, latitude, longitude from SHIP_MESSAGE where date >= '2013-02-11 18:00:00' order by date limit 1;
If I execute it once (to get the message from the first table), it takes around 150 ms, which is fine. But if I execute it twice (to get the messages from both tables), each query takes between 800 and 2000 ms !
So this works fine :
MessageDAO dao = new MessageDAO(); // Data access object, used to execute my query
Date d1 = new Date();
ShipMessage message = dao.getShipMessageAtDate(date);
Date d2 = new Date();
System.out.println( d2.getTime() - d1.getTime() ); // Around 150 ms
And this doesn't :
MessageDAO dao = new MessageDAO();
Date d1 = new Date();
NavigationMessage message = dao.getShipMessageAtDate(date);
Date d2 = new Date();
SubmarineMessage m2 = dao.getSubmarinMessageAtDate(date);
Date d3 = new Date();
System.out.println( d2.getTime() - d1.getTime() ); // Between 800 and 2000 ms
System.out.println( d3.getTime() - d2.getTime() ); // Between 800 and 2000 ms
I'm using a singleton pattern to get my connection. If I create two Connection objects, it works fine (~ 150 ms), but I don't want to do that because I won't be able to open enough connections when there will be too much clients.
Any idea ?
I tried to use a join to have only one request containing the data of both messages, but it is also too long (1-3 sec), which is weird because if I execute it directly in the terminal it is fast.
Thanks !
EDIT :
Here are the code for the MessageDAO :
public class MessageDAO extends DAO {
public MessageDAO() { super(); }
public MessageDAO(Connection connection) { super(connection); }
public NavSensorsMessage getShipMessageDate(Date date) throws SQLException {
String sql = "select * from BOAT_MESSAGE where date >= ? order by date limit 1;";
PreparedStatement ps = _connection.prepareStatement(sql);
ps.setTimestamp(1, new java.sql.Timestamp(date.getTime()));
ResultSet result = ps.executeQuery();
result.next();
Date datetime = result.getDate("datetime");
float latitude = result.getFloat("latitude");
float longitude = result.getFloat("longitude");
return new ShipMessage(datetime, latitude, longitude);
}
}
Here is the class DAO :
public abstract class DAO {
// -------------------------------------------------------------------------
protected Connection _connection;
// -------------------------------------------------------------------------
// -------------------------------------------------------------------------
// Constructors :
public DAO() { _connection = StaticPostgreSQLConnection.getInstance(); }
public DAO(Connection connection) { _connection = connection; }
// -------------------------------------------------------------------------
}
And here is the StaticPostgreSQLConnection :
public class StaticPostgreSQLConnection {
// -------------------------------------------------------------------------
private static final String _driverName = "org.postgresql.Driver";
private static final String _url = "jdbc:postgresql://localhost:5432/telesciences";
private static final String _user = "mylogin";
private static final String _password = "mypassword";
private static Connection _connection;
// -------------------------------------------------------------------------
// -------------------------------------------------------------------------
public static Connection getInstance() {
if (_connection == null) {
try {
Class.forName(_driverName);
_connection = DriverManager.getConnection(_url, _user, _password);
}
catch (ClassNotFoundException | SQLException e) { e.printStackTrace(System.err); }
}
return _connection;
}
// -------------------------------------------------------------------------
// -------------------------------------------------------------------------
public static void close() {
try {
_connection.close();
_connection = null;
}
catch (SQLException e) { e.printStackTrace(System.err); }
}
// -------------------------------------------------------------------------
// -------------------------------------------------------------------------
public static void begin() throws SQLException { getInstance().createStatement().execute("BEGIN;"); }
public static void commit() throws SQLException { getInstance().createStatement().execute("COMMIT;"); }
public static void rollback() throws SQLException { getInstance().createStatement().execute("ROLLBACK;"); }
// -------------------------------------------------------------------------
}
EDIT 2 :
Here is a piece of postgres log :
2014-02-12 11:02:02 CET LOG: durée : 0.122 ms, analyse <unnamed> : select * from NAVIGATION_MESSAGE where date >= $1 order by date limit 1
2014-02-12 11:02:02 CET LOG: durée : 0.143 ms, lien <unnamed> : select * from NAVIGATION_MESSAGE where date >= $1 order by date limit 1
2014-02-12 11:02:02 CET DÉTAIL: paramètres : $1 = '2011-07-02 01:08:05.16'
2014-02-12 11:02:02 CET LOG: exécute <unnamed>: select * from NAVIGATION_MESSAGE where date >= $1 order by date limit 1
2014-02-12 11:02:02 CET DÉTAIL: paramètres : $1 = '2011-07-02 01:08:05.16'
2014-02-12 11:02:02 CET LOG: durée : 157.295 ms
2014-02-12 11:02:02 CET LOG: durée : 0.114 ms, analyse <unnamed> : select * from NAVSENSORS_MESSAGE where date >= $1 order by date limit 1
2014-02-12 11:02:02 CET LOG: durée : 0.161 ms, lien <unnamed> : select * from NAVSENSORS_MESSAGE where date >= $1 order by date limit 1
2014-02-12 11:02:02 CET DÉTAIL: paramètres : $1 = '2011-07-02 01:08:04.88'
2014-02-12 11:02:02 CET LOG: exécute <unnamed>: select * from NAVSENSORS_MESSAGE where date >= $1 order by date limit 1
2014-02-12 11:02:02 CET DÉTAIL: paramètres : $1 = '2011-07-02 01:08:04.88'
2014-02-12 11:02:02 CET LOG: durée : 157.598 ms
Every request takes only 150 ms, so the problem is not postgres itself. I guess it comes from the way I get my connections.
log_statement = 'all'andlog_min_duration_statement = 0. Then report how long PostgreSQL says the statements took to run in the PostgreSQL logs. This will help you isolate where the delay is. Also consider enablingauto_explainand comparing the plans generated when you run it from JDBC to the plan generated when you run it by hand.select version()).