Search code examples
javasql-serverhibernatet-sqlsqljdbc

Sql Server query from java/hibernate randomly times out when called within a loop


I encounter a weird problem while trying to perform a sql query from a java call to sqlserver.

A single call to the java function goes well, but when I do the same within a loop (from 2 to 30 iterations), I sometimes (not always) got such an error :

Caused by: com.microsoft.sqlserver.jdbc.SQLServerException: Le délai imparti à la requête a expiré. at com.microsoft.sqlserver.jdbc.TDSCommand.checkForInterrupt(IOBuffer.java:5918)

The few things I noticed :

  • It always fail at the same step of the loop, provided the iterated item remain unchanged (eg, if it fails at step 7 of 15, it will always fail at step 7!)
  • It will fail at another step if I skip or change any iterated item, including the previously failing one... and it does not fail at the next step, but - what looks like - at a random one
  • If I copy/paste the failing query (from debugging) into SqlQueryBrowser and execute it : it works
  • If I copy/paste the failing query from Sql Server Profiler : it works!
  • If I execute the loop from within sql server query browser (iterating over input parameters) : it works!
  • If I execute the loop from within a JUnit Test, only iterating over the paremeters : it also works!!
  • From Sql Server Profiler, I can see the successfull requests take 200 to 600 ms to complete when the failing one takes exactly 15000 ms ( = currently configured timeout)
  • When I change the timeout, the query keeps timing out.

This is what I tried to perform, with no success :

  • Use one transaction per step / query
  • Update server 'connect timeout' et 'query timeout' through sp_serveroption (EXEC sp_serveroption 'myServer\SQLEXPRESS', 'connect timeout', 45;)
  • Change queryTimeout from java
  • Change "query wait" option from Sql Query Browser {Server} > "properties" > "advanced" > "parallelism"
  • Do not drop the temporary table #MATCHINGDAYS
  • Add a random token to #MATCHINGDAYS to prevent concurrency conflicts
  • Add BEGIN / END around the query
  • Delay the request with WAITFOR DELAY t
  • use a stored procedure instead of a string holding the request
  • perform a flush + clear of the session from within the "finally" statement.
  • Restart of the SqlServer + tomcat
  • Update driver to mssql-jdbc 6.1.0.jre7
  • Use an actual table instead of a temporary one

the java call

(It is embedded in a single transaction)

final SessionImpl sess = (SessionImpl) this.getSessionFactory().openSession();
try (Connection conn = sess.connection(); Statement st = conn.createStatement();) {
    final NamedParameterPreparedStatement ps = NamedParameterPreparedStatement.createNamedParameterPreparedStatement(conn, aStringWithTheRequestBelow);
        // ... set parameters here ...
    ps.setQueryTimeout(15);
    final ResultSet rs = ps.executeQuery();
} catch (final SQLException ex) {
    LOG.error("parameter 1 :" + parameter1 + "etc.");
} finally {
    sess.close();
}

the TSQL query

(I made it brain-and-eyes-friendly, but it is a little more tricky that what it looks like; but basicely, you have the idea of it)

--DECLARE @date as DATE = '2017-09-03'; -- one of the input parameter set up from java.


IF OBJECT_ID('tempdb.dbo.#MATCHINGDAYS718567154','U') is not null 
DROP TABLE #MATCHINGDAYS718567154; -- RANDOM TOKEN HERE TO AVOID CONCURRENCY

WITH startDateTable AS ( 
    SELECT TOP 1 a.dateStart 
    FROM   someSelection
), 
endDateTable AS ( 
    SELECT TOP 1 endDate
    FROM   anotherSelection
), 
AllDays  AS ( 
    SELECT myFunc_getMaxDate(DATEADD(DAY,1,startDateTable.dateStart), DATEADD(dd, -30,@date))AS [Date] 
    FROM startDateTable 
    UNION ALL 
    SELECT    
    DATEADD(DAY, 1, [Date]) 
    from  AllDays 
    join endDateTable on 1=1 
     WHERE    [Date] < myFunc_getMinDate(DATEADD(dd, +7, @date),endDateTable.endDate)) 


-- build a temporary table with all days from startDate to endDate the recursive way
-- with a min -30 days before input date and 7 days after output date    
SELECT [Date] 
     INTO #MATCHINGDAYS718567154 
         FROM    AllDays 
     OPTION (MAXRECURSION 37) 

SELECT   
    manyFields

from MainTable
-- various joins
join #MATCHINGDAYS718567154 as MD on 1 = 1 
where 1 = 1
and -- etc... many clauses including some computed over MATCHINGDAYS718567154

order by someField

DROP TABLE #MATCHINGDAYS718567154 

Some other info

  • java 1.7_071
  • hibernate 4.3.4.Final
  • SqlServer Express 2014
  • Tomcat 7
  • sqljdbc4 4.0

Edit 28/11 : THE CAUSE

somewhere in my loop, an object from the same table of the the queried item is inserted from time to time. It is performed in a separated transaction (though I also tried to perform it in the same transaction). The problem does not occur on the iteration when the object is inserted, but in the following iteration... Now, I have the cause... I still do not understand why this causes a failure on the next iteration... Though I suspect it will be perfectly obvious once I will understand it!

someIterationOver(List<SomeObject> manyObjects){
    from(SomeObject mo : manyObjects){
        List<MyTableObject> myTableObjects = performMyBigQueryOver(mo.getSomeId());
        for(MyTableObject myTableSingleObject : myTableObjects){
            if(myTableSingleObject.matchesSomeCondition()){
                TableSingleObject aNewTableSingleObject = new TableSingleObject("newTableObject");
                // this will cause the problem in the next iteration
                saveTableObject(aNewTableSingleObject);
            }
        }

    }
}

@Transactional(propagation = Propagation.REQUIRES_NEW)
private void saveTableObject(ableSingleObject aNewTableSingleObject){
    this.sessionFactory.getCurrentSession.save(aNewTableSingleObject); // works fine
}

... any tips are welcome here!


Solution

  • Eventually, I managed to have it work : moving the "saveTableObject" method from within the loop to outside of it did the trick... But although I found a solution, I still do not understand why a previous insert, embedded in its own devoted transaction, caused this lock to be maintained to the next iteration and in another transaction!... So if you have tips : they are still welcome!

    By the way, this post helped me a lot to find out which object was locked!

    @Jean : thanks a lot for your many questions that helped me focus on the core cause!