Invoke sqlite3_log() whenever one or more frames are recovered from a WAL file.

FossilOrigin-Name: e05089aaefe02ec59a1923812349471a78075d29

diff --git a/manifest b/manifest
index fd3c9c708d65d1783b3e78c8e5c53da5a2f55001..b20dcccde0aacff94b5ca7ab5a75d90cc74e703a 100644 (file)
--- a/manifest
+++ b/manifest
@@ -1,5 +1,5 @@
-C Fix\ssome\snon-ANSI\sC\scode\sin\stest_demovfs.c.\sAlso\schange\sthe\ssame\sfile\sso\sthat\sattempting\sto\sdelete\sa\sfile\sthat\sdoes\snot\sexist\sdoes\snot\sreturn\san\serror.
-D 2010-08-17T05:55:36
+C Invoke\ssqlite3_log()\swhenever\sone\sor\smore\sframes\sare\srecovered\sfrom\sa\sWAL\sfile.
+D 2010-08-17T14:52:23
 F Makefile.arm-wince-mingw32ce-gcc d6df77f1f48d690bd73162294bbba7f59507c72f
 F Makefile.in ec08dc838fd8110fe24c92e5130bcd91cbb1ff2e
 F Makefile.linux-gcc 91d710bdc4998cb015f39edf3cb314ec4f4d7e23
@@ -177,7 +177,7 @@ F src/sqliteLimit.h 4ae9b005144400984cbcafd4d7c09659bb2af92a
 F src/status.c 496913d4e8441195f6f2a75b1c95993a45b9b30b
 F src/table.c 2cd62736f845d82200acfa1287e33feb3c15d62e
 F src/tclsqlite.c 5cd96419fb6c771006f064196ccc70c29d01bec7
-F src/test1.c 0bfcda72f9f8ab5c0e90fac05cc22c1c21131ddf
+F src/test1.c 55005c9781b157b1d215ba145768783b9abae78c
 F src/test2.c 80d323d11e909cf0eb1b6fbb4ac22276483bcf31
 F src/test3.c 4c21700c73a890a47fc685c1097bfb661346ac94
 F src/test4.c 0528360b5025688002a5feb6be906ddce52eaaee
@@ -227,7 +227,7 @@ F src/vdbeblob.c 258a6010ba7a82b72b327fb24c55790655689256
 F src/vdbemem.c e5673f81a2381b35c60e73ef0a8502be2ab1041e
 F src/vdbetrace.c 864cef96919323482ebd9986f2132435115e9cc2
 F src/vtab.c 0e8e0cb30dffb078367e843e84e37ef99236c7e4
-F src/wal.c 241b963c0244b26eba2d5de63fb96a94dad0bc3b
+F src/wal.c 109c45210e5b01c6fd3de92805488a2f6895e17f
 F src/wal.h 96669b645e27cd5a111ba59f0cae7743a207bc3c
 F src/walker.c 3112bb3afe1d85dc52317cb1d752055e9a781f8f
 F src/where.c 7db3e41c2a846f9deeb24f1bbb75461b4010b7b5
@@ -782,7 +782,7 @@ F test/vtabE.test 7c4693638d7797ce2eda17af74292b97e705cc61
 F test/vtab_alter.test 9e374885248f69e251bdaacf480b04a197f125e5
 F test/vtab_err.test 0d4d8eb4def1d053ac7c5050df3024fd47a3fbd8
 F test/vtab_shared.test 0eff9ce4f19facbe0a3e693f6c14b80711a4222d
-F test/wal.test a63947f76decb58d7a707d152cb1c34187e54cc6
+F test/wal.test 5847943563e4a38aa9ceff12891a52bdda17f3a6
 F test/wal2.test 223f3e14d475730af772a7f5862d4bcfa7565c3a
 F test/wal3.test 695ea0f6c516423c611891df9a285aacd33344e3
 F test/wal4.test 3404b048fa5e10605facaf70384e6d2943412e30
@@ -843,7 +843,7 @@ F tool/speedtest2.tcl ee2149167303ba8e95af97873c575c3e0fab58ff
 F tool/speedtest8.c 2902c46588c40b55661e471d7a86e4dd71a18224
 F tool/speedtest8inst1.c 293327bc76823f473684d589a8160bde1f52c14e
 F tool/vdbe-compress.tcl d70ea6d8a19e3571d7ab8c9b75cba86d1173ff0f
-P 4271a95c8236bda4a4f8c02bf3a3560de1d00402
-R 18c0cd58bb3c4ba7fcb0fd62a8f6bf9b
+P 07570ce38051a05d6e8a71e39766850f6719ac07
+R 9dc78c7561a603e522c0bb81eb112898
 U dan
-Z ca9e70bb404e459223eefc978ac4467f
+Z d52d7cfd0d7a3de647988329bc045380

diff --git a/manifest.uuid b/manifest.uuid
index 5ec57d6f42802bc3900f6f0f41aebacf4cbe0e43..a265d51e137297860a5589cca8697b24458a4d54 100644 (file)
--- a/manifest.uuid
+++ b/manifest.uuid
@@ -1 +1 @@
-07570ce38051a05d6e8a71e39766850f6719ac07
\ No newline at end of file
+e05089aaefe02ec59a1923812349471a78075d29
\ No newline at end of file

diff --git a/src/test1.c b/src/test1.c
index acb812b372e33ac90702c2b8865d8828980b3080..f458cdb40b0e3715b0fbb057e9479ad3ce2cbfe9 100644 (file)
--- a/src/test1.c
+++ b/src/test1.c
@@ -4949,6 +4949,47 @@ static int test_wal_checkpoint(
   return TCL_OK;
 }
 
+/*
+** tclcmd:  test_sqlite3_log ?SCRIPT?
+*/
+static struct LogCallback {
+  Tcl_Interp *pInterp;
+  Tcl_Obj *pObj;
+} logcallback = {0, 0};
+static void xLogcallback(void *unused, int err, char *zMsg){
+  Tcl_Obj *pNew = Tcl_DuplicateObj(logcallback.pObj);
+  Tcl_IncrRefCount(pNew);
+  Tcl_ListObjAppendElement(
+      0, pNew, Tcl_NewStringObj(sqlite3TestErrorName(err), -1)
+  );
+  Tcl_ListObjAppendElement(0, pNew, Tcl_NewStringObj(zMsg, -1));
+  Tcl_EvalObjEx(logcallback.pInterp, pNew, TCL_EVAL_GLOBAL|TCL_EVAL_DIRECT);
+  Tcl_DecrRefCount(pNew);
+}
+static int test_sqlite3_log(
+  ClientData clientData,
+  Tcl_Interp *interp,    /* The TCL interpreter that invoked this command */
+  int objc,              /* Number of arguments */
+  Tcl_Obj *CONST objv[]  /* Command arguments */
+){
+  if( objc>2 ){
+    Tcl_WrongNumArgs(interp, 1, objv, "SCRIPT");
+    return TCL_ERROR;
+  }
+  if( logcallback.pObj ){
+    Tcl_DecrRefCount(logcallback.pObj);
+    logcallback.pObj = 0;
+    logcallback.pInterp = 0;
+    sqlite3_config(SQLITE_CONFIG_LOG, 0, 0);
+  }
+  if( objc>1 ){
+    logcallback.pObj = objv[1];
+    Tcl_IncrRefCount(logcallback.pObj);
+    logcallback.pInterp = interp;
+    sqlite3_config(SQLITE_CONFIG_LOG, xLogcallback, 0);
+  }
+  return TCL_OK;
+}
 
 /*
 **     tcl_objproc COMMANDNAME ARGS...
@@ -5172,6 +5213,7 @@ int Sqlitetest1_Init(Tcl_Interp *interp){
      { "sqlite3_unlock_notify", test_unlock_notify, 0  },
 #endif
      { "sqlite3_wal_checkpoint", test_wal_checkpoint, 0  },
+     { "test_sqlite3_log",     test_sqlite3_log, 0  },
   };
   static int bitmask_size = sizeof(Bitmask)*8;
   int i;

diff --git a/src/wal.c b/src/wal.c
index 12b5b73c438179fc46992264d124871fb0d0a2f6..94c6925ae27a3734f7ace7dab8e07e4c1f4a8469 100644 (file)
--- a/src/wal.c
+++ b/src/wal.c
@@ -1162,6 +1162,17 @@ finished:
     pInfo->nBackfill = 0;
     pInfo->aReadMark[0] = 0;
     for(i=1; i<WAL_NREADER; i++) pInfo->aReadMark[i] = READMARK_NOT_USED;
+
+    /* If more than one frame was recovered from the log file, report an
+    ** event via sqlite3_log(). This is to help with identifying performance
+    ** problems caused by applications routinely shutting down without
+    ** checkpointing the log file.
+    */
+    if( pWal->hdr.nPage ){
+      sqlite3_log(SQLITE_OK, "Recovered %d frames from WAL file %s",
+          pWal->hdr.nPage, pWal->zWalName
+      );
+    }
   }
 
 recovery_error:

diff --git a/test/wal.test b/test/wal.test
index 09648734a3a749bf05d52995a92ed3d3b6ef95af..0b3d4a041bfb6d5369e14261cdd77929ccc3b63b 100644 (file)
--- a/test/wal.test
+++ b/test/wal.test
@@ -1449,7 +1449,7 @@ do_test wal-21.3 {
 #
 foreach pgsz {512 1024 2048 4096 8192 16384 32768 65536} {
   do_multiclient_test tn [string map [list %PGSZ% $pgsz] {
-    do_test e_expr-22.%PGSZ%.$tn.1 {
+    do_test wal-22.%PGSZ%.$tn.1 {
       sql1 {
         PRAGMA main.page_size = %PGSZ%;
         PRAGMA auto_vacuum = 0;
@@ -1460,12 +1460,52 @@ foreach pgsz {512 1024 2048 4096 8192 16384 32768 65536} {
         INSERT INTO t1 SELECT randomblob(800);
       }
     } {wal}
-    do_test e_expr-22.%PGSZ%.$tn.2 { sql2 { PRAGMA integrity_check } } {ok}
-    do_test e_expr-22.%PGSZ%.$tn.3 {
+    do_test wal-22.%PGSZ%.$tn.2 { sql2 { PRAGMA integrity_check } } {ok}
+    do_test wal-22.%PGSZ%.$tn.3 {
       sql1 {PRAGMA wal_checkpoint}
       expr {[file size test.db] % %PGSZ%}
     } {0}
   }]
 }
 
+#-------------------------------------------------------------------------
+# Test that when 1 or more pages are recovered from a WAL file, 
+# sqlite3_log() is invoked to report this to the user.
+#
+set walfile [file join [pwd] test.db-wal]
+catch {db close}
+file delete -force test.db
+do_test wal-23.1 {
+  faultsim_delete_and_reopen
+  execsql {
+    CREATE TABLE t1(a, b);
+    PRAGMA journal_mode = WAL;
+    INSERT INTO t1 VALUES(1, 2);
+    INSERT INTO t1 VALUES(3, 4);
+  }
+  faultsim_save_and_close
+
+  sqlite3_shutdown
+  test_sqlite3_log [list lappend ::log]
+  set ::log [list]
+  sqlite3 db test.db
+  execsql { SELECT * FROM t1 }
+} {1 2 3 4}
+do_test wal-23.2 { set ::log } {}
+
+do_test wal-23.3 {
+  db close
+  set ::log [list]
+  faultsim_restore_and_reopen
+  execsql { SELECT * FROM t1 }
+} {1 2 3 4}
+do_test wal-23.4 { 
+  set ::log 
+} [list SQLITE_OK "Recovered 2 frames from WAL file $walfile"]
+
+db close
+sqlite3_shutdown
+test_sqlite3_log
+sqlite3_initialize
+
 finish_test