From: mistachkin Date: Tue, 14 Feb 2017 23:58:30 +0000 (+0000) Subject: Experimental enhancements to mutex debugging. X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=f284988320d0d4d7c0d6804b778f46910450acba;p=thirdparty%2Fsqlite.git Experimental enhancements to mutex debugging. FossilOrigin-Name: 804817549cfecbe5e1c4cea605d54cb4164f9bb6 --- diff --git a/manifest b/manifest index 28095b65b6..23aff9da97 100644 --- 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 da9b31e873..b8032df192 100644 --- 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 6f1bc9767d..6b63c8c616 100644 --- 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 +#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 ecc84b4a94..df733a4fc9 100644 --- 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 55d08c8052..51dfb329bb 100644 --- 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 505c8fab7e..86ffbf4d11 100644 --- 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 23b4dd9460..128ae970fd 100644 --- 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);