From a9da72afcd774acb9cb7d2e6a7a69f263510fb71 Mon Sep 17 00:00:00 2001 From: dan Date: Thu, 4 Aug 2016 14:08:06 +0000 Subject: [PATCH] Add extra logging calls to this branch. FossilOrigin-Name: 491f1ef36e60aa65d71444b604064e3505cabd18 --- manifest | 28 ++++++++++++++-------------- manifest.uuid | 2 +- src/malloc.c | 9 +++++++++ src/mutex_unix.c | 13 ++++--------- src/os.c | 41 +++++++++++++++++++++++++++++++++++++---- src/pager.c | 11 +++++++++++ src/sqliteInt.h | 17 +++++++++++++++++ src/vdbeapi.c | 10 ++++++++++ src/vdbeaux.c | 4 ++++ src/wal.c | 6 ++++++ 10 files changed, 113 insertions(+), 28 deletions(-) diff --git a/manifest b/manifest index 8c6b45215a..b439f07b08 100644 --- 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 06b489ad7c..20a8fb48a9 100644 --- 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 6fb9d53d1b..da8570e2aa 100644 --- 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 59b0ec97bc..9b16c0e838 100644 --- 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 b6c28a1dc4..f9665e337c 100644 --- 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 997f842d0a..ff665a36fc 100644 --- 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 d2f2f37fc8..9f7e75d58b 100644 --- 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 0ab76e0784..d4e3f2475f 100644 --- 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; inDb; 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 c0018bb71c..a2c969a91b 100644 --- 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 d49b0a3c57..cb1d36ea57 100644 --- 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; } -- 2.47.2