On May 12, 2014, at 2:30 PM, Sylvester Steele <sylvesterste...@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.
>
>
> 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!
>
> --
> 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+unsubscr...@googlegroups.com.
> To post to this group, send email to sqlalchemy@googlegroups.com.
> Visit this group at http://groups.google.com/group/sqlalchemy.
> For more options, visit https://groups.google.com/d/optout.
--
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+unsubscr...@googlegroups.com.
To post to this group, send email to sqlalchemy@googlegroups.com.
Visit this group at http://groups.google.com/group/sqlalchemy.
For more options, visit https://groups.google.com/d/optout.
