Added database deadlock debugging

DatabaseCursor.cpp

@@ -7,11 +7,19 @@ DatabaseCursor::DatabaseCursor(CQuery *query, int *timeoutms)
 	: query(query), transaction_lock(false), tries(60), timeoutms(timeoutms), lastErr(SQLITE_OK), _has_error(false)
 {
 	query->setupStepping(timeoutms);
+
+#ifdef DEBUG_QUERIES
+	active_query=new ScopedAddActiveQuery(query);
+#endif
 }
 
 DatabaseCursor::~DatabaseCursor(void)
 {
 	query->shutdownStepping(lastErr, timeoutms, transaction_lock);
+
+#ifdef DEBUG_QUERIES
+	delete active_query;
+#endif
 }
 
 bool DatabaseCursor::next(db_single_result &res)

DatabaseCursor.h

@@ -3,6 +3,7 @@
 
 #include "Interface/DatabaseCursor.h"
 #include "Interface/Object.h"
+#include "Query.h"
 
 class CQuery;
 
@@ -24,6 +25,10 @@ private:
 	int *timeoutms;
 	int lastErr;
 	bool _has_error;
+
+#ifdef DEBUG_QUERIES
+	ScopedAddActiveQuery *active_query;
+#endif
 };
 
 #endif //DATABASECURSOR_H_

Query.cpp

@@ -35,6 +35,13 @@
 #include "Database.h"
 #include "DatabaseCursor.h"
 #include <memory.h>
+#include <algorithm>
+#include "stringtools.h"
+
+#ifdef DEBUG_QUERIES
+IMutex* CQuery::active_mutex;
+std::vector<std::string> CQuery::active_queries;
+#endif
 
 CQuery::CQuery(const std::string &pStmt_str, sqlite3_stmt *prepared_statement, CDatabase *pDB)
 	: stmt_str(pStmt_str), cursor(NULL)
@@ -58,6 +65,13 @@ CQuery::~CQuery()
 	delete cursor;
 }
 
+void CQuery::init_mutex(void)
+{
+#ifdef DEBUG_QUERIES
+	active_mutex=Server->createMutex();
+#endif
+}
+
 void CQuery::Bind(const std::string &str)
 {
 	int err=sqlite3_bind_text(ps, curr_idx, str.c_str(), (int)str.size(), SQLITE_TRANSIENT);
@@ -282,6 +296,8 @@ db_nresults CQuery::ReadN(int *timeoutms)
 	bool transaction_lock=false;
 	int tries=60; //10min
 
+	ScopedAddActiveQuery active_query(this);
+
 	setupStepping(timeoutms);
 	
 	db_nsingle_result res;
@@ -309,6 +325,8 @@ db_results CQuery::Read(int *timeoutms)
 	bool transaction_lock=false;
 	int tries=60; //10min
 
+	ScopedAddActiveQuery active_query(this);
+
 	setupStepping(timeoutms);
 
 	db_single_result res;
@@ -362,8 +380,13 @@ int CQuery::step(db_single_result& res, int *timeoutms, int& tries, bool& transa
 				if(tries==-1)
 				{
 				  Server->Log("SQLITE: Long runnning query  Stmt: ["+stmt_str+"]", LL_ERROR);
+				  showActiveQueries(LL_ERROR);
+				}
+				else
+				{
+					Server->Log("SQLITE_BUSY in CQuery::Read  Stmt: ["+stmt_str+"]", LL_INFO);
+					showActiveQueries(LL_INFO);
 				}
-				Server->Log("SQLITE_BUSY in CQuery::Read  Stmt: ["+stmt_str+"]", LL_INFO);
 			}
 		}
 		else if( err==SQLITE_ROW )
@@ -476,8 +499,13 @@ int CQuery::stepN(db_nsingle_result& res, int *timeoutms, int& tries, bool& tran
 				if(tries==-1)
 				{
 				  Server->Log("SQLITE: Long running query  Stmt: ["+stmt_str+"]", LL_ERROR);
+				  showActiveQueries(LL_ERROR);
+				}
+				else
+				{
+					Server->Log("SQLITE_BUSY in CQuery::ReadN  Stmt: ["+stmt_str+"]", LL_INFO);
+					showActiveQueries(LL_INFO);
 				}
-				Server->Log("SQLITE_BUSY in CQuery::ReadN  Stmt: ["+stmt_str+"]", LL_INFO);
 			}
 		}
 		else if( err==SQLITE_ROW )
@@ -535,4 +563,38 @@ std::string CQuery::getErrMsg(void)
 	return std::string(sqlite3_errmsg(db->getDatabase()));
 }
 
+void CQuery::addActiveQuery(const std::string& query_str)
+{
+#ifdef DEBUG_QUERIES
+	IScopedLock lock(active_mutex);
+	if(std::find(active_queries.begin(), active_queries.end(),
+		query_str)==active_queries.end())
+	{
+		active_queries.push_back(query_str);
+	}
+#endif
+}
+
+void CQuery::removeActiveQuery(const std::string& query_str)
+{
+#ifdef DEBUG_QUERIES
+	IScopedLock lock(active_mutex);
+	std::vector<std::string>::iterator iter =
+		std::find(active_queries.begin(), active_queries.end(),
+				  query_str);
+	active_queries.erase(iter);
+#endif
+}
+
+void CQuery::showActiveQueries(int loglevel)
+{
+#ifdef DEBUG_QUERIES
+	IScopedLock lock(active_mutex);
+	for(size_t i=0;i<active_queries.size();++i)
+	{
+		Server->Log("Active query("+nconvert(i)+"): "+active_queries[i], loglevel);
+	}
+#endif
+}
+
 #endif

Query.h

@@ -1,4 +1,8 @@
+#ifndef CQUERY_H_
+#define CQUERY_H_
+
 #include "Interface/Query.h"
+#include "Interface/Mutex.h"
 
 struct sqlite3_stmt;
 struct sqlite3;
@@ -6,12 +10,18 @@ struct sqlite3;
 class CDatabase;
 class DatabaseCursor;
 
+#define DEBUG_QUERIES
+
+class ScopedAddActiveQuery;
+
 class CQuery : public IQuery
 {
 public:
 	CQuery(const std::string &pStmt_str, sqlite3_stmt *prepared_statement, CDatabase *pDB);
 	~CQuery();
 
+	static void init_mutex(void);
+
 	virtual void Bind(const std::string &str);
 	virtual void Bind(const std::wstring &str);
 	virtual void Bind(int p);
@@ -47,9 +57,46 @@ public:
 private:
 	bool Execute(int timeoutms);
 
+	void addActiveQuery(const std::string& query_str);
+	void removeActiveQuery(const std::string& query_str);
+	void showActiveQueries(int loglevel);
+
 	sqlite3_stmt *ps;
 	std::string stmt_str;
 	CDatabase *db;
 	int curr_idx;
 	DatabaseCursor *cursor;
+
+#ifdef DEBUG_QUERIES
+	static IMutex* active_mutex;
+	static std::vector<std::string> active_queries;
+#endif
+
+	friend class ScopedAddActiveQuery;
 };
+
+class CQuery;
+
+class ScopedAddActiveQuery
+{
+public:
+	ScopedAddActiveQuery(CQuery* query)
+		: query(query)
+	{
+#ifdef DEBUG_QUERIES
+		query->addActiveQuery(query->stmt_str);
+#endif
+	}
+
+	~ScopedAddActiveQuery()
+	{
+#ifdef DEBUG_QUERIES
+		query->removeActiveQuery(query->stmt_str);
+#endif
+	}
+
+private:
+	CQuery* query;
+};
+
+#endif //CQUERY_H_

Server.cpp

@@ -54,6 +54,7 @@
 #include "SQLiteFactory.h"
 #include "PipeThrottler.h"
 #include "mt19937ar.h"
+#include "Query.h"
 
 
 
@@ -128,6 +129,8 @@ void CServer::setup(void)
 	CDatabase::initMutex();
 	registerDatabaseFactory("sqlite", new SQLiteFactory );
 #endif
+
+	CQuery::init_mutex();
 }
 
 void CServer::destroyAllDatabases(void)