Add calls to sqlite3_log() when sqlite3_mutex_enter() takes more than

100,000 CPU cycles.

FossilOrigin-Name: 33c7ef7aca69f9b714bc25b2af5ae2a189d3ba78

diff --git a/manifest b/manifest
index 95dfbf5fe2cff3f9d74cd6f2d18416167cf90fba..bdd5107a3dd472b6d002cffe3dd88c9e950e88c5 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Temporarily\sadd\sextra\ssqlite3_log()\scalls\sto\sthis\sversion\sto\shelp\swith\sdebugging\sa\sperformance\sproblem.
-D 2016-07-16T11:47:45.840
+C Add\scalls\sto\ssqlite3_log()\swhen\ssqlite3_mutex_enter()\stakes\smore\sthan\s\n100,000\sCPU\scycles.
+D 2016-07-29T14:10:43.773
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in cf57f673d77606ab0f2d9627ca52a9ba1464146a
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -205,7 +205,7 @@ F src/memjournal.c 3eb2c0b51adbd869cb6a44780323f05fa904dc85
 F src/mutex.c 84a073c9a23a8d7bdd2ea832522d1730df18812c
 F src/mutex.h 779d588e3b7756ec3ecf7d78cde1d84aba414f85
 F src/mutex_noop.c f3f09fd7a2eb4287cfc799753ffc30380e7b71a1
-F src/mutex_unix.c 1b10d5413dfc794364a8adf3eb3a192926b43fa3
+F src/mutex_unix.c 9af77da894a1d5e16d5b8c11659b4c6de7ca1729
 F src/mutex_w32.c 06bfff9a3a83b53389a51a967643db3967032e1e
 F src/notify.c 9711a7575036f0d3040ba61bc6e217f13a9888e7
 F src/os.c 1b147e4cf7cc39e618115c14a086aed44bc91ace
@@ -1207,10 +1207,7 @@ F tool/vdbe_profile.tcl 67746953071a9f8f2f668b73fe899074e2c6d8c1
 F tool/warnings-clang.sh f6aa929dc20ef1f856af04a730772f59283631d4
 F tool/warnings.sh 0abfd78ceb09b7f7c27c688c8e3fe93268a13b32
 F tool/win/sqlite.vsix deb315d026cc8400325c5863eef847784a219a2f
-P 46bd9533c0b4656e9fb10eb41c9369ba8a113746
-R bce5e212270955da4d92cb60e4c49b45
-T *branch * debug
-T *sym-debug *
-T -sym-btree-balance-bias *
-U dan
-Z 9b01bf4c5271e3c2cb45a6e077ca93cf
+P 613c1ceaf4d552dc29aff090825941eaae6baed1
+R 6d8ae7e2095bf3fc683cc774df123cfb
+U drh
+Z 684747d28950efdfa4344d94c57523e7

diff --git a/manifest.uuid b/manifest.uuid
index 0ffa9d4c07aaf4b7373647692b758bfa20012a45..c60f0f9c647ddcde30f0b631586dde54ee7bbf4a 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-613c1ceaf4d552dc29aff090825941eaae6baed1
\ No newline at end of file
+33c7ef7aca69f9b714bc25b2af5ae2a189d3ba78
\ No newline at end of file

diff --git a/src/mutex_unix.c b/src/mutex_unix.c
index c8663144e8c55091487fb40d94f370166857c01f..f5a652041cae5ea44bd42d1a9954a81f1979cdab 100644 (file)
--- a/src/mutex_unix.c
+++ b/src/mutex_unix.c
@@ -200,6 +200,13 @@ static void pthreadMutexFree(sqlite3_mutex *p){
   sqlite3_free(p);
 }
 
+#include "hwtime.h"
+#ifdef SQLITE_MUTEX_NREF
+# define MUTEX_ID(p)  (p->id)
+#else
+# define MUTEX_ID(p)  0
+#endif
+
 /*
 ** The sqlite3_mutex_enter() and sqlite3_mutex_try() routines attempt
 ** to enter a mutex.  If another thread is already within the mutex,
@@ -212,6 +219,7 @@ static void pthreadMutexFree(sqlite3_mutex *p){
 ** more than once, the behavior is undefined.
 */
 static void pthreadMutexEnter(sqlite3_mutex *p){
+  sqlite3_uint64 iTimer = sqlite3Hwtime();
   assert( p->id==SQLITE_MUTEX_RECURSIVE || pthreadMutexNotheld(p) );
 
 #ifdef SQLITE_HOMEGROWN_RECURSIVE_MUTEX
@@ -245,6 +253,11 @@ static void pthreadMutexEnter(sqlite3_mutex *p){
   p->owner = pthread_self();
   p->nRef++;
 #endif
+  iTimer = sqlite3Hwtime() - iTimer;
+  if( iTimer>100000 ){
+    sqlite3_log(SQLITE_NOTICE, "slow mutex: %lld cycles on %d/%p",
+                iTimer, MUTEX_ID(p), p);
+  }
 #endif
 
 #ifdef SQLITE_DEBUG