From: drh Date: Tue, 9 Aug 2016 01:21:16 +0000 (+0000) Subject: Refocus the timer on the pager_end_transaction() routine. X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=c2af03b12f22a3d2b98f9f03cd965794c81438a0;p=thirdparty%2Fsqlite.git Refocus the timer on the pager_end_transaction() routine. FossilOrigin-Name: 9d4eb6e4750939c48aff267000bd69a73e1dc364 --- diff --git a/manifest b/manifest index b439f07b08..8f5f2ecff3 100644 --- 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 20a8fb48a9..b0deb8d7c7 100644 --- 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 da8570e2aa..6fb9d53d1b 100644 --- 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 ff665a36fc..936ed645c2 100644 --- 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 9f7e75d58b..094f95c963 100644 --- a/src/sqliteInt.h +++ b/src/sqliteInt.h @@ -3815,6 +3815,7 @@ int sqlite3ThreadCreate(SQLiteThread**,void*(*)(void*),void*); int sqlite3ThreadJoin(SQLiteThread*, void**); #endif +#include #define START_DEBUG_TIMER \ sqlite3_uint64 iDebugTimerStart, iDebugTimer; \ struct timeval debug_timer_var; \ diff --git a/src/vdbeapi.c b/src/vdbeapi.c index d4e3f2475f..857494ed83 100644 --- 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);