FWD » Core Development » Database

• _temp doesn't use c3p0 and it shouldn't; this is out of scope
• _meta still uses c3p0 and this shall be investigated
• _dirty still uses c3p0 and this shall be investigated

Review of 11288a / r16469

I think the code is good. Except for restricting the direct connection only to in-memory non-primary databases and keeping the pooling for primary H2 databases, pretty much of the observations below are about code style.

• ConnectionProvider.java
  • lines 2-62: please remove the space character at the beginning (paste artifact);
  • lines 67-70: the package import should be used instead of individual classes;
  • lines 83, 231: empty lines to be dropped;
  • lines 109, 227: although the detection of H2 is probably correct, I think the discriminator here should be if the url jdbc:h2:mem:. That is because we can have standalone H2 database server, and connections pooling is certainly better. The truth is, to my knowledge, this is only used in developing environments, not in production. But still, I think the direct access should be used only in case of in-memory databases, not to all databases backed by H2;
  • lines 139, 197: methods getConnectionURL() and getH2Connection() can be private;
  • lines 140, 198, 224: incorrect indentation (also due to paste operation, I think);

• JdbcDataSource.java
  • line 103: why is dataSource no longer private?
  • lines 137-165: I appreciate the refactoring. The method looks much better now.
  • line 256: the defaulting to TenantManager.DEFAULT_TENANT_NAME was dropped. Is this performed in some other place?

Ovidiu Maxiniuc wrote:

Review of 11288a / r16469

• line 256: the defaulting to TenantManager.DEFAULT_TENANT_NAME was dropped. Is this performed in some other place?

Yes, getConnectionURL accounts for a null tenant, but this was done only for retrieving the url, in getDataSource it is also needed to create the correct data source, so removing the defaulting to the default tenant here was a mistake on my part, thank you for catching it.

I addressed all the issues, please review rev 16470.

I tested the multi tenant application since it's the most complex in terms of the db infrastructure. I spotted no regressions and the connection management is as expected.

I think we can merge this one.

11288a was merged to trunk/16471.

Since this task was derived from #11282, I assume the patch should be delivered to the custom branch also?

Artur, trunk/16471 seems to have a regression. The new ConnectionProvider.getH2Connection is missing this piece of code which causes #7143-1846.

         // setup the blob and clob creators
         Dialect dialect = Dialect.getDialect(settings);
         TypeManager.addBlobCreator(jdbcUrl, dialect::blobCreator);
         TypeManager.addClobCreator(jdbcUrl, dialect::clobCreator);

Artur: Please update Open Regressions in FWD v4 with the details.

Ovidiu, I also added cfg initialization.

Constantin,
There is an issue with an unit test from the large gui application suite, I need to see what is is first, please remove the branch from the queue.

Artur Școlnic wrote:

With direct connections, close() is immediate. So the sequence was effectively:
1. setBlob, execute, commit, connection closes
2. LOB stream not fully written yet

I don't understand this - are you saying there is some async processing in the background?

Are you sure that setString and setBytes works for H2? Also, what about the getter - is that blocking?

Constantin Asofiei wrote:

I don't understand this - are you saying there is some async processing in the background?

Not necessarily, I think it has to do with how the binary data is streamed, with direct connect not all the data reached the database.

Are you sure that setString and setBytes works for H2?

Yes, already tested.

Please check if we are not re-using a prepared statement after the connection has closed. Also, post a small test, please.,

I agree.
The drop of c3p0 pooling support for in-memory databases was just an optimisation, as proven by the initial entries in this task.
Since it caused regressions, the logical option for a fast and save solution is to roll 11288a back until we have a fix for it and also for the new issues discovered.

Alex: can you take care of the rollback?

Alex: can you take care of the rollback?

Now is WIP.

Alexandru Lungu wrote:

Branch 11288c was merged into trunk as rev. 16478 and archived.

Please also patch 10614_main

Done:

Port of trunk/16478: Reverted changes done by 11288a in trunk/16471. (refs: #11288)

Ovidiu Maxiniuc wrote:

I agree.
The drop of c3p0 pooling support for in-memory databases was just an optimisation, as proven by the initial entries in this task.
Since it caused regressions, the logical option for a fast and save solution is to roll 11288a back until we have a fix for it and also for the new issues discovered.

This change was about more than optimizing performance; it was about reducing complexity and removing a point of failure where the wrong configuration of the connection pool could cause problems. We needed to make sure it wouldn't make performance worse, but any performance gain was secondary.

Constantin wrote:

we need to better understand why 11288b still fails after adding the lob creators - Artur's findings are not clear, there is no async processing of the lob in H2; so my thinking we are closing a connection and somehow that is reused.

Yes, we do. Artur's analysis in #11288-24 suggests that with c3p0, the lob processing is working by side effect of a connection remaining open for some time after it is returned to the pool. Since that connection can be closed at any moment or re-assigned to do unrelated work, we can't rely on the rollback of 11288a alone to fix this.

Artur Școlnic wrote:

With c3p0, this worked by accident because connection.close() doesn't actually close the connection, it returns it to the pool. That means the connection stayed alive a bit longer, giving H2 enough time to finish writing the LOB data in the background.

I'm sorry, something does not make sense here.

What if we do not properly close the connection? I just guessing that C3P0 takes care to do a flush of all associated data before the actual close routine.

At any rate, before calling close() on the connection, a transaction (even a direct commit) should execute the commit first. I imagine this include the LOB data for the processed records. It is pretty illogical to return with success but the transaction data is not fully saved into database. This breaks both the atomicity of the transactions and the data sanity/integrity.

Ovidiu Maxiniuc wrote:

Artur Școlnic wrote:

With c3p0, this worked by accident because connection.close() doesn't actually close the connection, it returns it to the pool. That means the connection stayed alive a bit longer, giving H2 enough time to finish writing the LOB data in the background.

I'm sorry, something does not make sense here.

What if we do not properly close the connection? I just guessing that C3P0 takes care to do a flush of all associated data before the actual close routine.

At any rate, before calling close() on the connection, a transaction (even a direct commit) should execute the commit first. I imagine this include the LOB data for the processed records. It is pretty illogical to return with success but the transaction data is not fully saved into database. This breaks both the atomicity of the transactions and the data sanity/integrity.

I agree with Ovidiu that the "side effect" theory doesn't fully make sense. Are we going with Ovidiu's theory above about implicit transaction commit on connection check-in? How do we finally prove or disprove that this is why the code is working with c3p0 (and not without it)?

If we understand why it is working with c3p0, this should inform us as to how to make it work without c3p0, if we determine that's faster/better. If OTOH, we determine the current implementation is actually working only by side effect, that cannot remain as is; it must be more robust than that, with or without c3p0.

Ovidiu, Alexandru, Artur: how do we get closure on this one?

I need to use 11288a again and find the recreate based on the failing unit test in the customer application. At this point a better understanding of the blob issue is more important than any performance difference, since it could be small to none in a real application.

The test case without connection pooling is:

procedure main :
   do transaction on error undo, throw:
       create blob_table.
       assign blob_table.id = "1".
       copy-lob from file search('file.xml':U) to blob_table.blb no-convert. // inserts dmo in dirty db  

       run findBlob.   
  end.

end procedure.

procedure findBlob:
    define buffer blob_table for blob_table.
    find first blob_table. // fails
    message available blob_table.    
end procedure.    

run main.   

Dirty share must be enabled.

The error log

26/05/19 12:56:35.022+0300 |  SEVERE | com.goldencode.p2j.util.ErrorManager | ThreadName:Conversation [00000001:bogus], Session:00000001, ThreadId:00000005, User:bogus | ** FIND FIRST/LAST failed for table blob_table. (565)
26/05/19 12:56:35.072+0300 |  SEVERE | com.goldencode.p2j.util.ErrorManager | ThreadName:Conversation [00000001:bogus], Session:00000001, ThreadId:00000005, User:bogus | stack trace follows
com.goldencode.p2j.persist.PersistenceException: com.goldencode.p2j.persist.PersistenceException: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: "java.io.IOException: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: ""Missing lob entry: 1"" [90028-200]"; "lob: null table: -3 id: 1" [90031-200]
Caused by: com.goldencode.p2j.persist.PersistenceException: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: "java.io.IOException: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: ""Missing lob entry: 1"" [90028-200]"; "lob: null table: -3 id: 1" [90031-200]
Caused by: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: "java.io.IOException: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: ""Missing lob entry: 1"" [90028-200]"; "lob: null table: -3 id: 1" [90031-200]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:505)
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
    at org.h2.message.DbException.get(DbException.java:194)
    at org.h2.message.DbException.convertIOException(DbException.java:394)
    at org.h2.value.ValueLobDb.getInputStream(ValueLobDb.java:430)
    at org.h2.jdbc.JdbcBlob.getBytes(JdbcBlob.java:84)
    at com.goldencode.p2j.util.blob.readData(blob.java:281)
    at com.goldencode.p2j.util.blob.<init>(blob.java:177)
    at com.goldencode.p2j.persist.orm.types.BlobType.readProperty(BlobType.java:171)
    at com.goldencode.p2j.persist.orm.BaseRecord.readProperty(BaseRecord.java:1432)
    at com.goldencode.p2j.persist.orm.Loader.readScalarData(Loader.java:669)
    at com.goldencode.p2j.persist.orm.Loader.load(Loader.java:586)
    at com.goldencode.p2j.persist.orm.Loader.load(Loader.java:503)
    at com.goldencode.p2j.persist.orm.Session.getImpl(Session.java:810)
    at com.goldencode.p2j.persist.orm.Session.get(Session.java:693)
    at com.goldencode.p2j.persist.dirty.DefaultDirtyShareManager.update(DefaultDirtyShareManager.java:643)
    at com.goldencode.p2j.persist.dirty.DirtyShareContext.update(DirtyShareContext.java:552)
    at com.goldencode.p2j.persist.RecordNursery$RecordsStash.updateDirty(RecordNursery.java:735)
    at com.goldencode.p2j.persist.RecordNursery$UpdatedRecordsStash.notifyRemoved(RecordNursery.java:1046)
    at com.goldencode.p2j.persist.RecordNursery$RecordsStash.remove(RecordNursery.java:617)
    at com.goldencode.p2j.persist.RecordNursery.remove(RecordNursery.java:340)
    at com.goldencode.p2j.persist.orm.Validation.flush(Validation.java:647)
    at com.goldencode.p2j.persist.orm.Validation.validateMaybeFlush(Validation.java:378)
    at com.goldencode.p2j.persist.RecordBuffer.validateMaybeFlush(RecordBuffer.java:11730)
    at com.goldencode.p2j.persist.RecordBuffer.flush(RecordBuffer.java:7376)
    at com.goldencode.p2j.persist.RecordBuffer.validate(RecordBuffer.java:6837)
    at com.goldencode.p2j.persist.TxWrapper$WorkArea.validate(TxWrapper.java:976)
    at com.goldencode.p2j.util.TransactionManager$WorkArea.processValidateImpl(TransactionManager.java:11081)
    at com.goldencode.p2j.util.TransactionManager$WorkArea.processValidate(TransactionManager.java:11035)
    at com.goldencode.p2j.util.TransactionManager$TransactionHelper.processValidate(TransactionManager.java:10442)
    at com.goldencode.p2j.util.BlockManager.executeStateManaged(BlockManager.java:13325)
    at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:9751)
    at com.goldencode.p2j.util.BlockManager.doBlockWorker(BlockManager.java:11047)
    at com.goldencode.p2j.util.BlockManager.doBlock(BlockManager.java:1647)
    at com.goldencode.dataset.Start.lambda$main$2(Start.java:56)
    ...
Caused by: java.io.IOException: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: "Missing lob entry: 1" [90028-200]
    at org.h2.message.DbException.convertToIOException(DbException.java:651)
    at org.h2.pagestore.db.LobStorageBackend.getInputStream(LobStorageBackend.java:337)
    at org.h2.value.ValueLobDb.getInputStream(ValueLobDb.java:428)
    ... 75 more
Caused by: org.h2.jdbc.JdbcSQLNonTransientException: IO Exception: "Missing lob entry: 1" [90028-200]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:505)
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:429)
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:415)
    at org.h2.pagestore.db.LobStorageBackend$LobInputStream.<init>(LobStorageBackend.java:664)
    at org.h2.pagestore.db.LobStorageBackend.getInputStream(LobStorageBackend.java:333)

It is crucial that the dirty db is used, since 11288a is providing new direct connections to it which seems to cause the issue.

The test case from #11288-40 is also failing with trunk, the find fails, I think the record is not persisted properly in the dirty db.

The reason for JdbcSQLNonTransientException is h2 blob persistence peculiarities, in h2 the blobs are not inserted in the table, but rather a pointer to a storage, they are tied to a connection, after a connection closes, the LobStorageBackend.removeLob is called and the blobs are removed from the underlying storage. With connection pooling this does not happen since the connection are not actually closed, but rather returned to the pool and reused (even if a close is called, it happens much later).

With setBytes no lob mapping/backing storage is done, the bytes are directly inserted in the table, this avoids the mentioned issues.

setBytes solves the JdbcSQLNonTransientException, but not the record not being found, I need to investigate this.

Artur Școlnic wrote:

setBytes solves the JdbcSQLNonTransientException, but not the record not being found, I need to investigate this.

4gl will find the dirty record regardless of the field that was changed, FWD looks in the dirty db only if an indexed field was changed.
Not sure if this is a regression or intended that way.

To further prove that the blobs are connection bound, I set setMaxConnectionAge to 1 second (close connection after 1 second, can be reused in that meantime) in c3p0, then put a sleep after the copy-lob, before the find, this resulted in the same Missing lob entry: 1 error. Theoretically, if in a client's application, a blob is inserted in the dirty/temp db and the connection that was used to create it, is not reused for the dirty find, this error will be raised. With setBytes there are no such issues for reasons I mentioned above.

Smoke-testing 11288d on a customer app passed.

Thank you, Razvan.

Constantin, please put 11288d in the merge queue when you can.

What practical performance testing can we do with and without this update?

Eric,
I don't expect performance in a customer application to be affected in a measurable way, this change was more about reducing the need for configuring the h2 databases, minor memory efficiency and solving the blob persistence mystery. The performance improvement can be seen clearly only in a standalone test case where a large number of connections are requested in a short amount of time. As a reminder, in the end we went with connection pooling for the temporary database in order to preserve statement caching and the most h2 connections are used for this database, so the performance effects of the 11288 are even smaller because of this.

Artur, please patch 10614_main with 11288a now.

11288d was ported to 10614_main rev 16417.