Refocus the timer on the pager_end_transaction() routine.

FossilOrigin-Name: 9d4eb6e4750939c48aff267000bd69a73e1dc364

diff --git a/manifest b/manifest
index b439f07b08375af50e871eb62901a46660ecdc27..8f5f2ecff330137a5b72d107d5974909034d1bb8 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Add\sextra\slogging\scalls\sto\sthis\sbranch.
-D 2016-08-04T14:08:06.316
+C Refocus\sthe\stimer\son\sthe\spager_end_transaction()\sroutine.
+D 2016-08-09T01:21:16.687
 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 218f15781b9a92d6433c02d5097ea6c5656ae953
+F src/malloc.c 3c3ac67969612493d435e14b6832793209afd2ec
 F src/mem0.c 6a55ebe57c46ca1a7d98da93aaa07f99f1059645
 F src/mem1.c faf615aafd8be74a71494dfa027c113ea5c6615f
 F src/mem2.c f1940d9e91948dd6a908fbb9ce3835c36b5d83c3
@@ -215,7 +215,7 @@ 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 5099402a6038e79e7823be3c193b89d4381671d1
+F src/pager.c 0d363201cc4b0f1a27f0f70f29a1e88bb5e5a31a
 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 2821f805b8d3f5dca402ab5b02b45af333c09c16
+F src/sqliteInt.h 6422d7d1e8bd346607877cf66fbd40d7f48ded56
 F src/sqliteLimit.h 164b0e6749d31e0daa1a4589a169d31c0dec7b3d
 F src/status.c 961d5926e5a8fda611d385ec22c226b8635cd1cb
 F src/table.c 2e99ef7ef16187e17033d9398dc962ce22dab5cb
@@ -292,7 +292,7 @@ F src/vacuum.c 59f03f92bcff57faa6a8ca256eb29ccddfb0614a
 F src/vdbe.c 5ee15a66ce07e0482b92aa29e4dd0c5827a22d79
 F src/vdbe.h 09f5b4e3719fa454f252322b1cdab5cf1f361327
 F src/vdbeInt.h e2a060a55ee18a6ab973353a5e2ec7ee569bf787
-F src/vdbeapi.c c56dc899791cd5708479c01fceae0b27b2643520
+F src/vdbeapi.c 4fc644896359dc095481b80336888eb3aad7c4aa
 F src/vdbeaux.c e755d2a3d873a8211689219b385e7c86243ad24d
 F src/vdbeblob.c 848238dc73e93e48432991bb5651bf87d865eca4
 F src/vdbemem.c 31d8eabb0cd78bfeab4e5124c7363c3e9e54db9f
@@ -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 92b9fead353d50eb41f5ab7e3a887dd4e5c3aa80
-R 97d498068ede0b7b0205f624119fd57b
-U dan
-Z 74a7e885da65e56edb7ed4dbb325dbed
+P 491f1ef36e60aa65d71444b604064e3505cabd18
+R e29c5144299bab68bda60556e6dafd92
+U drh
+Z 44d6270f2b449a107198473da9531b56

diff --git a/manifest.uuid b/manifest.uuid
index 20a8fb48a96e3a58ad45193fbaa247c0cc2535ad..b0deb8d7c74064227c378c4150774c7c017cb45a 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-491f1ef36e60aa65d71444b604064e3505cabd18
\ No newline at end of file
+9d4eb6e4750939c48aff267000bd69a73e1dc364
\ No newline at end of file

diff --git a/src/malloc.c b/src/malloc.c
index da8570e2aaff84ddb3954aba32c6705ab071ad76..6fb9d53d1b6c054ca04af84a9d440c0100650aeb 100644 (file)
--- a/src/malloc.c
+++ b/src/malloc.c
@@ -296,7 +296,6 @@ 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
@@ -312,10 +311,6 @@ 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;
 }
 
@@ -480,7 +475,6 @@ 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) );
@@ -493,9 +487,6 @@ 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/pager.c b/src/pager.c
index ff665a36fc2d89d5be4808e7a051f4b4bf9d6a06..936ed645c2918e6f8ff2eb52345479daaf7446ff 100644 (file)
--- a/src/pager.c
+++ b/src/pager.c
@@ -1907,6 +1907,7 @@ static int pager_truncate(Pager *pPager, Pgno nPage);
 static int pager_end_transaction(Pager *pPager, int hasMaster, int bCommit){
   int rc = SQLITE_OK;      /* Error code from journal finalization operation */
   int rc2 = SQLITE_OK;     /* Error code from db file unlock operation */
+  START_DEBUG_TIMER;
 
   /* Do nothing if the pager does not have an open write transaction
   ** or at least a RESERVED lock. This function may be called when there
@@ -1973,6 +1974,11 @@ static int pager_end_transaction(Pager *pPager, int hasMaster, int bCommit){
       }
     }
   }
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, "slow pager_end_transaction(1): %llu %d", 
+      iDebugTimer, pagerUseWal(pPager));
+    iDebugTimerStart += iDebugTimer;
+  }
 
 #ifdef SQLITE_CHECK_PAGES
   sqlite3PcacheIterateDirty(pPager->pPCache, pager_set_pagehash);
@@ -1989,7 +1995,17 @@ static int pager_end_transaction(Pager *pPager, int hasMaster, int bCommit){
   pPager->pInJournal = 0;
   pPager->nRec = 0;
   sqlite3PcacheCleanAll(pPager->pPCache);
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, "slow pager_end_transaction(2): %llu %d", 
+      iDebugTimer, pagerUseWal(pPager));
+    iDebugTimerStart += iDebugTimer;
+  }
   sqlite3PcacheTruncate(pPager->pPCache, pPager->dbSize);
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, "slow pager_end_transaction(3): %llu %d",
+      iDebugTimer, pagerUseWal(pPager));
+    iDebugTimerStart += iDebugTimer;
+  }
 
   if( pagerUseWal(pPager) ){
     /* Drop the WAL write-lock, if any. Also, if the connection was in 
@@ -2008,6 +2024,11 @@ static int pager_end_transaction(Pager *pPager, int hasMaster, int bCommit){
     assert( pPager->eLock==EXCLUSIVE_LOCK );
     rc = pager_truncate(pPager, pPager->dbSize);
   }
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, "slow pager_end_transaction(4): %llu %d",
+      iDebugTimer, pagerUseWal(pPager));
+    iDebugTimerStart += iDebugTimer;
+  }
 
   if( rc==SQLITE_OK && bCommit && isOpen(pPager->fd) ){
     rc = sqlite3OsFileControl(pPager->fd, SQLITE_FCNTL_COMMIT_PHASETWO, 0);
@@ -2023,6 +2044,10 @@ static int pager_end_transaction(Pager *pPager, int hasMaster, int bCommit){
   pPager->eState = PAGER_READER;
   pPager->setMaster = 0;
 
+  END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){
+    sqlite3_log(SQLITE_NOTICE, "slow pager_end_transaction(5): %llu %d",
+      iDebugTimer, pagerUseWal(pPager));
+  }
   return (rc==SQLITE_OK?rc2:rc);
 }
 
@@ -6106,8 +6131,6 @@ 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
@@ -6255,10 +6278,6 @@ 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;
 }
 
@@ -6280,7 +6299,6 @@ 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
@@ -6315,10 +6333,6 @@ 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 9f7e75d58bd00bfba94c00e1be0829b8a458e776..094f95c963c7e4638fbc4278f804ae7f18c53dd1 100644 (file)
--- a/src/sqliteInt.h
+++ b/src/sqliteInt.h
@@ -3815,6 +3815,7 @@ int sqlite3ThreadCreate(SQLiteThread**,void*(*)(void*),void*);
 int sqlite3ThreadJoin(SQLiteThread*, void**);
 #endif
 
+#include <sys/time.h>
 #define START_DEBUG_TIMER \
   sqlite3_uint64 iDebugTimerStart, iDebugTimer;                     \
   struct timeval debug_timer_var;                                   \

diff --git a/src/vdbeapi.c b/src/vdbeapi.c
index d4e3f2475fbee97dcc1a766d9875a77325211b00..857494ed83a632d1bb14aeeb5a403ba9abc213ae 100644 (file)
--- a/src/vdbeapi.c
+++ b/src/vdbeapi.c
@@ -546,8 +546,8 @@ 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
+    sqlite3_log(SQLITE_NOTICE, "slow (%llu) sqlite3Step(%s)", 
+        iDebugTimer, (p->zSql ? p->zSql : "")
     );
   }
   return (rc&db->errMask);