Granny's Programming Pearls
"inside of every large program is a small program struggling to get out"
JavaRanch.com/granny.jsp
  • Post Reply
  • Bookmark Topic Watch Topic
  • New Topic

delay in db insertion

 
shweta misra
Greenhorn
Posts: 10
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
Hi,

Following is the snippet of the java code which inserts a record into a table.
The insert query insertCDRSQL2 is also given below. When this code is executed the observation is that the logger CDR generation successfully is printed at 11.31 pm in the log file but in the db the column TRANSACTION_DATETIME of the record inserted shows 11.34 pm. There is a 3 min delay in actually writing the record. This happens intermittently for some inserts.

I want to know what could be the problem here and why there could be a delay.




try {

conn = ocsgds.getConnection();
pre_stmt = conn.prepareStatement(insertCDRSQL2);


…..
pre_stmt.executeUpdate();
logger.info("CDR generation successfully");

}catch (Exception e) {
logger.error("Error in generating CDRs in the DB",e);
throw e;

}





INSERT INTO CUSTOM_CDR(TRANSACTION_ID,TRANSACTION_DATETIME, CIRCLE ......)
" VALUES(?,systimestamp,??........)

 
Christophe Verré
Sheriff
Posts: 14691
16
Eclipse IDE Ubuntu VI Editor
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
1. Are the clock of the database server and the clock of the machine where your application runs set at the same time ?
2. When is the transaction committed ?
 
Martin Vajsar
Sheriff
Posts: 3752
62
Chrome Netbeans IDE Oracle
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
The log message is the same for every call. How do you match the log messages with inserted rows? How often is the method called?
 
shweta misra
Greenhorn
Posts: 10
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
Hi Christophe,
We assumed the clocks should be the same because we see this issue intermittently. not for all the requests. I will however get the clocks checked.
Since auto commit is on by default we havent committed the transactions explicitly.


Hi Martin,
The log message actually looks something like this logger.info("CDR generated successfully for transcation id "+transcationId);
We compare the transactionid in the log and the one in the TRANSACTION_ID column of the table
We have a load of 400-500TPS and a record is written in the db for every successfull transaction. So this method is called for every successfull transaction. in our analysis so far , for every 50 successful transactions we see this issue in 7-8 transactions and the delay is always 3 min.
 
Martin Vajsar
Sheriff
Posts: 3752
62
Chrome Netbeans IDE Oracle
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
Is the message to the log actually written before or after the insert statement has been executed?

(If the message is actually logged after the insert statement returns, I wouldn't have any explanation for that. If it is logged before the insert statement returns, well - something in the database or on the network might cause delay in the insert. I'm not sure I would be able to help with that myself, but at least we would know what we're looking for.)
 
shweta misra
Greenhorn
Posts: 10
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
The message is logged after the insert statement is executed.

when we execute an insert statement , is the record immediately written into the db or is it put into some db queue from where its picked and then executed ?? in our case , the logger is printed after the insert statement. does this mean that the record should be written into the db by that time or is it possible that the query is accepted by the db but not processed
 
Jaikiran Pai
Marshal
Pie
Posts: 10447
227
IntelliJ IDE Ubuntu
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
The insert query insertCDRSQL2 is also given below. When this code is executed the observation is that the logger CDR generation successfully is printed at 11.31 pm in the log file but in the db the column TRANSACTION_DATETIME of the record inserted shows 11.34 pm. There is a 3 min delay in actually writing the record. This happens intermittently for some inserts.


Your code shows that you are getting a connection from a datasource:



DataSources typically enroll the connection in a transaction. The data is committed only when the transaction completes. It does not necessarily have to be when the method which does the insert ends. It all depends on the transaction boundaries i.e. when the transaction is created and completed. You'll have to take a look at the entire code flow to understand what controls the transaction lifespan.
 
Martin Vajsar
Sheriff
Posts: 3752
62
Chrome Netbeans IDE Oracle
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
Jaikiran Pai wrote:DataSources typically enroll the connection in a transaction. The data is committed only when the transaction completes. It does not necessarily have to be when the method which does the insert ends. It all depends on the transaction boundaries i.e. when the transaction is created and completed. You'll have to take a look at the entire code flow to understand what controls the transaction lifespan.

True, but the systimestamp function is evaluated at the time the insert statement happens, isn't it? Even if the commit happens a minute or an hour later, the value in the column should match the time when the insert statement was executed.

Which database are you using, Shweta? Do you have any triggers defined in your database? Do you have any other processes that could modify the table?

Edit: I don't know of any database which would queue up statements, returned to the caller and then processed them, at least unless explicitly instructed to process the query asynchronously. Furthermore, I'm not aware of JDBC supporting asynchronous executions.
 
Jaikiran Pai
Marshal
Pie
Posts: 10447
227
IntelliJ IDE Ubuntu
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
Martin Vajsar wrote:
Jaikiran Pai wrote:DataSources typically enroll the connection in a transaction. The data is committed only when the transaction completes. It does not necessarily have to be when the method which does the insert ends. It all depends on the transaction boundaries i.e. when the transaction is created and completed. You'll have to take a look at the entire code flow to understand what controls the transaction lifespan.

True, but the systimestamp function is evaluated at the time the insert statement happens, isn't it? Even if the commit happens a minute or an hour later, the value in the column should match the time when the insert statement was executed.

That's a good point. I hadn't paid attention to that part.


 
shweta misra
Greenhorn
Posts: 10
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
We are using Oracle 10g DB and no ... we are not using any triggers or process to modify this table.

btw we just found that the clock of one our DB instance was actually fast. so we have raised a request to bring it in sync. will then monitor the system.
hopefully this will resolve the issue. thanks for this pointer.


 
Martin Vajsar
Sheriff
Posts: 3752
62
Chrome Netbeans IDE Oracle
  • Mark post as helpful
  • send pies
  • Quote
  • Report post to moderator
So to sum it up: you have a RAC and records inserted by one instance appear right, while records inserted by the other instance have the insertion date set to the future. Neat!

A quick search on the internet seems to indicate that unsynced clock on a RAC can potentially lead to other, much more serious problems. You probably should set up a time server to keep the clocks in sync (preferably over all of your infractructure, of course )
 
  • Post Reply
  • Bookmark Topic Watch Topic
  • New Topic