SQLite

Check-in [9d4eb6e475]
Login

Many hyperlinks are disabled.
Use anonymous login to enable hyperlinks.

Overview
Comment:Refocus the timer on the pager_end_transaction() routine.
Downloads: Tarball | ZIP archive
Timelines: family | ancestors | descendants | both | debug
Files: files | file ages | folders
SHA1: 9d4eb6e4750939c48aff267000bd69a73e1dc364
User & Date: drh 2016-08-09 01:21:16.687
Context
2016-08-09
11:23
Add a debug timer to pcache1Truncate(). Change the formatting of some other messages to make them easier to read. (check-in: 7d0af4b53c user: dan tags: debug)
01:21
Refocus the timer on the pager_end_transaction() routine. (check-in: 9d4eb6e475 user: drh tags: debug)
2016-08-04
14:08
Add extra logging calls to this branch. (check-in: 491f1ef36e user: dan tags: debug)
Changes
Unified Diff Ignore Whitespace Patch
Changes to src/malloc.c.
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325

/*
** Allocate memory.  This routine is like sqlite3_malloc() except that it
** assumes the memory subsystem has already been initialized.
*/
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
    ** xMalloc().  Hence we limit the maximum size to 0x7fffff00, giving
    ** 255 bytes of overhead.  SQLite itself will never use anything near
    ** this amount.  The only way to reach the limit is with sqlite3_malloc() */
    p = 0;
  }else if( sqlite3GlobalConfig.bMemstat ){
    sqlite3_mutex_enter(mem0.mutex);
    mallocWithAlarm((int)n, &p);
    sqlite3_mutex_leave(mem0.mutex);
  }else{
    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;
}

/*
** This version of the memory allocation is for use by the application.
** First make sure the memory subsystem is initialized, then do the
** allocation.







<















<
<
<
<







292
293
294
295
296
297
298

299
300
301
302
303
304
305
306
307
308
309
310
311
312
313




314
315
316
317
318
319
320

/*
** Allocate memory.  This routine is like sqlite3_malloc() except that it
** assumes the memory subsystem has already been initialized.
*/
void *sqlite3Malloc(u64 n){
  void *p;

  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
    ** xMalloc().  Hence we limit the maximum size to 0x7fffff00, giving
    ** 255 bytes of overhead.  SQLite itself will never use anything near
    ** this amount.  The only way to reach the limit is with sqlite3_malloc() */
    p = 0;
  }else if( sqlite3GlobalConfig.bMemstat ){
    sqlite3_mutex_enter(mem0.mutex);
    mallocWithAlarm((int)n, &p);
    sqlite3_mutex_leave(mem0.mutex);
  }else{
    p = sqlite3GlobalConfig.m.xMalloc((int)n);
  }
  assert( EIGHT_BYTE_ALIGNMENT(p) );  /* IMP: R-11148-40995 */




  return p;
}

/*
** This version of the memory allocation is for use by the application.
** First make sure the memory subsystem is initialized, then do the
** allocation.
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
  return (sqlite3_uint64)sqlite3GlobalConfig.m.xSize(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) );
  if( sqlite3GlobalConfig.bMemstat ){
    sqlite3_mutex_enter(mem0.mutex);
    sqlite3StatusAdd(SQLITE_STATUS_MEMORY_USED, -sqlite3MallocSize(p));
    sqlite3StatusAdd(SQLITE_STATUS_MALLOC_COUNT, -1);
    sqlite3GlobalConfig.m.xFree(p);
    sqlite3_mutex_leave(mem0.mutex);
  }else{
    sqlite3GlobalConfig.m.xFree(p);
  }
  END_DEBUG_TIMER( DEBUG_TIMER_SMALL_TIMEOUT ){
    sqlite3_log(SQLITE_NOTICE, "slow sqlite3_free(ptr): %llu uS", iDebugTimer);
  }
}

/*
** Add the size of memory allocation "p" to the count in
** *db->pnBytesFreed.
*/
static SQLITE_NOINLINE void measureAllocationSize(sqlite3 *db, void *p){







<












<
<
<







471
472
473
474
475
476
477

478
479
480
481
482
483
484
485
486
487
488
489



490
491
492
493
494
495
496
  return (sqlite3_uint64)sqlite3GlobalConfig.m.xSize(p);
}

/*
** Free memory previously obtained from sqlite3Malloc().
*/
void sqlite3_free(void *p){

  if( p==0 ) return;  /* IMP: R-49053-54554 */
  assert( sqlite3MemdebugHasType(p, MEMTYPE_HEAP) );
  assert( sqlite3MemdebugNoType(p, ~MEMTYPE_HEAP) );
  if( sqlite3GlobalConfig.bMemstat ){
    sqlite3_mutex_enter(mem0.mutex);
    sqlite3StatusAdd(SQLITE_STATUS_MEMORY_USED, -sqlite3MallocSize(p));
    sqlite3StatusAdd(SQLITE_STATUS_MALLOC_COUNT, -1);
    sqlite3GlobalConfig.m.xFree(p);
    sqlite3_mutex_leave(mem0.mutex);
  }else{
    sqlite3GlobalConfig.m.xFree(p);
  }



}

/*
** Add the size of memory allocation "p" to the count in
** *db->pnBytesFreed.
*/
static SQLITE_NOINLINE void measureAllocationSize(sqlite3 *db, void *p){
Changes to src/pager.c.
1903
1904
1905
1906
1907
1908
1909

1910
1911
1912
1913
1914
1915
1916
** unlock operation fails as well, then the first error code related
** to the first error encountered (the journal finalization one) is
** returned.
*/
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 */


  /* 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
  ** is no write-transaction active but a RESERVED or greater lock is
  ** held under two circumstances:
  **
  **   1. After a successful hot-journal rollback, it is called with







>







1903
1904
1905
1906
1907
1908
1909
1910
1911
1912
1913
1914
1915
1916
1917
** unlock operation fails as well, then the first error code related
** to the first error encountered (the journal finalization one) is
** returned.
*/
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
  ** is no write-transaction active but a RESERVED or greater lock is
  ** held under two circumstances:
  **
  **   1. After a successful hot-journal rollback, it is called with
1969
1970
1971
1972
1973
1974
1975





1976
1977
1978
1979
1980
1981
1982
1983
1984
1985
1986
1987
1988
1989
1990
1991





1992





1993
1994
1995
1996
1997
1998
1999
2000
2001
2002
2003
2004
2005
2006
2007
2008
2009
2010





2011
2012
2013
2014
2015
2016
2017
2018
2019
2020
2021
2022
2023
2024
2025




2026
2027
2028
2029
2030
2031
2032
      );
      sqlite3OsClose(pPager->jfd);
      if( bDelete ){
        rc = sqlite3OsDelete(pPager->pVfs, pPager->zJournal, 0);
      }
    }
  }






#ifdef SQLITE_CHECK_PAGES
  sqlite3PcacheIterateDirty(pPager->pPCache, pager_set_pagehash);
  if( pPager->dbSize==0 && sqlite3PcacheRefCount(pPager->pPCache)>0 ){
    PgHdr *p = sqlite3PagerLookup(pPager, 1);
    if( p ){
      p->pageHash = 0;
      sqlite3PagerUnrefNotNull(p);
    }
  }
#endif

  sqlite3BitvecDestroy(pPager->pInJournal);
  pPager->pInJournal = 0;
  pPager->nRec = 0;
  sqlite3PcacheCleanAll(pPager->pPCache);





  sqlite3PcacheTruncate(pPager->pPCache, pPager->dbSize);






  if( pagerUseWal(pPager) ){
    /* Drop the WAL write-lock, if any. Also, if the connection was in 
    ** locking_mode=exclusive mode but is no longer, drop the EXCLUSIVE 
    ** lock held on the database file.
    */
    rc2 = sqlite3WalEndWriteTransaction(pPager->pWal);
    assert( rc2==SQLITE_OK );
  }else if( rc==SQLITE_OK && bCommit && pPager->dbFileSize>pPager->dbSize ){
    /* This branch is taken when committing a transaction in rollback-journal
    ** mode if the database file on disk is larger than the database image.
    ** At this point the journal has been finalized and the transaction 
    ** successfully committed, but the EXCLUSIVE lock is still held on the
    ** file. So it is safe to truncate the database file to its minimum
    ** required size.  */
    assert( pPager->eLock==EXCLUSIVE_LOCK );
    rc = pager_truncate(pPager, pPager->dbSize);
  }






  if( rc==SQLITE_OK && bCommit && isOpen(pPager->fd) ){
    rc = sqlite3OsFileControl(pPager->fd, SQLITE_FCNTL_COMMIT_PHASETWO, 0);
    if( rc==SQLITE_NOTFOUND ) rc = SQLITE_OK;
  }

  if( !pPager->exclusiveMode 
   && (!pagerUseWal(pPager) || sqlite3WalExclusiveMode(pPager->pWal, 0))
  ){
    rc2 = pagerUnlockDb(pPager, SHARED_LOCK);
    pPager->changeCountDone = 0;
  }
  pPager->eState = PAGER_READER;
  pPager->setMaster = 0;





  return (rc==SQLITE_OK?rc2:rc);
}

/*
** Execute a rollback if a transaction is active and unlock the 
** database file. 
**







>
>
>
>
>
















>
>
>
>
>

>
>
>
>
>


















>
>
>
>
>















>
>
>
>







1970
1971
1972
1973
1974
1975
1976
1977
1978
1979
1980
1981
1982
1983
1984
1985
1986
1987
1988
1989
1990
1991
1992
1993
1994
1995
1996
1997
1998
1999
2000
2001
2002
2003
2004
2005
2006
2007
2008
2009
2010
2011
2012
2013
2014
2015
2016
2017
2018
2019
2020
2021
2022
2023
2024
2025
2026
2027
2028
2029
2030
2031
2032
2033
2034
2035
2036
2037
2038
2039
2040
2041
2042
2043
2044
2045
2046
2047
2048
2049
2050
2051
2052
2053
2054
2055
2056
2057
      );
      sqlite3OsClose(pPager->jfd);
      if( bDelete ){
        rc = sqlite3OsDelete(pPager->pVfs, pPager->zJournal, 0);
      }
    }
  }
  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);
  if( pPager->dbSize==0 && sqlite3PcacheRefCount(pPager->pPCache)>0 ){
    PgHdr *p = sqlite3PagerLookup(pPager, 1);
    if( p ){
      p->pageHash = 0;
      sqlite3PagerUnrefNotNull(p);
    }
  }
#endif

  sqlite3BitvecDestroy(pPager->pInJournal);
  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 
    ** locking_mode=exclusive mode but is no longer, drop the EXCLUSIVE 
    ** lock held on the database file.
    */
    rc2 = sqlite3WalEndWriteTransaction(pPager->pWal);
    assert( rc2==SQLITE_OK );
  }else if( rc==SQLITE_OK && bCommit && pPager->dbFileSize>pPager->dbSize ){
    /* This branch is taken when committing a transaction in rollback-journal
    ** mode if the database file on disk is larger than the database image.
    ** At this point the journal has been finalized and the transaction 
    ** successfully committed, but the EXCLUSIVE lock is still held on the
    ** file. So it is safe to truncate the database file to its minimum
    ** required size.  */
    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);
    if( rc==SQLITE_NOTFOUND ) rc = SQLITE_OK;
  }

  if( !pPager->exclusiveMode 
   && (!pagerUseWal(pPager) || sqlite3WalExclusiveMode(pPager->pWal, 0))
  ){
    rc2 = pagerUnlockDb(pPager, SHARED_LOCK);
    pPager->changeCountDone = 0;
  }
  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);
}

/*
** Execute a rollback if a transaction is active and unlock the 
** database file. 
**
6102
6103
6104
6105
6106
6107
6108
6109
6110
6111
6112
6113
6114
6115
6116
6117
int sqlite3PagerCommitPhaseOne(
  Pager *pPager,                  /* Pager object */
  const char *zMaster,            /* If not NULL, the master journal name */
  int noSync                      /* True to omit the xSync on the db file */
){
  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
       || pPager->eState==PAGER_ERROR
  );
  assert( assert_pager_state(pPager) );








<
<







6127
6128
6129
6130
6131
6132
6133


6134
6135
6136
6137
6138
6139
6140
int sqlite3PagerCommitPhaseOne(
  Pager *pPager,                  /* Pager object */
  const char *zMaster,            /* If not NULL, the master journal name */
  int noSync                      /* True to omit the xSync on the db file */
){
  int rc = SQLITE_OK;             /* Return code */



  assert( pPager->eState==PAGER_WRITER_LOCKED
       || pPager->eState==PAGER_WRITER_CACHEMOD
       || pPager->eState==PAGER_WRITER_DBMOD
       || pPager->eState==PAGER_ERROR
  );
  assert( assert_pager_state(pPager) );

6251
6252
6253
6254
6255
6256
6257
6258
6259
6260
6261
6262
6263
6264
6265
6266
6267
6268
    }
  }

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;
}


/*
** When this function is called, the database file has been completely
** updated to reflect the changes made by the current transaction and







<
<
<
<







6274
6275
6276
6277
6278
6279
6280




6281
6282
6283
6284
6285
6286
6287
    }
  }

commit_phase_one_exit:
  if( rc==SQLITE_OK && !pagerUseWal(pPager) ){
    pPager->eState = PAGER_WRITER_FINISHED;
  }




  return rc;
}


/*
** When this function is called, the database file has been completely
** updated to reflect the changes made by the current transaction and
6276
6277
6278
6279
6280
6281
6282
6283
6284
6285
6286
6287
6288
6289
6290
** irrevocably committed.
**
** If an error occurs, an IO error code is returned and the pager
** moves into the error state. Otherwise, SQLITE_OK is returned.
*/
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
  ** called, just return the same error code without doing anything. */
  if( NEVER(pPager->errCode) ) return pPager->errCode;

  assert( pPager->eState==PAGER_WRITER_LOCKED







<







6295
6296
6297
6298
6299
6300
6301

6302
6303
6304
6305
6306
6307
6308
** irrevocably committed.
**
** If an error occurs, an IO error code is returned and the pager
** moves into the error state. Otherwise, SQLITE_OK is returned.
*/
int sqlite3PagerCommitPhaseTwo(Pager *pPager){
  int rc = SQLITE_OK;                  /* Return code */


  /* 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
  ** called, just return the same error code without doing anything. */
  if( NEVER(pPager->errCode) ) return pPager->errCode;

  assert( pPager->eState==PAGER_WRITER_LOCKED
6311
6312
6313
6314
6315
6316
6317
6318
6319
6320
6321
6322
6323
6324
6325
6326
6327
6328
    assert( pPager->journalOff==JOURNAL_HDR_SZ(pPager) || !pPager->journalOff );
    pPager->eState = PAGER_READER;
    return SQLITE_OK;
  }

  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);
}

/*
** If a write transaction is open, then all changes made within the 
** transaction are reverted and the current write-transaction is closed.
** The pager falls back to PAGER_READER state if successful, or PAGER_ERROR







<
<
<
<







6329
6330
6331
6332
6333
6334
6335




6336
6337
6338
6339
6340
6341
6342
    assert( pPager->journalOff==JOURNAL_HDR_SZ(pPager) || !pPager->journalOff );
    pPager->eState = PAGER_READER;
    return SQLITE_OK;
  }

  PAGERTRACE(("COMMIT %d\n", PAGERID(pPager)));
  rc = pager_end_transaction(pPager, pPager->setMaster, 1);




  return pager_error(pPager, rc);
}

/*
** If a write transaction is open, then all changes made within the 
** transaction are reverted and the current write-transaction is closed.
** The pager falls back to PAGER_READER state if successful, or PAGER_ERROR
Changes to src/sqliteInt.h.
3811
3812
3813
3814
3815
3816
3817

3818
3819
3820
3821
3822
3823
3824
** Threading interface
*/
#if SQLITE_MAX_WORKER_THREADS>0
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;








>







3811
3812
3813
3814
3815
3816
3817
3818
3819
3820
3821
3822
3823
3824
3825
** Threading interface
*/
#if SQLITE_MAX_WORKER_THREADS>0
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;                                   \
  gettimeofday(&debug_timer_var, 0);                                \
  iDebugTimerStart = 1000000*(sqlite3_uint64)debug_timer_var.tv_sec \
                     + debug_timer_var.tv_usec;

Changes to src/vdbeapi.c.
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
    /* If this statement was prepared using sqlite3_prepare_v2(), and an
    ** error has occurred, then return the error code in p->rc to the
    ** caller. Set the error code in the database handle to the same value.
    */ 
    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);
}

/*
** This is the top-level implementation of sqlite3_step().  Call







|
|







542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
    /* If this statement was prepared using sqlite3_prepare_v2(), and an
    ** error has occurred, then return the error code in p->rc to the
    ** caller. Set the error code in the database handle to the same value.
    */ 
    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);
}

/*
** This is the top-level implementation of sqlite3_step().  Call