Slow query performance in embedded mode

[rcoe]

I was surprised at how long a simple query with a join was taking and so tested my application with postgres.  For H2, I implemented a jdbcConnectionPool and for postgres, I used the Tomcat jdbc-pool.  The following shows the performance for executing the same query several times in each Db.  I am using postgres 9.1 and H2 1.3.167.

Below are some relevant statistics.  Any thoughts on how I can improve the H2 numbers?  From the H2 performance page I expected 10x the postgres performance.

By the way, the H2 Db is fully compacted and is used in strictly read-only mode, so no fragmentation.

====== PGSQL ====== 

 INFO [main] (SystemScanner.java:102) - Starting system scanner.

 INFO [main] (DbConnectionFactory.java:76) - Using datasource URL: jdbc:postgresql://localhost:5432/db.

 INFO [main] (SystemScanner.java:118) - ...entering monitoring mode.

 INFO [SocketListener] (SocketListener.java:73) - Starting socket listener.

 INFO [SocketListener] (SocketListener.java:79) - ...listening on localhost:8180

 INFO [SocketListener] (ServerSocketHandler.java:28) - Opening socket handler for incoming connection: /127.0.0.1:52237

DEBUG [ServerSocketHandler] (FileRecordDAO.java:38) - Executing com.xxxxx.da.dao.FileRecordDAO getMatchingFileRecords( "AST_" ) produced 569 results and took 2236 ms.

 INFO [ServerSocketHandler] (ClientSocket.java:86) - Closing socket from /127.0.0.1:52237

 INFO [SocketListener] (ServerSocketHandler.java:28) - Opening socket handler for incoming connection: /127.0.0.1:52238

DEBUG [ServerSocketHandler] (FileRecordDAO.java:38) - Executing com.xxxxx.da.dao.FileRecordDAO getMatchingFileRecords( "AST_" ) produced 569 results and took 600 ms.

 INFO [ServerSocketHandler] (ClientSocket.java:86) - Closing socket from /127.0.0.1:52238

 INFO [SocketListener] (ServerSocketHandler.java:28) - Opening socket handler for incoming connection: /127.0.0.1:52239

DEBUG [ServerSocketHandler] (FileRecordDAO.java:38) - Executing com.xxxxx.da.dao.FileRecordDAO getMatchingFileRecords( "AST_" ) produced 569 results and took 544 ms.

 INFO [ServerSocketHandler] (ClientSocket.java:86) - Closing socket from /127.0.0.1:52239

 INFO [Thread-3] (SystemScanner.java:194) - SocketListener shutdown.

 INFO [Thread-3] (SocketListener.java:148) - Shutting down socket listener.

 INFO [Thread-3] (SocketListener.java:158) - ...closed.  No longer accepting connections.

 INFO [Thread-3] (DbConnectionFactory.java:185) - Executing pre-shutdown command for PGSQL database.

====== H2 ====== 

 INFO [main] (SystemScanner.java:102) - Starting system scanner.

 INFO [main] (DbConnectionFactory.java:76) - Using datasource URL: jdbc:h2:C:\Users\xxx\workspace\SystemScanner/db.

DEBUG [main] (H2DataSourceFactory.java:72) - Debug state initialized.

 INFO [main] (SystemScanner.java:118) - ...entering monitoring mode.

 INFO [SocketListener] (SocketListener.java:73) - Starting socket listener.

 INFO [SocketListener] (SocketListener.java:79) - ...listening on localhost:8180

 INFO [SocketListener] (ServerSocketHandler.java:28) - Opening socket handler for incoming connection: /127.0.0.1:52240

DEBUG [ServerSocketHandler] (FileRecordDAO.java:38) - Executing com.xxxxx.da.dao.FileRecordDAO getMatchingFileRecords( "AST_" ) produced 81 results and took 46955 ms.

 INFO [ServerSocketHandler] (ClientSocket.java:86) - Closing socket from /127.0.0.1:52240

 INFO [SocketListener] (ServerSocketHandler.java:28) - Opening socket handler for incoming connection: /127.0.0.1:52241

DEBUG [ServerSocketHandler] (FileRecordDAO.java:38) - Executing com.xxxxx.da.dao.FileRecordDAO getMatchingFileRecords( "AST_" ) produced 81 results and took 4061 ms.

 INFO [ServerSocketHandler] (ClientSocket.java:86) - Closing socket from /127.0.0.1:52241

 INFO [SocketListener] (ServerSocketHandler.java:28) - Opening socket handler for incoming connection: /127.0.0.1:52242

DEBUG [ServerSocketHandler] (FileRecordDAO.java:38) - Executing com.xxxxx.da.dao.FileRecordDAO getMatchingFileRecords( "AST_" ) produced 81 results and took 4247 ms.

 INFO [ServerSocketHandler] (ClientSocket.java:86) - Closing socket from /127.0.0.1:52242

I haven't yet tested H2 in client-server mode.

The resource_ref table has a foreign key to the lookup table -- the lookup table is a many-to-one back to the resource_ref table.  The H2 query returns 38601 records, the postgres query returns 63380.  The postgres db has 3 288 821 lookup records, while H2 only has 1 525 717.

Here are the plans:

H2:

SELECT DISTINCT

    UID,

    PATH,

    FILENAME,

    LASTTOUCHED,

    CREATEDTIME,

    UPDATEDTIME

FROM (

    SELECT

        RESOURCEID

    FROM DB.LOOKUP

        /* DB.IDX_LOOKUPKEY: LOOKUPKEY >= 'AST'

            AND LOOKUPKEY < 'ASU'

         */

    WHERE LOOKUPKEY LIKE 'AST%'

) LOOKUP

    /* SELECT

        RESOURCEID

    FROM DB.LOOKUP

        /++ DB.IDX_LOOKUPKEY: LOOKUPKEY >= 'AST'

            AND LOOKUPKEY < 'ASU'

         ++/

    WHERE LOOKUPKEY LIKE 'AST%'

     */

    /* scanCount: 38602 */

INNER JOIN DB.RESOURCE_REF RESOURCE

    /* DB.PRIMARY_KEY_7: UID = LOOKUP.RESOURCEID */

    ON 1=1

    /* scanCount: 77202 */

WHERE RESOURCE.UID = LOOKUP.RESOURCEID

ORDER BY 3

/*

total: 14372

LOOKUP.IDX_LOOKUPKEY read: 293 (2%)

LOOKUP.LOOKUP_DATA read: 5135 (35%)

PAGE_INDEX.PAGE_INDEX_DATA read: 2 (0%)

RESOURCE_REF.RESOURCE_REF_DATA read: 2584 (17%)

TEMP_RESULT_SET_34.TEMP_RESULT_SET_34 read: 3286 (22%)

TEMP_RESULT_SET_34.TEMP_RESULT_SET_34_DATA read: 3072 (21%)

*/

PGSQL:

 Unique  (cost=102449.56..103639.47 rows=67995 width=58) (actual time=1269.422..1379.455 rows=63380 loops=1)

   ->  Sort  (cost=102449.56..102619.54 rows=67995 width=58) (actual time=1269.421..1364.431 rows=63814 loops=1)

         Sort Key: resource.filename, resource.uid, resource.path, resource.lasttouched, resource.createdtime, resource.updatedtime

         Sort Method: external merge  Disk: 4208kB

         ->  Merge Join  (cost=69973.26..94433.39 rows=67995 width=58) (actual time=593.265..835.823 rows=63814 loops=1)

               Merge Cond: (resource.uid = db.lookup.resourceid)

               ->  Index Scan using resource_ref_pkey on resource_ref resource  (cost=0.00..21907.08 rows=605796 width=58) (actual time=0.007..154.629 rows=606402 loops=1)

               ->  Materialize  (cost=69973.23..70313.20 rows=67995 width=8) (actual time=593.244..610.836 rows=63814 loops=1)

                     ->  Sort  (cost=69973.23..70143.22 rows=67995 width=8) (actual time=593.241..603.593 rows=63814 loops=1)

                           Sort Key: db.lookup.resourceid

                           Sort Method: external sort  Disk: 1128kB

                           ->  Seq Scan on lookup  (cost=0.00..63584.56 rows=67995 width=8) (actual time=0.044..543.486 rows=63814 loops=1)

                                 Filter: ((lookupkey)::text ~~ 'AST%'::text)

 Total runtime: 1382.849 ms

[Thomas Mueller]

Hi,

From the H2 performance page I expected 10x the postgres performance.

I'm sorry if the performance page makes you think H2 is 10x faster than PostgreSQL across the board. That's not what I want it to look like. The reason why H2 embedded could run 10 times more operations within the same time than PostgreSQL is because the operations in the benchark were quite simply. I will change the documentation to say:

"Please note this is mostly a single connection benchmark run on one computer, *with many very simple operations running against the database. This benchmark does not include very complex queries. The embedded mode of H2 is faster than the client-server mode because the per-statement overhead is greatly reduced.*"

One reason why PostgreSQL is faster than H2 is that in this case, H2 stored the result set in a temporary table (TEMP_RESULT_SET_34). The reason is that the result set is large. Large result sets is an area where H2 is relatively weak I'm afraid. Another possible explanation why PostgreSQL is that much faster than H2 is that maybe PostgreSQL has the data in the cache, while maybe H2 (embedded mode) not; but I'm not sure.

Regards,

Thomas