/ Check-in [613c1cea]
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 | SQL archive
Timelines: family | ancestors | descendants | both | debug
Files: files | file ages | folders
SHA1: 613c1ceaf4d552dc29aff090825941eaae6baed1
User & Date: dan 2016-07-16 11:47:45
Context
2016-07-29
14:10
Add calls to sqlite3_log() when sqlite3_mutex_enter() takes more than 100,000 CPU cycles. check-in: 33c7ef7a 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: 613c1cea 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: 46bd9533 user: drh tags: btree-balance-bias
Changes
Hide Diffs Unified Diffs Ignore Whitespace Patch

Changes to src/wal.c.

1713
1714
1715
1716
1717
1718
1719








1720
1721
1722
1723
1724
1725
1726
....
2812
2813
2814
2815
2816
2817
2818






2819
2820
2821
2822
2823
2824
2825
....
2917
2918
2919
2920
2921
2922
2923




2924
2925
2926
2927
2928
2929
2930
....
2987
2988
2989
2990
2991
2992
2993





2994
2995
2996
2997
2998
2999
3000
  }

  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
................................................................................
    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.
................................................................................
  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 ){
................................................................................
    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







>
>
>
>
>
>
>
>







 







>
>
>
>
>
>







 







>
>
>
>







 







>
>
>
>
>







1713
1714
1715
1716
1717
1718
1719
1720
1721
1722
1723
1724
1725
1726
1727
1728
1729
1730
1731
1732
1733
1734
....
2820
2821
2822
2823
2824
2825
2826
2827
2828
2829
2830
2831
2832
2833
2834
2835
2836
2837
2838
2839
....
2931
2932
2933
2934
2935
2936
2937
2938
2939
2940
2941
2942
2943
2944
2945
2946
2947
2948
....
3005
3006
3007
3008
3009
3010
3011
3012
3013
3014
3015
3016
3017
3018
3019
3020
3021
3022
3023
  }

  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
................................................................................
    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.
................................................................................
  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 ){
................................................................................
    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