Concurrent raw sql execution in a multi-threaded application: Connection is busy with results for another hstmt error

[Sylvester Steele]

Hi,

I am using sqlalchemy version 0.7.6 on Win 7. I am using sqlalchemy to execute raw SQL queries in parallel. Here is how I do it:

eng = get_engine() #Threadsafe method to get engine

raw_con = eng.connect().connection.connection

raw_con.autocommit= True

crsr = raw_con.cursor()

res = crsr.execute (qry, *multiparams) #multiparams is empty in my case

raw_con.autocommit= False

If it is a select query:

    res_fetched = res.fetchall()

res.close()

Sometimes, I get Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

Looking at the logs I can see that two queries were indeed running together- one was a bulk insert (an update query) and another was a select query. 

If it is a select query:

    res_fetched = res.fetchall()

is just a convenient\brief way of writing it here. I actually have separate select and update functions, that call the 'execute' function. The select function will then do a fetchall, but the update function will not.

From the docs here:

The Connection object is a facade that uses a DBAPI connection internally in order to communicate with the database. This connection is procured from the connection-holdingPool referenced by this Engine. When the close() method of the Connection object is called, the underlying DBAPI connection is then returned to the connection pool, where it may be used again in a subsequent call to connect().

If I understand the above correctly, and assuming that the engine connect function is thread safe, the two queries running simultaneously should be running with different raw_con objects. 

Not sure why I am running into this error. 

Thanks!

[Michael Bayer]

the code here isn’t really showing me the nature of the two separate connections.   They will be different unless you’re using “threadlocal” on the engine or pool and both are in the same thread.  A simple comparison of the “raw” DBAPI connections to see if they are different objects will suffice (make sure you’re on the ultimate DBAPI connection though, not the “fairy” object).   However note that Microsoft ODBC drivers also feature connection pooling, so you’d need to turn it off at the ODBC configuration level as well.

[Sylvester Steele]

the code here isn’t really showing me the nature of the two separate connections.   They will be different unless you’re using “threadlocal” on the engine or pool and both are in the same thread.  A simple comparison of the “raw” DBAPI connections to see if they are different objects will suffice (make sure you’re on the ultimate DBAPI connection though, not the “fairy” object).   However note that Microsoft ODBC drivers also feature connection pooling, so you’d need to turn it off at the ODBC configuration level as well.

Hopefully the following details will help. Here is the sanitized code and logs:

class QueryObj (object):            

#blah blah

def select (qry, other params):

 #This is simplified from the real code

eng = get_engine() #Threadsafe method to get engine

raw_con = eng.connect().connection.connection

logger.debug("Raw connection %s" % raw_con)

crsr = raw_con.cursor()

logger.debug("Cursor: %s" % cursor)

raw_con.autocommit= True

res = crsr.execute (qry, *multiparams) #multiparams is empty here

raw_con.autocommit= False

res_fetched = res.fetchall()

res.close()

class ParTest (Thread):

    def __init__(self):

        Thread.__init__(self)

        

    def run (self):

        q = QueryObj (My params)

        for _ in range(5):

          try:

            resultset= q.select("My query which takes a few seconds", other params like Db etc.)

            except Exception:

            pass

            

def main ():

    lst = []

    for i in range(10):

        lst.append(ParTest())

    for i in range(10):

        lst[i].start()

Here is the log (apologies for the rather lengthy log). The structure of the log statements is:

Thread id - timestamp - level - log statement

30848 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

26188 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

30148 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

31624 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

27788 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

30624 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

31008 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

14832 - 2014-05-12 13:05:32,104 - DEBUG - Start query: My query

22108 - 2014-05-12 13:05:32,102 - DEBUG - Start query: My query

30364 - 2014-05-12 13:05:32,104 - DEBUG - Start query: My query

30848 - 2014-05-12 13:05:32,246 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3870>

30848 - 2014-05-12 13:05:32,246 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000004A74B10>

26188 - 2014-05-12 13:05:32,259 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3978>

26188 - 2014-05-12 13:05:32,260 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000004A74B70>

31624 - 2014-05-12 13:05:32,272 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED39D0>

31624 - 2014-05-12 13:05:32,273 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000004A74C90>

30148 - 2014-05-12 13:05:32,285 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3A28>

30148 - 2014-05-12 13:05:32,286 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000004A74BD0>

30624 - 2014-05-12 13:05:32,298 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3A80>

30624 - 2014-05-12 13:05:32,299 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000004A74CF0>

27788 - 2014-05-12 13:05:32,358 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3AD8>

31008 - 2014-05-12 13:05:32,358 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3B30>

14832 - 2014-05-12 13:05:32,358 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3B88>

22108 - 2014-05-12 13:05:32,358 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3BE0>

30364 - 2014-05-12 13:05:32,358 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3C38>

27788 - 2014-05-12 13:05:32,359 - ERROR - Error: Attempt to use a closed connection.. Query My query 

Traceback (most recent call last):

  File "QueryObj.py", line 503, in execute

    cursor = raw_con.cursor()

ProgrammingError: Attempt to use a closed connection.

31008 - 2014-05-12 13:05:32,359 - ERROR - Error: Attempt to use a closed connection.. Query My query 

Traceback (most recent call last):

  File "QueryObj.py", line 503, in execute

    cursor = raw_con.cursor()

ProgrammingError: Attempt to use a closed connection.

14832 - 2014-05-12 13:05:32,361 - ERROR - Error: Attempt to use a closed connection.. Query My query 

Traceback (most recent call last):

  File "QueryObj.py", line 503, in execute

    cursor = raw_con.cursor()

ProgrammingError: Attempt to use a closed connection.

22108 - 2014-05-12 13:05:32,361 - ERROR - Error: Attempt to use a closed connection.. Query My query 

Traceback (most recent call last):

  File "QueryObj.py", line 503, in execute

    cursor = raw_con.cursor()

ProgrammingError: Attempt to use a closed connection.

30364 - 2014-05-12 13:05:32,362 - ERROR - Error: Attempt to use a closed connection.. Query My query 

Traceback (most recent call last):

  File "QueryObj.py", line 503, in execute

    cursor = raw_con.cursor()

ProgrammingError: Attempt to use a closed connection.

27788 - 2014-05-12 13:05:32,365 - ERROR - Error Attempt to use a closed connection. fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

ProgrammingError: Attempt to use a closed connection.

31008 - 2014-05-12 13:05:32,367 - ERROR - Error Attempt to use a closed connection. fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

ProgrammingError: Attempt to use a closed connection.

14832 - 2014-05-12 13:05:32,368 - ERROR - Error Attempt to use a closed connection. fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

ProgrammingError: Attempt to use a closed connection.

22108 - 2014-05-12 13:05:32,368 - ERROR - Error Attempt to use a closed connection. fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

ProgrammingError: Attempt to use a closed connection.

30364 - 2014-05-12 13:05:32,368 - ERROR - Error Attempt to use a closed connection. fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

ProgrammingError: Attempt to use a closed connection.

27788 - 2014-05-12 13:05:32,369 - DEBUG - Start query: My query

31008 - 2014-05-12 13:05:32,371 - DEBUG - Start query: My query

14832 - 2014-05-12 13:05:32,371 - DEBUG - Start query: My query

22108 - 2014-05-12 13:05:32,372 - DEBUG - Start query: My query

30364 - 2014-05-12 13:05:32,374 - DEBUG - Start query: My query

27788 - 2014-05-12 13:05:32,374 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3870>

31008 - 2014-05-12 13:05:32,375 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3978>

14832 - 2014-05-12 13:05:32,375 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED39D0>

22108 - 2014-05-12 13:05:32,375 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3A28>

30364 - 2014-05-12 13:05:32,377 - DEBUG - Raw connection <pyodbc.Connection object at 0x0000000007ED3A80>

27788 - 2014-05-12 13:05:32,377 - DEBUG - Cursor: <pyodbc.Cursor object at 0x00000000080EBF90>

31008 - 2014-05-12 13:05:32,378 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000008181030>

14832 - 2014-05-12 13:05:32,378 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000008181090>

22108 - 2014-05-12 13:05:32,378 - DEBUG - Cursor: <pyodbc.Cursor object at 0x00000000081810F0>

30364 - 2014-05-12 13:05:32,380 - DEBUG - Cursor: <pyodbc.Cursor object at 0x0000000008181150>

27788 - 2014-05-12 13:05:32,381 - ERROR - Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)'). Query My query on ,

Traceback (most recent call last):

  File "QueryObj.py", line 508, in execute

    res = cursor.execute (qry, *multiparams)

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

31008 - 2014-05-12 13:05:32,381 - ERROR - Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)'). Query My query on ,

Traceback (most recent call last):

  File "QueryObj.py", line 508, in execute

    res = cursor.execute (qry, *multiparams)

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

14832 - 2014-05-12 13:05:32,381 - ERROR - Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)'). Query My query on ,

Traceback (most recent call last):

  File "QueryObj.py", line 508, in execute

    res = cursor.execute (qry, *multiparams)

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

22108 - 2014-05-12 13:05:32,381 - ERROR - Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)'). Query My query on ,

Traceback (most recent call last):

  File "QueryObj.py", line 508, in execute

    res = cursor.execute (qry, *multiparams)

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

30364 - 2014-05-12 13:05:32,382 - ERROR - Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)'). Query My query on ,

Traceback (most recent call last):

  File "QueryObj.py", line 508, in execute

    res = cursor.execute (qry, *multiparams)

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

27788 - 2014-05-12 13:05:32,384 - ERROR - Error ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)') fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

31008 - 2014-05-12 13:05:32,384 - ERROR - Error ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)') fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

14832 - 2014-05-12 13:05:32,385 - ERROR - Error ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)') fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

22108 - 2014-05-12 13:05:32,385 - ERROR - Error ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)') fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

30364 - 2014-05-12 13:05:32,387 - ERROR - Error ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)') fetching results. 

Traceback (most recent call last):

  File "QueryObj.py", line 999, in select

    res= execute (selectQry, My params)

  File "QueryObj.py", line 666, in execute

    raise e

Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)')

[Removed log statements]

30848 - 2014-05-12 13:06:40,200 - DEBUG - Finish query: My query

[Removed log statements]

What the code does:

 The code is simply trying to run in parallel, a query that takes a few seconds to execute.

Notes on the log statements:

For thread id 27788 - When this thread starts for the first time, it gets the pyodbc connection object at 7ED3AD8. This object is not being used by any other thread, yet it encounters ProgrammingError: Attempt to use a closed connection. Why would this be?

Later, at 13:05:32,374- thread id 27788 retries. It gets pyodbc connection 7ED3870, and cursor 80EBF90. This pyodbc connection (but not this cursor) was already given to thread id 30848 at 13:05:32,246, and is still in use there. Hence, when 27788 tries to execute a query it runs into: Error: ('HY000', '[HY000] [Microsoft][ODBC SQL Server Driver]Connection is busy with results for another hstmt (0) (SQLExecDirectW)').

It does seem like the error being thrown is legitimate, given that the connection is actually being used elsewhere. I do not understand why the engine.connect() function, when executed by thread id 27788 returns the pyodbc object at 7ED3870, while it is being used in thread id 30848. Is this expected? 

My understanding of how this pool works is: 30848 checks out the connection from the pool when it runs the eng.connect() statement. This connection is returned to the pool only when the res.close() statement is run, which is after all the results have been fetched. While the connection has been checked out, the pool should not be giving the same connection to other threads.

I also tried turning off the ODBC connection pooling by going to the control panel, that did not help either.

Thanks for your help!

[Michael Bayer]

On May 12, 2014, at 2:30 PM, Sylvester Steele <sylvest...@gmail.com> wrote:

the code here isn’t really showing me the nature of the two separate connections.   They will be different unless you’re using “threadlocal” on the engine or pool and both are in the same thread.  A simple comparison of the “raw” DBAPI connections to see if they are different objects will suffice (make sure you’re on the ultimate DBAPI connection though, not the “fairy” object).   However note that Microsoft ODBC drivers also feature connection pooling, so you’d need to turn it off at the ODBC configuration level as well.

Hopefully the following details will help. Here is the sanitized code and logs:

well the create_engine() statement isn’t here which is really what would illustrate if you’re doing some kind of thread local thing up there.  It looks a lot like your ODBC driver is pooling connections, as we see lots of pyodbc.connection objects with different identifiers, but yet it says the connection is busy with other results, additionally we see that you have a cursor local to select() yet some kind of error is being raised lots which illustrates continuous “connection closed” issues.

so same answer, look to see that you don’t have anything thread local on your engine and look that you don’t have pooling in your ODBC driver turned on.

--
You received this message because you are subscribed to the Google Groups "sqlalchemy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sqlalchemy+...@googlegroups.com.
To post to this group, send email to sqlal...@googlegroups.com.
Visit this group at http://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.

[Sylvester Steele]

On Mon, May 12, 2014 at 4:53 PM, Michael Bayer <mik...@zzzcomputing.com> wrote:

On May 12, 2014, at 2:30 PM, Sylvester Steele <sylvest...@gmail.com> wrote:

the code here isn’t really showing me the nature of the two separate connections.   They will be different unless you’re using “threadlocal” on the engine or pool and both are in the same thread.  A simple comparison of the “raw” DBAPI connections to see if they are different objects will suffice (make sure you’re on the ultimate DBAPI connection though, not the “fairy” object).   However note that Microsoft ODBC drivers also feature connection pooling, so you’d need to turn it off at the ODBC configuration level as well.

Hopefully the following details will help. Here is the sanitized code and logs:

well the create_engine() statement isn’t here which is really what would illustrate if you’re doing some kind of thread local thing up there.  It looks a lot like your ODBC driver is pooling connections, as we see lots of pyodbc.connection objects with different identifiers, but yet it says the connection is busy with other results, additionally we see that you have a cursor local to select() yet some kind of error is being raised lots which illustrates continuous “connection closed” issues.

so same answer, look to see that you don’t have anything thread local on your engine and look that you don’t have pooling in your ODBC driver turned on.

I will look again. The engine creation logic is quite separate from the query execution logic. The code that creates engines is threadsafe to make sure that only one engine is created per session per DB. So, all these threads would be using the exact same engine (because the query that they are all executing goes to the same DB). The first thread which reaches the select function will be the only thread to actually create an engine. This engine is then cached and reused by all other threads.

[Sylvester Steele]

Looks like I finally figured it out. I enabled sqlalchemy pool logging and found that as soon as the object returned by eng.connect() goes out of scope the connection is returned to the pool. In the above code- that happens near instantly. So, the sqlalchemy pool thinks that this connection is checked in the pool and available for use. But, in reality the code is still using it. Keeping the object returned by eng.connect() until the result set is fetched seems to have solved the problem. 

ODBC connection pooling setting did not matter. After the above change, code is running in both cases (ODBC connection pooling on or pooling off).

Let me know if this is an issue and you need more info.

Thanks

[Michael Bayer]

On May 13, 2014, at 2:23 PM, Sylvester Steele <sylvest...@gmail.com> wrote:

ODBC connection pooling setting did not matter. After the above change, code is running in both cases (ODBC connection pooling on or pooling off).

Let me know if this is an issue and you need more info.

OK so I’m guessing you did something like this:

conn = engine.connect()

raw_connection = conn.connection.connection

del conn   # conn goes out of scope

so yeah, that will break like that.   What you can do is stick with “conn.connection” at least, that’s the so-called “Connection Fairy” which will keep the DBAPI connection checked out until it goes out of scope.

[Sylvester Steele]

Correct, that is what I did. Except, I do a conn.close() at the end rather than a del.

--
You received this message because you are subscribed to a topic in the Google Groups "sqlalchemy" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/sqlalchemy/hRyAeD0xWv0/unsubscribe.
To unsubscribe from this group and all its topics, send an email to sqlalchemy+...@googlegroups.com.