Experimental enhancements to mutex debugging.

FossilOrigin-Name: 804817549cfecbe5e1c4cea605d54cb4164f9bb6

diff --git a/manifest b/manifest
index 28095b65b67e122e7aa5f3200b7be2d46ce5fa18..23aff9da9775ed81557fcdace9821d2115decce9 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Clarification\sof\sthe\shelp\stext\sfor\sthe\scommand-line\sshell.
-D 2017-02-14T21:47:46.389
+C Experimental\senhancements\sto\smutex\sdebugging.
+D 2017-02-14T23:58:30.321
 F Makefile.in edb6bcdd37748d2b1c3422ff727c748df7ffe918
 F Makefile.linux-gcc 7bc79876b875010e8c8f9502eb935ca92aa3c434
 F Makefile.msc 067a6766f800cc8d72845ab61f8de4ffe8f3fc99
@@ -368,11 +368,11 @@ F src/mem3.c 8768ac94694f31ffaf8b4d0ea5dc08af7010a35a
 F src/mem5.c 9bf955937b07f8c32541c8a9991f33ce3173d944
 F src/memjournal.c 95752936c11dc6995672d1dd783cd633eea0cc95
 F src/msvc.h 4942752b6a253116baaa8de75256c51a459a5e81
-F src/mutex.c 8e45800ee78e0cd1f1f3fe8e398853307f4a085c
+F src/mutex.c 64604d2b9754f3698059e42316e9114823878793
 F src/mutex.h 779d588e3b7756ec3ecf7d78cde1d84aba414f85
-F src/mutex_noop.c 9d4309c075ba9cc7249e19412d3d62f7f94839c4
-F src/mutex_unix.c 27bb6cc49485ee46711a6580ab7b3f1402211d23
-F src/mutex_w32.c 3631e57d056062807ae2c92b79f3d1c05f04ecfe
+F src/mutex_noop.c 6a0ac0bd696bbc600ed94302ae10a4337791b9d0
+F src/mutex_unix.c 68ced9b5a25dda67346b45b0e0ee303e98f2f98f
+F src/mutex_w32.c 285c1f2c3eb68b7c604faadc9a8aee09c2d78a5f
 F src/notify.c 9711a7575036f0d3040ba61bc6e217f13a9888e7
 F src/os.c add02933b1dce7a39a005b00a2f5364b763e9a24
 F src/os.h 8e976e59eb4ca1c0fca6d35ee803e38951cb0343
@@ -399,7 +399,7 @@ F src/shell.c a661e7ccd202b16cb5321999354699e5ee018fb2
 F src/sqlite.h.in 751ff125eb159c8f92c182b8df980a5e4f50e966
 F src/sqlite3.rc 5121c9e10c3964d5755191c80dd1180c122fc3a8
 F src/sqlite3ext.h 8648034aa702469afb553231677306cc6492a1ae
-F src/sqliteInt.h c3f878dcbe947938f9e0984644f1902dd9051094
+F src/sqliteInt.h b8c2e9ea279edf9b544fa29cc1cea60e9f8f2145
 F src/sqliteLimit.h c0373387c287c8d0932510b5547ecde31b5da247
 F src/status.c a9e66593dfb28a9e746cba7153f84d49c1ddc4b1
 F src/table.c b46ad567748f24a326d9de40e5b9659f96ffff34
@@ -1555,7 +1555,10 @@ F vsixtest/vsixtest.tcl 6a9a6ab600c25a91a7acc6293828957a386a8a93
 F vsixtest/vsixtest.vcxproj.data 2ed517e100c66dc455b492e1a33350c1b20fbcdc
 F vsixtest/vsixtest.vcxproj.filters 37e51ffedcdb064aad6ff33b6148725226cd608e
 F vsixtest/vsixtest_TemporaryKey.pfx e5b1b036facdb453873e7084e1cae9102ccc67a0
-P 54836270c9c0bfa5910f7ad74ec238b9d7ddee5f
-R 81ac83b9aa3d80dbb34372d0527e01bd
-U drh
-Z 42f594c3c0159a4f4af8ef6e693c76a8
+P ca4f1e4962df64ae756c286f3795af7d6f692cdd
+R d6a0bafe616fe547ff07dfc42e463ec9
+T *branch * mutexDbg2
+T *sym-mutexDbg2 *
+T -sym-trunk *
+U mistachkin
+Z 92255d0c1926221a5bf48dc4677aec44

diff --git a/manifest.uuid b/manifest.uuid
index da9b31e87320abbfdbec480acf42f20774f81c5a..b8032df192793302a0cde483eca36f1115f87935 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-ca4f1e4962df64ae756c286f3795af7d6f692cdd
\ No newline at end of file
+804817549cfecbe5e1c4cea605d54cb4164f9bb6
\ No newline at end of file

diff --git a/src/mutex.c b/src/mutex.c
index 6f1bc9767db8e1a3ce002bcc10b77c72c9e6f51c..6b63c8c61685ea9be192b31538474e69ddc600b7 100644 (file)
--- a/src/mutex.c
+++ b/src/mutex.c
@@ -14,6 +14,11 @@
 ** This file contains code that is common across all mutex implementations.
 */
 #include "sqliteInt.h"
+#if SQLITE_OS_UNIX
+#  include <pthread.h>
+#elif SQLITE_OS_WIN
+#  include "os_win.h"
+#endif
 
 #if defined(SQLITE_DEBUG) && !defined(SQLITE_MUTEX_OMIT)
 /*
@@ -83,6 +88,47 @@ int sqlite3MutexEnd(void){
   return rc;
 }
 
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+/* Return a time value for use by the mutex subsystem. */
+i64 sqlite3MutexTimeOfDay(void){
+#ifdef SQLITE_GET_MUTEX_TIME
+  return SQLITE_GET_MUTEX_TIME();
+#else
+  return 0;
+#endif
+}
+
+/*
+** Calculates the elapsed time, in milliseconds, that a particular mutex
+** was held and issues a warning, via the sqlite3_log() interface, if it
+** was held for "too long".
+*/
+void sqlite3MutexTimeAlert(
+  sqlite3_mutex *p,
+  i64 entered
+){
+  i64 exited = sqlite3MutexTimeOfDay();
+  i64 elapsed;
+  assert( p!=0 );
+  assert( exited>=entered );
+  elapsed = exited - entered;
+  if( elapsed>SQLITE_MUTEX_ALERT_MILLISECONDS ){
+    void *tid = 0;
+    int mid = -1;
+#ifdef SQLITE_GET_THREAD_ID
+    tid = SQLITE_GET_THREAD_ID();
+#endif
+#ifdef SQLITE_GET_MUTEX_ID
+    mid = SQLITE_GET_MUTEX_ID(p);
+#endif
+    sqlite3_log(SQLITE_NOTICE,
+      "thread %p delayed %lldms for mutex %p (%d)",
+      tid, elapsed, p, mid
+    );
+  }
+}
+#endif
+
 /*
 ** Retrieve a pointer to a static mutex or allocate a new dynamic one.
 */

diff --git a/src/mutex_noop.c b/src/mutex_noop.c
index ecc84b4a94aeffca7782bc9331a7f2ded2915992..df733a4fc9155d9e070bc98ff1c3111580680534 100644 (file)
--- a/src/mutex_noop.c
+++ b/src/mutex_noop.c
@@ -80,6 +80,9 @@ sqlite3_mutex_methods const *sqlite3NoopMutex(void){
 typedef struct sqlite3_debug_mutex {
   int id;     /* The mutex type */
   int cnt;    /* Number of entries without a matching leave */
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  i64 entered; /* Time that mutex was entered */
+#endif
 } sqlite3_debug_mutex;
 
 /*
@@ -164,11 +167,17 @@ static void debugMutexEnter(sqlite3_mutex *pX){
   sqlite3_debug_mutex *p = (sqlite3_debug_mutex*)pX;
   assert( p->id==SQLITE_MUTEX_RECURSIVE || debugMutexNotheld(pX) );
   p->cnt++;
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  p->entered = sqlite3MutexTimeOfDay();
+#endif
 }
 static int debugMutexTry(sqlite3_mutex *pX){
   sqlite3_debug_mutex *p = (sqlite3_debug_mutex*)pX;
   assert( p->id==SQLITE_MUTEX_RECURSIVE || debugMutexNotheld(pX) );
   p->cnt++;
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  p->entered = sqlite3MutexTimeOfDay();
+#endif
   return SQLITE_OK;
 }
 
@@ -181,6 +190,9 @@ static int debugMutexTry(sqlite3_mutex *pX){
 static void debugMutexLeave(sqlite3_mutex *pX){
   sqlite3_debug_mutex *p = (sqlite3_debug_mutex*)pX;
   assert( debugMutexHeld(pX) );
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  sqlite3MutexTimeAlert((sqlite3_mutex*)p, p->entered);
+#endif
   p->cnt--;
   assert( p->id==SQLITE_MUTEX_RECURSIVE || debugMutexNotheld(pX) );
 }

diff --git a/src/mutex_unix.c b/src/mutex_unix.c
index 55d08c80522de23dfab1cfdf02fc5c91ec354336..51dfb329bb90bb40a3c077a90a4eacb21603fc52 100644 (file)
--- a/src/mutex_unix.c
+++ b/src/mutex_unix.c
@@ -43,6 +43,9 @@ struct sqlite3_mutex {
 #if SQLITE_MUTEX_NREF || defined(SQLITE_ENABLE_API_ARMOR)
   int id;                    /* Mutex type */
 #endif
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  i64 entered;               /* Time that mutex was entered */
+#endif
 #if SQLITE_MUTEX_NREF
   volatile int nRef;         /* Number of entrances */
   volatile pthread_t owner;  /* Thread that is within this mutex */
@@ -261,6 +264,9 @@ static void pthreadMutexEnter(sqlite3_mutex *p){
       p->nRef++;
     }else{
       pthread_mutex_lock(&p->mutex);
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+      p->entered = sqlite3MutexTimeOfDay();
+#endif
       assert( p->nRef==0 );
       p->owner = self;
       p->nRef = 1;
@@ -270,6 +276,9 @@ static void pthreadMutexEnter(sqlite3_mutex *p){
   /* Use the built-in recursive mutexes if they are available.
   */
   pthread_mutex_lock(&p->mutex);
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  p->entered = sqlite3MutexTimeOfDay();
+#endif
 #if SQLITE_MUTEX_NREF
   assert( p->nRef>0 || p->owner==0 );
   p->owner = pthread_self();
@@ -304,6 +313,9 @@ static int pthreadMutexTry(sqlite3_mutex *p){
       p->nRef++;
       rc = SQLITE_OK;
     }else if( pthread_mutex_trylock(&p->mutex)==0 ){
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+      p->entered = sqlite3MutexTimeOfDay();
+#endif
       assert( p->nRef==0 );
       p->owner = self;
       p->nRef = 1;
@@ -316,6 +328,9 @@ static int pthreadMutexTry(sqlite3_mutex *p){
   /* Use the built-in recursive mutexes if they are available.
   */
   if( pthread_mutex_trylock(&p->mutex)==0 ){
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+    p->entered = sqlite3MutexTimeOfDay();
+#endif
 #if SQLITE_MUTEX_NREF
     p->owner = pthread_self();
     p->nRef++;
@@ -350,9 +365,15 @@ static void pthreadMutexLeave(sqlite3_mutex *p){
 
 #ifdef SQLITE_HOMEGROWN_RECURSIVE_MUTEX
   if( p->nRef==0 ){
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+    sqlite3MutexTimeAlert(p, p->entered);
+#endif
     pthread_mutex_unlock(&p->mutex);
   }
 #else
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  sqlite3MutexTimeAlert(p, p->entered);
+#endif
   pthread_mutex_unlock(&p->mutex);
 #endif
 

diff --git a/src/mutex_w32.c b/src/mutex_w32.c
index 505c8fab7eba18cda98cbaa2506f54e51133446a..86ffbf4d1125a9509a6fc9ffd95730d395bd592f 100644 (file)
--- a/src/mutex_w32.c
+++ b/src/mutex_w32.c
@@ -37,6 +37,9 @@
 struct sqlite3_mutex {
   CRITICAL_SECTION mutex;    /* Mutex controlling the lock */
   int id;                    /* Mutex type */
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  i64 entered;               /* Time that mutex was entered */
+#endif
 #ifdef SQLITE_DEBUG
   volatile int nRef;         /* Number of enterances */
   volatile DWORD owner;      /* Thread holding this mutex */
@@ -293,6 +296,9 @@ static void winMutexEnter(sqlite3_mutex *p){
 #endif
   assert( winMutex_isInit==1 );
   EnterCriticalSection(&p->mutex);
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  p->entered = sqlite3MutexTimeOfDay();
+#endif
 #ifdef SQLITE_DEBUG
   assert( p->nRef>0 || p->owner==0 );
   p->owner = tid;
@@ -330,6 +336,9 @@ static int winMutexTry(sqlite3_mutex *p){
   }
   assert( winMutex_isNt==0 || winMutex_isNt==1 );
   if( winMutex_isNt && TryEnterCriticalSection(&p->mutex) ){
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+    p->entered = sqlite3MutexTimeOfDay();
+#endif
 #ifdef SQLITE_DEBUG
     p->owner = tid;
     p->nRef++;
@@ -367,6 +376,9 @@ static void winMutexLeave(sqlite3_mutex *p){
   assert( p->nRef==0 || p->id==SQLITE_MUTEX_RECURSIVE );
 #endif
   assert( winMutex_isInit==1 );
+#if SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  sqlite3MutexTimeAlert(p, p->entered);
+#endif
   LeaveCriticalSection(&p->mutex);
 #ifdef SQLITE_DEBUG
   if( p->trace ){

diff --git a/src/sqliteInt.h b/src/sqliteInt.h
index 23b4dd946004e30b7b536569d63bd94c43620c3d..128ae970fdc8cd0813aa69533800b323ec3370c1 100644 (file)
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -3526,6 +3526,75 @@ const sqlite3_mem_methods *sqlite3MemGetMemsys3(void);
 # define sqlite3MemoryBarrier()
 #endif
 
+/*
+** When SQLITE_MUTEX_ALERT_MILLISECONDS is greater than zero, extra code
+** will be included to issue warnings via the sqlite3_log() interface if
+** a mutex is held for longer than the number of milliseconds specified
+** by SQLITE_MUTEX_ALERT_MILLISECONDS.
+*/
+#ifndef SQLITE_MUTEX_ALERT_MILLISECONDS
+# define SQLITE_MUTEX_ALERT_MILLISECONDS (0)
+#endif
+
+#if !defined(SQLITE_MUTEX_OMIT) && SQLITE_MUTEX_ALERT_MILLISECONDS>0
+  i64 sqlite3MutexTimeOfDay(void);
+  void sqlite3MutexTimeAlert(sqlite3_mutex *, i64);
+
+/*
+** This macro returns a 64-bit integer time value, in milliseconds,
+** or zero if that information is not available.
+*/
+# ifndef SQLITE_GET_MUTEX_TIME
+#  if SQLITE_OS_UNIX
+#   define SQLITE_GET_MUTEX_TIME()   (((i64)time())*1000)
+#  elif SQLITE_OS_WIN
+#   define SQLITE_GET_MUTEX_TIME()   ((i64)GetTickCount())
+#  else
+#   define SQLITE_GET_MUTEX_TIME()   (0)
+#  endif
+# endif
+
+/*
+** This macro returns the integer type for the specified mutex or
+** negative one if that information is not available.
+*/
+# ifndef SQLITE_GET_MUTEX_ID
+#  if SQLITE_OS_UNIX
+#   if SQLITE_MUTEX_NREF || defined(SQLITE_ENABLE_API_ARMOR)
+#    define SQLITE_GET_MUTEX_ID(p)    \
+         *((int*)(((unsigned char*)(p))+sizeof(pthread_mutex_t)))
+#   else
+#    define SQLITE_GET_MUTEX_ID(p)    (-1)
+#   endif
+#  elif SQLITE_OS_WIN
+#   define SQLITE_GET_MUTEX_ID(p)     \
+         *((int*)(((unsigned char*)(p))+sizeof(CRITICAL_SECTION)))
+#  else
+#   define SQLITE_GET_MUTEX_ID(p)     (-1)
+#  endif
+# endif
+
+/*
+** This macro returns the integer identifier for the current thread
+** or zero if that information is not available.
+*/
+# ifndef SQLITE_GET_THREAD_ID
+#  if SQLITE_OS_UNIX
+#   define SQLITE_GET_THREAD_ID()     ((void *)pthread_self())
+#  elif SQLITE_OS_WIN
+#   define SQLITE_GET_THREAD_ID()     ((void *)GetCurrentThreadId())
+#  else
+#   define SQLITE_GET_THREAD_ID()     ((void *)0)
+#  endif
+# endif
+#else
+# define sqlite3MutexTimeOfDay()      (0)
+# define sqlite3MutexTimeAlert(X,Y)
+# define SQLITE_GET_MUTEX_TIME()      (0)
+# define SQLITE_GET_MUTEX_ID(p)       (-1)
+# define SQLITE_GET_THREAD_ID()       ((void *)0)
+#endif
+
 sqlite3_int64 sqlite3StatusValue(int);
 void sqlite3StatusUp(int, int);
 void sqlite3StatusDown(int, int);