SQLite

Check-in [613c1ceaf4]
Login

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

Overview
Comment:Temporarily add extra sqlite3_log() calls to this version to help with debugging a performance problem.
Downloads: Tarball | ZIP archive
Timelines: family | ancestors | descendants | both | debug
Files: files | file ages | folders
SHA1: 613c1ceaf4d552dc29aff090825941eaae6baed1
User & Date: dan 2016-07-16 11:47:45.840
Context
2016-07-29
14:10
Add calls to sqlite3_log() when sqlite3_mutex_enter() takes more than 100,000 CPU cycles. (check-in: 33c7ef7aca user: drh tags: debug)
2016-07-16
11:47
Temporarily add extra sqlite3_log() calls to this version to help with debugging a performance problem. (check-in: 613c1ceaf4 user: dan tags: debug)
2016-07-14
20:19
Experimental patch restore the slight bias in btree-balancing immediately after the change to reduces the amount of memcpy() work done by balancing. (Leaf check-in: 46bd9533c0 user: drh tags: btree-balance-bias)
Changes
Unified Diff Ignore Whitespace Patch
Changes to src/wal.c.
1713
1714
1715
1716
1717
1718
1719








1720
1721
1722
1723
1724
1725
1726
  }

  if( pInfo->nBackfill<mxSafeFrame
   && (rc = walBusyLock(pWal, xBusy, pBusyArg, WAL_READ_LOCK(0), 1))==SQLITE_OK
  ){
    i64 nSize;                    /* Current size of database file */
    u32 nBackfill = pInfo->nBackfill;









    /* Sync the WAL to disk */
    if( sync_flags ){
      rc = sqlite3OsSync(pWal->pWalFd, sync_flags);
    }

    /* If the database may grow as a result of this checkpoint, hint







>
>
>
>
>
>
>
>







1713
1714
1715
1716
1717
1718
1719
1720
1721
1722
1723
1724
1725
1726
1727
1728
1729
1730
1731
1732
1733
1734
  }

  if( pInfo->nBackfill<mxSafeFrame
   && (rc = walBusyLock(pWal, xBusy, pBusyArg, WAL_READ_LOCK(0), 1))==SQLITE_OK
  ){
    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);
    }

    /* If the database may grow as a result of this checkpoint, hint
2812
2813
2814
2815
2816
2817
2818






2819
2820
2821
2822
2823
2824
2825
    assert( iOffset==walFrameOffset(iFrame, szPage) );
    nDbSize = (isCommit && p->pDirty==0) ? nTruncate : 0;
    rc = walWriteOneFrame(&w, p, nDbSize, iOffset);
    if( rc ) return rc;
    pLast = p;
    iOffset += szFrame;
  }







  /* If this is the end of a transaction, then we might need to pad
  ** the transaction and/or sync the WAL file.
  **
  ** Padding and syncing only occur if this set of frames complete a
  ** transaction and if PRAGMA synchronous=FULL.  If synchronous==NORMAL
  ** or synchronous==OFF, then no padding or syncing are needed.







>
>
>
>
>
>







2820
2821
2822
2823
2824
2825
2826
2827
2828
2829
2830
2831
2832
2833
2834
2835
2836
2837
2838
2839
    assert( iOffset==walFrameOffset(iFrame, szPage) );
    nDbSize = (isCommit && p->pDirty==0) ? nTruncate : 0;
    rc = walWriteOneFrame(&w, p, nDbSize, iOffset);
    if( rc ) return rc;
    pLast = p;
    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.
  **
  ** Padding and syncing only occur if this set of frames complete a
  ** transaction and if PRAGMA synchronous=FULL.  If synchronous==NORMAL
  ** or synchronous==OFF, then no padding or syncing are needed.
2917
2918
2919
2920
2921
2922
2923




2924
2925
2926
2927
2928
2929
2930
  int *pnLog,                     /* OUT: Number of frames in WAL */
  int *pnCkpt                     /* OUT: Number of backfilled frames in WAL */
){
  int rc;                         /* Return code */
  int isChanged = 0;              /* True if a new wal-index header is loaded */
  int eMode2 = eMode;             /* Mode to pass to walCheckpoint() */





  assert( pWal->ckptLock==0 );
  assert( pWal->writeLock==0 );

  if( pWal->readOnly ) return SQLITE_READONLY;
  WALTRACE(("WAL%p: checkpoint begins\n", pWal));
  rc = walLockExclusive(pWal, WAL_CKPT_LOCK, 1);
  if( rc ){







>
>
>
>







2931
2932
2933
2934
2935
2936
2937
2938
2939
2940
2941
2942
2943
2944
2945
2946
2947
2948
  int *pnLog,                     /* OUT: Number of frames in WAL */
  int *pnCkpt                     /* OUT: Number of backfilled frames in WAL */
){
  int rc;                         /* Return code */
  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 );

  if( pWal->readOnly ) return SQLITE_READONLY;
  WALTRACE(("WAL%p: checkpoint begins\n", pWal));
  rc = walLockExclusive(pWal, WAL_CKPT_LOCK, 1);
  if( rc ){
2987
2988
2989
2990
2991
2992
2993





2994
2995
2996
2997
2998
2999
3000
    memset(&pWal->hdr, 0, sizeof(WalIndexHdr));
  }

  /* Release the locks. */
  sqlite3WalEndWriteTransaction(pWal);
  walUnlockExclusive(pWal, WAL_CKPT_LOCK, 1);
  pWal->ckptLock = 0;





  WALTRACE(("WAL%p: checkpoint %s\n", pWal, rc ? "failed" : "ok"));
  return (rc==SQLITE_OK && eMode!=eMode2 ? SQLITE_BUSY : rc);
}

/* Return the value to pass to a sqlite3_wal_hook callback, the
** number of frames in the WAL at the point of the last commit since
** sqlite3WalCallback() was called.  If no commits have occurred since







>
>
>
>
>







3005
3006
3007
3008
3009
3010
3011
3012
3013
3014
3015
3016
3017
3018
3019
3020
3021
3022
3023
    memset(&pWal->hdr, 0, sizeof(WalIndexHdr));
  }

  /* Release the locks. */
  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);
}

/* Return the value to pass to a sqlite3_wal_hook callback, the
** number of frames in the WAL at the point of the last commit since
** sqlite3WalCallback() was called.  If no commits have occurred since