Add extra logging calls to this branch.

FossilOrigin-Name: 491f1ef36e60aa65d71444b604064e3505cabd18

diff --git a/manifest b/manifest
index 8c6b45215aab5aa45a8cc42ef8bb791145a0f054..b439f07b08375af50e871eb62901a46660ecdc27 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C A\snew\sversion\sof\sthe\sslow\smutex\slog\sthat\suses\sgettimeofday()\sinstead\sof\ntrying\sto\saccess\sthe\shardware\stimer.
-D 2016-07-30T03:33:30.306
+C Add\sextra\slogging\scalls\sto\sthis\sbranch.
+D 2016-08-04T14:08:06.316
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in cf57f673d77606ab0f2d9627ca52a9ba1464146a
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -195,7 +195,7 @@ F src/legacy.c ba1863ea58c4c840335a84ec276fc2b25e22bc4e
 F src/lempar.c 7274c97d24bb46631e504332ccd3bd1b37841770
 F src/loadext.c de741e66e5ddc1598d904d7289239696e40ed994
 F src/main.c 8207ece1b4005b1efab55d1505d8ffb45bfced05
-F src/malloc.c 3c3ac67969612493d435e14b6832793209afd2ec
+F src/malloc.c 218f15781b9a92d6433c02d5097ea6c5656ae953
 F src/mem0.c 6a55ebe57c46ca1a7d98da93aaa07f99f1059645
 F src/mem1.c faf615aafd8be74a71494dfa027c113ea5c6615f
 F src/mem2.c f1940d9e91948dd6a908fbb9ce3835c36b5d83c3
@@ -205,17 +205,17 @@ 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 5cbf63bc6e2999eecbcfa883537c9eacf1484a62
+F src/mutex_unix.c 543aab0a578f09ad15e2b743789e4cfe8ab04cf5
 F src/mutex_w32.c 06bfff9a3a83b53389a51a967643db3967032e1e
 F src/notify.c 9711a7575036f0d3040ba61bc6e217f13a9888e7
-F src/os.c 1b147e4cf7cc39e618115c14a086aed44bc91ace
+F src/os.c a93752993c14b6496ec50212e093a3825e10ce8f
 F src/os.h 3e57a24e2794a94d3cf2342c6d9a884888cd96bf
 F src/os_common.h 92815ed65f805560b66166e3583470ff94478f04
 F src/os_setup.h c9d4553b5aaa6f73391448b265b89bed0b890faa
 F src/os_unix.c e7157dfa077c06aaeecdfc4dcb6b0a489ef5c57a
 F src/os_win.c a019caaae2bcbbc0cc4c39af6e7d7e43d8426053
 F src/os_win.h 09e751b20bbc107ffbd46e13555dc73576d88e21
-F src/pager.c 8d97b3633f098fef817656dcbf167ca904511d78
+F src/pager.c 5099402a6038e79e7823be3c193b89d4381671d1
 F src/pager.h d1eee3c3f741be247ce6d82752a178515fc8578b
 F src/parse.y 5dfead8aed90cb0c7c1115898ee2266804daff45
 F src/pcache.c 4121a0571c18581ee9f82f086d5e2030051ebd6a
@@ -232,7 +232,7 @@ F src/shell.c 282f8f5278e0c78eb442217531172ec9e1538796
 F src/sqlite.h.in 4a5e5158c189d2bcd45c7c4607c2c0eb6d25c153
 F src/sqlite3.rc 992c9f5fb8285ae285d6be28240a7e8d3a7f2bad
 F src/sqlite3ext.h 17d487c3c91b0b8c584a32fbeb393f6f795eea7d
-F src/sqliteInt.h 3726a8b41814157986cbd2c58b9537ea96e9df9f
+F src/sqliteInt.h 2821f805b8d3f5dca402ab5b02b45af333c09c16
 F src/sqliteLimit.h 164b0e6749d31e0daa1a4589a169d31c0dec7b3d
 F src/status.c 961d5926e5a8fda611d385ec22c226b8635cd1cb
 F src/table.c 2e99ef7ef16187e17033d9398dc962ce22dab5cb
@@ -292,14 +292,14 @@ F src/vacuum.c 59f03f92bcff57faa6a8ca256eb29ccddfb0614a
 F src/vdbe.c 5ee15a66ce07e0482b92aa29e4dd0c5827a22d79
 F src/vdbe.h 09f5b4e3719fa454f252322b1cdab5cf1f361327
 F src/vdbeInt.h e2a060a55ee18a6ab973353a5e2ec7ee569bf787
-F src/vdbeapi.c 37a6c6ae284a97bcace365f2f0a225680c0499d9
-F src/vdbeaux.c edbb7a9c8b2a8f7a68ac75c2475edd4040266b76
+F src/vdbeapi.c c56dc899791cd5708479c01fceae0b27b2643520
+F src/vdbeaux.c e755d2a3d873a8211689219b385e7c86243ad24d
 F src/vdbeblob.c 848238dc73e93e48432991bb5651bf87d865eca4
 F src/vdbemem.c 31d8eabb0cd78bfeab4e5124c7363c3e9e54db9f
 F src/vdbesort.c 975aeffa99acb0991b2f288d30294756bff41438
 F src/vdbetrace.c 7e4222955e07dd707a2f360c0eb73452be1cb010
 F src/vtab.c cb0c194303fea276b48d7d4b6d970b5a96bde8de
-F src/wal.c e77da6efffa373cd20d248be9e86c54c634bc4fe
+F src/wal.c 430abe09fd057a8789a9589a3db366c40f1427dc
 F src/wal.h df01efe09c5cb8c8e391ff1715cca294f89668a4
 F src/walker.c c253b95b4ee44b21c406e2a1052636c31ea27804
 F src/where.c 4ce8c4826b7f86d080f0ed4e7a9045bb5014be77
@@ -1207,7 +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 ea3c7162dc79cb85868d2bc86d9938fe7c2ae7ef
-R 4317055374b4abe2abea36440aabee15
-U drh
-Z d3037cc2511d419210d869068053f9a1
+P 92b9fead353d50eb41f5ab7e3a887dd4e5c3aa80
+R 97d498068ede0b7b0205f624119fd57b
+U dan
+Z 74a7e885da65e56edb7ed4dbb325dbed

diff --git a/manifest.uuid b/manifest.uuid
index 06b489ad7c6a6bb631e9b7aa4b3b5a849bce1f0f..20a8fb48a96e3a58ad45193fbaa247c0cc2535ad 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-92b9fead353d50eb41f5ab7e3a887dd4e5c3aa80
\ No newline at end of file
+491f1ef36e60aa65d71444b604064e3505cabd18
\ No newline at end of file

diff --git a/src/malloc.c b/src/malloc.c
index 6fb9d53d1b6c054ca04af84a9d440c0100650aeb..da8570e2aaff84ddb3954aba32c6705ab071ad76 100644 (file)
--- a/src/malloc.c
+++ b/src/malloc.c
@@ -296,6 +296,7 @@ static int mallocWithAlarm(int n, void **pp){
 */
 void *sqlite3Malloc(u64 n){
   void *p;
+  START_DEBUG_TIMER
   if( n==0 || n>=0x7fffff00 ){
     /* A memory allocation of a number of bytes which is near the maximum
     ** signed integer value might cause an integer overflow inside of the
@@ -311,6 +312,10 @@ void *sqlite3Malloc(u64 n){
     p = sqlite3GlobalConfig.m.xMalloc((int)n);
   }
   assert( EIGHT_BYTE_ALIGNMENT(p) );  /* IMP: R-11148-40995 */
+  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, 
+        "slow sqlite3Malloc(%llu): %llu uS", n, iDebugTimer);
+  }
   return p;
 }
 
@@ -475,6 +480,7 @@ sqlite3_uint64 sqlite3_msize(void *p){
 ** Free memory previously obtained from sqlite3Malloc().
 */
 void sqlite3_free(void *p){
+  START_DEBUG_TIMER;
   if( p==0 ) return;  /* IMP: R-49053-54554 */
   assert( sqlite3MemdebugHasType(p, MEMTYPE_HEAP) );
   assert( sqlite3MemdebugNoType(p, ~MEMTYPE_HEAP) );
@@ -487,6 +493,9 @@ void sqlite3_free(void *p){
   }else{
     sqlite3GlobalConfig.m.xFree(p);
   }
+  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, "slow sqlite3_free(ptr): %llu uS", iDebugTimer);
+  }
 }
 
 /*

diff --git a/src/mutex_unix.c b/src/mutex_unix.c
index 59b0ec97bca4f332e22a77feff6eb2e16913789f..9b16c0e838b926e91b805b31fcc0a96407399ece 100644 (file)
--- a/src/mutex_unix.c
+++ b/src/mutex_unix.c
@@ -219,12 +219,10 @@ static void pthreadMutexFree(sqlite3_mutex *p){
 ** more than once, the behavior is undefined.
 */
 static void pthreadMutexEnter(sqlite3_mutex *p){
-  struct timeval x;
-  sqlite3_uint64 iBegin, iEnd;
+
+  START_DEBUG_TIMER;
   assert( p->id==SQLITE_MUTEX_RECURSIVE || pthreadMutexNotheld(p) );
 
-  gettimeofday(&x, 0);
-  iBegin = 1000000*(sqlite3_uint64)x.tv_sec + x.tv_usec;
 #ifdef SQLITE_HOMEGROWN_RECURSIVE_MUTEX
   /* If recursive mutexes are not available, then we have to grow
   ** our own.  This implementation assumes that pthread_equal()
@@ -256,16 +254,13 @@ static void pthreadMutexEnter(sqlite3_mutex *p){
   p->owner = pthread_self();
   p->nRef++;
 #endif
-  gettimeofday(&x, 0);
-  iEnd = 1000000*(sqlite3_uint64)x.tv_sec + x.tv_usec;
-  if( iEnd > iBegin+500 ){
+  END_DEBUG_TIMER(500) {
     sqlite3_mutex *pMaster = sqlite3_mutex_alloc(SQLITE_MUTEX_STATIC_MASTER);
     int id = -1;
     if( p>=pMaster && p<=&pMaster[SQLITE_MUTEX_STATIC_APP3-2] ){
       id = (int)(p - pMaster) + 2;
     }
-    sqlite3_log(SQLITE_NOTICE, "slow mutex: %llu uS on %d/%p",
-                iEnd - iBegin, id, p);
+    sqlite3_log(SQLITE_NOTICE, "slow mutex: %llu uS on %d/%p",iDebugTimer,id,p);
   }
 #endif
 

diff --git a/src/os.c b/src/os.c
index b6c28a1dc447b43023d345f62caf6bb7b49ee8b5..f9665e337cefccc5b0d397c60106b35d002d7075 100644 (file)
--- a/src/os.c
+++ b/src/os.c
@@ -61,10 +61,14 @@ int sqlite3_memdebug_vfs_oom_test = 1;
 */
 int sqlite3OsClose(sqlite3_file *pId){
   int rc = SQLITE_OK;
+  START_DEBUG_TIMER;
   if( pId->pMethods ){
     rc = pId->pMethods->xClose(pId);
     pId->pMethods = 0;
   }
+  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, "slow sqlite3OsClose: %llu uS", iDebugTimer);
+  }
   return rc;
 }
 int sqlite3OsRead(sqlite3_file *id, void *pBuf, int amt, i64 offset){
@@ -79,8 +83,15 @@ int sqlite3OsTruncate(sqlite3_file *id, i64 size){
   return id->pMethods->xTruncate(id, size);
 }
 int sqlite3OsSync(sqlite3_file *id, int flags){
-  DO_OS_MALLOC_TEST(id);
-  return id->pMethods->xSync(id, flags);
+  int rc;
+  START_DEBUG_TIMER;
+  rc = id->pMethods->xSync(id, flags);
+  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, 
+        "slow sqlite3OsSync(ptr, %d): %llu uS", flags, iDebugTimer
+    );
+  }
+  return rc;
 }
 int sqlite3OsFileSize(sqlite3_file *id, i64 *pSize){
   DO_OS_MALLOC_TEST(id);
@@ -107,6 +118,8 @@ int sqlite3OsCheckReservedLock(sqlite3_file *id, int *pResOut){
 ** routine has no return value since the return value would be meaningless.
 */
 int sqlite3OsFileControl(sqlite3_file *id, int op, void *pArg){
+  int rc;
+  START_DEBUG_TIMER;
 #ifdef SQLITE_TEST
   if( op!=SQLITE_FCNTL_COMMIT_PHASETWO ){
     /* Faults are not injected into COMMIT_PHASETWO because, assuming SQLite
@@ -122,7 +135,12 @@ int sqlite3OsFileControl(sqlite3_file *id, int op, void *pArg){
     DO_OS_MALLOC_TEST(id);
   }
 #endif
-  return id->pMethods->xFileControl(id, op, pArg);
+  rc = id->pMethods->xFileControl(id, op, pArg);
+  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, 
+        "slow sqlite3OsFileControl: %llu uS", iDebugTimer);
+  }
+  return rc;
 }
 void sqlite3OsFileControlHint(sqlite3_file *id, int op, void *pArg){
   (void)id->pMethods->xFileControl(id, op, pArg);
@@ -136,10 +154,25 @@ int sqlite3OsDeviceCharacteristics(sqlite3_file *id){
   return id->pMethods->xDeviceCharacteristics(id);
 }
 int sqlite3OsShmLock(sqlite3_file *id, int offset, int n, int flags){
-  return id->pMethods->xShmLock(id, offset, n, flags);
+  int rc;
+  START_DEBUG_TIMER;
+  rc = id->pMethods->xShmLock(id, offset, n, flags);
+  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, 
+        "slow sqlite3OsShmLock(ptr, %d, %d, %d): %llu uS", 
+        offset, n, flags, iDebugTimer
+    );
+  }
+  return rc;
 }
 void sqlite3OsShmBarrier(sqlite3_file *id){
+  START_DEBUG_TIMER;
   id->pMethods->xShmBarrier(id);
+  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, 
+        "slow sqlite3OsShmBarrier: %llu uS", iDebugTimer
+    );
+  }
 }
 int sqlite3OsShmUnmap(sqlite3_file *id, int deleteFlag){
   return id->pMethods->xShmUnmap(id, deleteFlag);

diff --git a/src/pager.c b/src/pager.c
index 997f842d0a391603f0b5fda30f7b00d865818a94..ff665a36fc2d89d5be4808e7a051f4b4bf9d6a06 100644 (file)
--- a/src/pager.c
+++ b/src/pager.c
@@ -6106,6 +6106,8 @@ int sqlite3PagerCommitPhaseOne(
 ){
   int rc = SQLITE_OK;             /* Return code */
 
+  START_DEBUG_TIMER;
+
   assert( pPager->eState==PAGER_WRITER_LOCKED
        || pPager->eState==PAGER_WRITER_CACHEMOD
        || pPager->eState==PAGER_WRITER_DBMOD
@@ -6253,6 +6255,10 @@ commit_phase_one_exit:
   if( rc==SQLITE_OK && !pagerUseWal(pPager) ){
     pPager->eState = PAGER_WRITER_FINISHED;
   }
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ) {
+    sqlite3_log(SQLITE_NOTICE, 
+        "slow sqlite3PagerCommitPhaseOne: %llu uS", iDebugTimer);
+  }
   return rc;
 }
 
@@ -6274,6 +6280,7 @@ commit_phase_one_exit:
 */
 int sqlite3PagerCommitPhaseTwo(Pager *pPager){
   int rc = SQLITE_OK;                  /* Return code */
+  START_DEBUG_TIMER;
 
   /* This routine should not be called if a prior error has occurred.
   ** But if (due to a coding error elsewhere in the system) it does get
@@ -6308,6 +6315,10 @@ int sqlite3PagerCommitPhaseTwo(Pager *pPager){
 
   PAGERTRACE(("COMMIT %d\n", PAGERID(pPager)));
   rc = pager_end_transaction(pPager, pPager->setMaster, 1);
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, 
+        "slow sqlite3PagerCommitPhaseTwo: %llu uS", iDebugTimer);
+  }
   return pager_error(pPager, rc);
 }
 

diff --git a/src/sqliteInt.h b/src/sqliteInt.h
index d2f2f37fc8dad84461a07afdf471075259ba6eea..9f7e75d58bd00bfba94c00e1be0829b8a458e776 100644 (file)
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -3815,4 +3815,21 @@ int sqlite3ThreadCreate(SQLiteThread**,void*(*)(void*),void*);
 int sqlite3ThreadJoin(SQLiteThread*, void**);
 #endif
 
+#define START_DEBUG_TIMER \
+  sqlite3_uint64 iDebugTimerStart, iDebugTimer;                     \
+  struct timeval debug_timer_var;                                   \
+  gettimeofday(&debug_timer_var, 0);                                \
+  iDebugTimerStart = 1000000*(sqlite3_uint64)debug_timer_var.tv_sec \
+                     + debug_timer_var.tv_usec;
+
+#define END_DEBUG_TIMER(nDebugUsec) \
+  gettimeofday(&debug_timer_var, 0);                                \
+  iDebugTimer = 1000000*(sqlite3_uint64)debug_timer_var.tv_sec      \
+                +debug_timer_var.tv_usec-iDebugTimerStart;          \
+  if( iDebugTimer>=nDebugUsec )
+
+
+#define DEBUG_TIMER_BIG_TIMEOUT  10000
+#define DEBUG_TIMER_SMALL_TIMEOUT 1000
+
 #endif /* _SQLITEINT_H_ */

diff --git a/src/vdbeapi.c b/src/vdbeapi.c
index 0ab76e0784c530e3f1bfdab70b4a866f8b60d2be..d4e3f2475fbee97dcc1a766d9875a77325211b00 100644 (file)
--- a/src/vdbeapi.c
+++ b/src/vdbeapi.c
@@ -395,6 +395,7 @@ void sqlite3_result_error_nomem(sqlite3_context *pCtx){
 */
 static int doWalCallbacks(sqlite3 *db){
   int rc = SQLITE_OK;
+  START_DEBUG_TIMER;
 #ifndef SQLITE_OMIT_WAL
   int i;
   for(i=0; i<db->nDb; i++){
@@ -407,6 +408,9 @@ static int doWalCallbacks(sqlite3 *db){
     }
   }
 #endif
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ) {
+    sqlite3_log(SQLITE_NOTICE, "slow doWalCallbacks: %llu uS", iDebugTimer);
+  }
   return rc;
 }
 
@@ -422,6 +426,7 @@ static int doWalCallbacks(sqlite3 *db){
 static int sqlite3Step(Vdbe *p){
   sqlite3 *db;
   int rc;
+  START_DEBUG_TIMER;
 
   assert(p);
   if( p->magic!=VDBE_MAGIC_RUN ){
@@ -540,6 +545,11 @@ end_of_step:
     */ 
     rc = sqlite3VdbeTransferError(p);
   }
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ) {
+    sqlite3_log(SQLITE_NOTICE, "slow sqlite3Step(%s): %llu uS", 
+        (p->zSql ? p->zSql : ""), iDebugTimer
+    );
+  }
   return (rc&db->errMask);
 }
 

diff --git a/src/vdbeaux.c b/src/vdbeaux.c
index c0018bb71cae5d486e5e94f90963d3ce509dc16e..a2c969a91b44b4f514d341c09d64a828a7f97418 100644 (file)
--- a/src/vdbeaux.c
+++ b/src/vdbeaux.c
@@ -1905,6 +1905,7 @@ static int vdbeCommit(sqlite3 *db, Vdbe *p){
   int nTrans = 0;  /* Number of databases with an active write-transaction */
   int rc = SQLITE_OK;
   int needXcommit = 0;
+  START_DEBUG_TIMER;
 
 #ifdef SQLITE_OMIT_VIRTUALTABLE
   /* With this option, sqlite3VtabSync() is defined to be simply 
@@ -2134,6 +2135,9 @@ static int vdbeCommit(sqlite3 *db, Vdbe *p){
   }
 #endif
 
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ) {
+    sqlite3_log(SQLITE_NOTICE, "slow vdbeCommit: %llu uS", iDebugTimer);
+  }
   return rc;
 }
 

diff --git a/src/wal.c b/src/wal.c
index d49b0a3c571904ccc4941c984dfb4fec893b3525..cb1d36ea575cc5f43ce4336daed87f0986ce98a1 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -2738,6 +2738,8 @@ int sqlite3WalFrames(
   i64 iOffset;                    /* Next byte to write in WAL file */
   WalWriter w;                    /* The writer */
 
+  START_DEBUG_TIMER;
+
   assert( pList );
   assert( pWal->writeLock );
 
@@ -2906,6 +2908,10 @@ int sqlite3WalFrames(
     }
   }
 
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ) {
+    sqlite3_log(SQLITE_NOTICE, "slow sqlite3WalFrames: %llu uS", iDebugTimer);
+  }
+
   WALTRACE(("WAL%p: frame write %s\n", pWal, rc ? "failed" : "ok"));
   return rc;
 }