From: drh Date: Wed, 10 Aug 2016 02:54:15 +0000 (+0000) Subject: Remove all timers and other debugging logs except for the one timer on X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=d4a85406a11a1ebb623242504796e7a5c953e42c;p=thirdparty%2Fsqlite.git Remove all timers and other debugging logs except for the one timer on pcache1TruncateUnsafe(). FossilOrigin-Name: 5980e625dbb694dc3b0535e71fd986a6d211e245 --- diff --git a/manifest b/manifest index 84fa580eb2..5b8d528389 100644 --- a/manifest +++ b/manifest @@ -1,5 +1,5 @@ -C Add\sanother\stimer\son\spcache1TruncateUnsafe(). -D 2016-08-09T11:44:06.664 +C Remove\sall\stimers\sand\sother\sdebugging\slogs\sexcept\sfor\sthe\sone\stimer\son\npcache1TruncateUnsafe(). +D 2016-08-10T02:54:15.340 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f F Makefile.in cf57f673d77606ab0f2d9627ca52a9ba1464146a F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23 @@ -205,22 +205,22 @@ 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 543aab0a578f09ad15e2b743789e4cfe8ab04cf5 +F src/mutex_unix.c 1b10d5413dfc794364a8adf3eb3a192926b43fa3 F src/mutex_w32.c 06bfff9a3a83b53389a51a967643db3967032e1e F src/notify.c 9711a7575036f0d3040ba61bc6e217f13a9888e7 -F src/os.c a93752993c14b6496ec50212e093a3825e10ce8f +F src/os.c 1b147e4cf7cc39e618115c14a086aed44bc91ace 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_unix.c fb587121840f690101336879adfa6d0b2cd0e8c7 F src/os_win.c a019caaae2bcbbc0cc4c39af6e7d7e43d8426053 F src/os_win.h 09e751b20bbc107ffbd46e13555dc73576d88e21 -F src/pager.c d69ede96f8fac2d0c9c3be64eb06edfe682b01ef +F src/pager.c 8d97b3633f098fef817656dcbf167ca904511d78 F src/pager.h d1eee3c3f741be247ce6d82752a178515fc8578b F src/parse.y 5dfead8aed90cb0c7c1115898ee2266804daff45 F src/pcache.c 4121a0571c18581ee9f82f086d5e2030051ebd6a F src/pcache.h 9b559127b83f84ff76d735c8262f04853be0c59a -F src/pcache1.c eeb485caa40fda583d21977a7b5fbd3852904d7f +F src/pcache1.c 938bc830177ccd5198ab07a7522338c8598a00f7 F src/pragma.c 3f3e959390a10c0131676f0e307acce372777e0f F src/prepare.c 6ef0cf2f9274982988ed6b7cab1be23147e94196 F src/printf.c 090fac0f779c93c8a95089a125339686648835e4 @@ -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 4fc644896359dc095481b80336888eb3aad7c4aa -F src/vdbeaux.c e755d2a3d873a8211689219b385e7c86243ad24d +F src/vdbeapi.c 37a6c6ae284a97bcace365f2f0a225680c0499d9 +F src/vdbeaux.c edbb7a9c8b2a8f7a68ac75c2475edd4040266b76 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 430abe09fd057a8789a9589a3db366c40f1427dc +F src/wal.c 10e7de7ce90865a68153f001a61f1d985cd17983 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 7d0af4b53c440f4628f0cecdc40459335630fa4e -R 67c20c387fa50de70cf8667debaaa82a +P 42ce53f648a506d0a5d9c1231eb28c11b4e6b124 +R e064622bb758d47c8c7ad1ed3f41c26c U drh -Z 63fcef9cf7b93ddf816f7412e9d532bf +Z 49509f85b3a161b812f3ddad4852a442 diff --git a/manifest.uuid b/manifest.uuid index 7095413bf7..032f706678 100644 --- a/manifest.uuid +++ b/manifest.uuid @@ -1 +1 @@ -42ce53f648a506d0a5d9c1231eb28c11b4e6b124 \ No newline at end of file +5980e625dbb694dc3b0535e71fd986a6d211e245 \ No newline at end of file diff --git a/src/mutex_unix.c b/src/mutex_unix.c index 9b16c0e838..c8663144e8 100644 --- a/src/mutex_unix.c +++ b/src/mutex_unix.c @@ -200,13 +200,6 @@ static void pthreadMutexFree(sqlite3_mutex *p){ sqlite3_free(p); } -#include -#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, @@ -219,8 +212,6 @@ static void pthreadMutexFree(sqlite3_mutex *p){ ** more than once, the behavior is undefined. */ static void pthreadMutexEnter(sqlite3_mutex *p){ - - START_DEBUG_TIMER; assert( p->id==SQLITE_MUTEX_RECURSIVE || pthreadMutexNotheld(p) ); #ifdef SQLITE_HOMEGROWN_RECURSIVE_MUTEX @@ -254,14 +245,6 @@ static void pthreadMutexEnter(sqlite3_mutex *p){ p->owner = pthread_self(); p->nRef++; #endif - 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",iDebugTimer,id,p); - } #endif #ifdef SQLITE_DEBUG diff --git a/src/os.c b/src/os.c index f9665e337c..b6c28a1dc4 100644 --- a/src/os.c +++ b/src/os.c @@ -61,14 +61,10 @@ 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){ @@ -83,15 +79,8 @@ int sqlite3OsTruncate(sqlite3_file *id, i64 size){ return id->pMethods->xTruncate(id, size); } int sqlite3OsSync(sqlite3_file *id, int 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; + DO_OS_MALLOC_TEST(id); + return id->pMethods->xSync(id, flags); } int sqlite3OsFileSize(sqlite3_file *id, i64 *pSize){ DO_OS_MALLOC_TEST(id); @@ -118,8 +107,6 @@ 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 @@ -135,12 +122,7 @@ int sqlite3OsFileControl(sqlite3_file *id, int op, void *pArg){ DO_OS_MALLOC_TEST(id); } #endif - 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; + return id->pMethods->xFileControl(id, op, pArg); } void sqlite3OsFileControlHint(sqlite3_file *id, int op, void *pArg){ (void)id->pMethods->xFileControl(id, op, pArg); @@ -154,25 +136,10 @@ int sqlite3OsDeviceCharacteristics(sqlite3_file *id){ return id->pMethods->xDeviceCharacteristics(id); } int sqlite3OsShmLock(sqlite3_file *id, int offset, int n, int 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; + return id->pMethods->xShmLock(id, offset, n, flags); } 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/os_unix.c b/src/os_unix.c index fbf14cfe38..a9344ee830 100644 --- a/src/os_unix.c +++ b/src/os_unix.c @@ -4629,12 +4629,8 @@ static void unixShmBarrier( sqlite3_file *fd /* Database file holding the shared memory */ ){ UNUSED_PARAMETER(fd); -#if defined(__GNUC__) && GCC_VERSION>=4001000 - __sync_synchronize(); -#else unixEnterMutex(); unixLeaveMutex(); -#endif } /* diff --git a/src/pager.c b/src/pager.c index 1222cbb231..997f842d0a 100644 --- a/src/pager.c +++ b/src/pager.c @@ -1907,7 +1907,6 @@ 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 @@ -1974,11 +1973,6 @@ 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 uS wal=%d", - iDebugTimer, pagerUseWal(pPager)); - iDebugTimerStart += iDebugTimer; - } #ifdef SQLITE_CHECK_PAGES sqlite3PcacheIterateDirty(pPager->pPCache, pager_set_pagehash); @@ -1995,17 +1989,7 @@ 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 uS wal=%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 uS wal=%d", - iDebugTimer, pagerUseWal(pPager)); - iDebugTimerStart += iDebugTimer; - } if( pagerUseWal(pPager) ){ /* Drop the WAL write-lock, if any. Also, if the connection was in @@ -2024,11 +2008,6 @@ 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 uS wal=%d", - iDebugTimer, pagerUseWal(pPager)); - iDebugTimerStart += iDebugTimer; - } if( rc==SQLITE_OK && bCommit && isOpen(pPager->fd) ){ rc = sqlite3OsFileControl(pPager->fd, SQLITE_FCNTL_COMMIT_PHASETWO, 0); @@ -2044,10 +2023,6 @@ 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 uS wal=%d", - iDebugTimer, pagerUseWal(pPager)); - } return (rc==SQLITE_OK?rc2:rc); } diff --git a/src/pcache1.c b/src/pcache1.c index c66d06391d..5ae4ad06e3 100644 --- a/src/pcache1.c +++ b/src/pcache1.c @@ -521,8 +521,11 @@ static void pcache1TruncateUnsafe( } assert( pCache->nPage==nPage ); END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){ - sqlite3_log(SQLITE_NOTICE, "slow pcache1TruncateUnsafe() %lld nFree=%d", - iDebugTimer, nFree); + sqlite3_log(SQLITE_NOTICE, + "slow pcache1TruncateUnsafe() %lld " + " nFree=%d nHash=%d nPage=%d iLimit=%d iMaxKey=%d", + iDebugTimer, + nFree, pCache->nHash, pCache->nPage, iLimit, pCache->iMaxKey); } } @@ -934,17 +937,12 @@ static void pcache1Rekey( */ static void pcache1Truncate(sqlite3_pcache *p, unsigned int iLimit){ PCache1 *pCache = (PCache1 *)p; - START_DEBUG_TIMER; pcache1EnterMutex(pCache->pGroup); if( iLimit<=pCache->iMaxKey ){ pcache1TruncateUnsafe(pCache, iLimit); pCache->iMaxKey = iLimit-1; } pcache1LeaveMutex(pCache->pGroup); - END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ){ - sqlite3_log(SQLITE_NOTICE, "slow pcache1Truncate(%d): %llu uS", - (int)iLimit, iDebugTimer); - } } /* diff --git a/src/vdbeapi.c b/src/vdbeapi.c index 857494ed83..0ab76e0784 100644 --- a/src/vdbeapi.c +++ b/src/vdbeapi.c @@ -395,7 +395,6 @@ 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; inDb; i++){ @@ -408,9 +407,6 @@ static int doWalCallbacks(sqlite3 *db){ } } #endif - END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ) { - sqlite3_log(SQLITE_NOTICE, "slow doWalCallbacks: %llu uS", iDebugTimer); - } return rc; } @@ -426,7 +422,6 @@ 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 ){ @@ -545,11 +540,6 @@ end_of_step: */ rc = sqlite3VdbeTransferError(p); } - END_DEBUG_TIMER( DEBUG_TIMER_BIG_TIMEOUT ) { - sqlite3_log(SQLITE_NOTICE, "slow (%llu) sqlite3Step(%s)", - iDebugTimer, (p->zSql ? p->zSql : "") - ); - } return (rc&db->errMask); } diff --git a/src/vdbeaux.c b/src/vdbeaux.c index a2c969a91b..c0018bb71c 100644 --- a/src/vdbeaux.c +++ b/src/vdbeaux.c @@ -1905,7 +1905,6 @@ 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 @@ -2135,9 +2134,6 @@ 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 cb1d36ea57..c0861d5be7 100644 --- a/src/wal.c +++ b/src/wal.c @@ -1718,14 +1718,6 @@ static int walCheckpoint( i64 nSize; /* Current size of database file */ u32 nBackfill = pInfo->nBackfill; - /* ELATDPP: Extra logging added to debug performance problem */ - sqlite3_log(SQLITE_NOTICE, - "wal: checkpoint salt1=%08x salt2=%08x " - "nBackfill=%d mxSafeFrame=%d mxFrame=%d", - pWal->hdr.aSalt[0], pWal->hdr.aSalt[1], - (int)nBackfill, (int)mxSafeFrame, (int)pWal->hdr.mxFrame - ); - /* Sync the WAL to disk */ if( sync_flags ){ rc = sqlite3OsSync(pWal->pWalFd, sync_flags); @@ -2738,8 +2730,6 @@ int sqlite3WalFrames( i64 iOffset; /* Next byte to write in WAL file */ WalWriter w; /* The writer */ - START_DEBUG_TIMER; - assert( pList ); assert( pWal->writeLock ); @@ -2827,12 +2817,6 @@ int sqlite3WalFrames( iOffset += szFrame; } - /* ELATDPP: Extra logging added to debug performance problem */ - sqlite3_log(SQLITE_NOTICE, "wal: write nFrame=%d iFrame=%d", - iFrame - pWal->hdr.mxFrame, - pWal->hdr.mxFrame+1 - ); - /* If this is the end of a transaction, then we might need to pad ** the transaction and/or sync the WAL file. ** @@ -2908,10 +2892,6 @@ 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; } @@ -2941,10 +2921,6 @@ int sqlite3WalCheckpoint( int isChanged = 0; /* True if a new wal-index header is loaded */ int eMode2 = eMode; /* Mode to pass to walCheckpoint() */ - /* ELATDPP: Extra logging added to debug performance problem */ - sqlite3_int64 t1, t2; - sqlite3OsCurrentTimeInt64(pWal->pVfs, &t1); - assert( pWal->ckptLock==0 ); assert( pWal->writeLock==0 ); @@ -3015,11 +2991,6 @@ int sqlite3WalCheckpoint( sqlite3WalEndWriteTransaction(pWal); walUnlockExclusive(pWal, WAL_CKPT_LOCK, 1); pWal->ckptLock = 0; - - /* ELATDPP: Extra logging added to debug performance problem */ - sqlite3OsCurrentTimeInt64(pWal->pVfs, &t2); - sqlite3_log(SQLITE_NOTICE, "wal: checkpoint rc=%d ms=%lld", rc, t2-t1); - WALTRACE(("WAL%p: checkpoint %s\n", pWal, rc ? "failed" : "ok")); return (rc==SQLITE_OK && eMode!=eMode2 ? SQLITE_BUSY : rc); }