test/walthread.test

   1 # 2010 April 13
   2 #
   3 # The author disclaims copyright to this source code.  In place of
   4 # a legal notice, here is a blessing:
   5 #
   6 #    May you do good and not evil.
   7 #    May you find forgiveness for yourself and forgive others.
   8 #    May you share freely, never taking more than you give.
   9 #
  10 #***********************************************************************
  11 # This file implements regression tests for SQLite library.  The
  12 # focus of this file is testing the operation of the library in
  13 # "PRAGMA journal_mode=WAL" mode with multiple threads.
  14 #
  15
  16 set testdir [file dirname $argv0]
  17
  18 source $testdir/tester.tcl
  19 source $testdir/lock_common.tcl
  20 if {[run_thread_tests]==0} { finish_test ; return }
  21 ifcapable !wal             { finish_test ; return }
  22
  23 set sqlite_walsummary_mmap_incr 64
  24
  25 # How long, in seconds, to run each test for. If a test is set to run for
  26 # 0 seconds, it is omitted entirely.
  27 #
  28 unset -nocomplain seconds
  29 set seconds(walthread-1) 20
  30 set seconds(walthread-2) 20
  31 set seconds(walthread-3) 20
  32 set seconds(walthread-4) 20
  33 set seconds(walthread-5) 1
  34
  35 # The parameter is the name of a variable in the callers context. The
  36 # variable may or may not exist when this command is invoked.
  37 #
  38 # If the variable does exist, its value is returned. Otherwise, this
  39 # command uses [vwait] to wait until it is set, then returns the value.
  40 # In other words, this is a version of the [set VARNAME] command that
  41 # blocks until a variable exists.
  42 #
  43 proc wait_for_var {varname} {
  44   if {0==[uplevel [list info exists $varname]]} {
  45     uplevel [list vwait $varname]
  46   }
  47   uplevel [list set $varname]
  48 }
  49
  50 # The argument is the name of a list variable in the callers context. The
  51 # first element of the list is removed and returned. For example:
  52 #
  53 #   set L {a b c}
  54 #   set x [lshift L]
  55 #   assert { $x == "a" && $L == "b c" }
  56 #
  57 proc lshift {lvar} {
  58   upvar $lvar L
  59   set ret [lindex $L 0]
  60   set L [lrange $L 1 end]
  61   return $ret
  62 }
  63
  64
  65 #-------------------------------------------------------------------------
  66 #   do_thread_test TESTNAME OPTIONS...
  67 #
  68 # where OPTIONS are:
  69 #
  70 #   -seconds   SECONDS                How many seconds to run the test for
  71 #   -init      SCRIPT                 Script to run before test.
  72 #   -thread    NAME COUNT SCRIPT      Scripts to run in threads (or processes).
  73 #   -processes BOOLEAN                True to use processes instead of threads.
  74 #   -check     SCRIPT                 Script to run after test.
  75 #
  76 proc do_thread_test {args} {
  77
  78   set A $args
  79
  80   set P(testname) [lshift A]
  81   set P(seconds) 5
  82   set P(init) ""
  83   set P(threads) [list]
  84   set P(processes) 0
  85   set P(check) {
  86     set ic [db eval "PRAGMA integrity_check"]
  87     if {$ic != "ok"} { error $ic }
  88   }
  89
  90   unset -nocomplain ::done
  91
  92   while {[llength $A]>0} {
  93     set a [lshift A]
  94     switch -glob -- $a {
  95       -seconds {
  96         set P(seconds) [lshift A]
  97       }
  98
  99       -init {
 100         set P(init) [lshift A]
 101       }
 102
 103       -processes {
 104         set P(processes) [lshift A]
 105       }
 106
 107       -check {
 108         set P(check) [lshift A]
 109       }
 110
 111       -thread {
 112         set name  [lshift A]
 113         set count [lshift A]
 114         set prg   [lshift A]
 115         lappend P(threads) [list $name $count $prg]
 116       }
 117
 118       default {
 119         error "Unknown option: $a"
 120       }
 121     }
 122   }
 123
 124   if {$P(seconds) == 0} {
 125     puts "Skipping $P(testname)"
 126     return
 127   }
 128
 129   puts "Running $P(testname) for $P(seconds) seconds..."
 130
 131   catch { db close }
 132   forcedelete test.db test.db-journal test.db-wal
 133
 134   sqlite3 db test.db
 135   eval $P(init)
 136   catch { db close }
 137
 138   foreach T $P(threads) {
 139     set name  [lindex $T 0]
 140     set count [lindex $T 1]
 141     set prg   [lindex $T 2]
 142
 143     for {set i 1} {$i <= $count} {incr i} {
 144       set vars "
 145         set E(pid) $i
 146         set E(nthread) $count
 147         set E(seconds) $P(seconds)
 148       "
 149       set program [string map [list %TEST% $prg %VARS% $vars] {
 150
 151         %VARS%
 152
 153         proc usleep {ms} {
 154           set ::usleep 0
 155           after $ms {set ::usleep 1}
 156           vwait ::usleep
 157         }
 158
 159         proc integrity_check {{db db}} {
 160           set ic [$db eval {PRAGMA integrity_check}]
 161           if {$ic != "ok"} {error $ic}
 162         }
 163
 164         proc busyhandler {n} { usleep 10 ; return 0 }
 165
 166         sqlite3 db test.db
 167         db busy busyhandler
 168         db eval { SELECT randomblob($E(pid)*5) }
 169
 170         set ::finished 0
 171         after [expr $E(seconds) * 1000] {set ::finished 1}
 172         proc tt_continue {} { update ; expr ($::finished==0) }
 173
 174         set rc [catch { %TEST% } msg]
 175
 176         catch { db close }
 177         list $rc $msg
 178       }]
 179
 180       if {$P(processes)==0} {
 181         sqlthread spawn ::done($name,$i) $program
 182       } else {
 183         testfixture_nb ::done($name,$i) $program
 184       }
 185     }
 186   }
 187
 188   set report "  Results:"
 189   foreach T $P(threads) {
 190     set name  [lindex $T 0]
 191     set count [lindex $T 1]
 192     set prg   [lindex $T 2]
 193
 194     set reslist [list]
 195     for {set i 1} {$i <= $count} {incr i} {
 196       set res [wait_for_var ::done($name,$i)]
 197       lappend reslist [lindex $res 1]
 198       do_test $P(testname).$name.$i [list lindex $res 0] 0
 199     }
 200
 201     append report "   $name $reslist"
 202   }
 203   puts $report
 204
 205   sqlite3 db test.db
 206   set res ""
 207   if {[catch $P(check) msg]} { set res $msg }
 208   do_test $P(testname).check [list set {} $res] ""
 209 }
 210
 211 # A wrapper around [do_thread_test] which runs the specified test twice.
 212 # Once using processes, once using threads. This command takes the same
 213 # arguments as [do_thread_test], except specifying the -processes switch
 214 # is illegal.
 215 #
 216 proc do_thread_test2 {args} {
 217   set name [lindex $args 0]
 218   if {[lsearch $args -processes]>=0} { error "bad option: -processes"}
 219   uplevel [lreplace $args 0 0 do_thread_test "$name-threads" -processes 0]
 220   uplevel [lreplace $args 0 0 do_thread_test "$name-processes" -processes 1]
 221 }
 222
 223 #--------------------------------------------------------------------------
 224 # Start 10 threads. Each thread performs both read and write
 225 # transactions. Each read transaction consists of:
 226 #
 227 #   1) Reading the md5sum of all but the last table row,
 228 #   2) Running integrity check.
 229 #   3) Reading the value stored in the last table row,
 230 #   4) Check that the values read in steps 1 and 3 are the same, and that
 231 #      the md5sum of all but the last table row has not changed.
 232 #
 233 # Each write transaction consists of:
 234 #
 235 #   1) Modifying the contents of t1 (inserting, updating, deleting rows).
 236 #   2) Appending a new row to the table containing the md5sum() of all
 237 #      rows in the table.
 238 #
 239 # Each of the N threads runs N read transactions followed by a single write
 240 # transaction in a loop as fast as possible.
 241 #
 242 # There is also a single checkpointer thread. It runs the following loop:
 243 #
 244 #   1) Execute "PRAGMA wal_checkpoint"
 245 #   2) Sleep for 500 ms.
 246 #
 247 do_thread_test2 walthread-1 -seconds $seconds(walthread-1) -init {
 248   execsql {
 249     PRAGMA journal_mode = WAL;
 250     CREATE TABLE t1(x PRIMARY KEY);
 251     PRAGMA lock_status;
 252     INSERT INTO t1 VALUES(randomblob(100));
 253     INSERT INTO t1 VALUES(randomblob(100));
 254     INSERT INTO t1 SELECT md5sum(x) FROM t1;
 255   }
 256 } -thread main 10 {
 257
 258   proc read_transaction {} {
 259     set results [db eval {
 260       BEGIN;
 261         PRAGMA integrity_check;
 262         SELECT md5sum(x) FROM t1 WHERE rowid != (SELECT max(rowid) FROM t1);
 263         SELECT x FROM t1 WHERE rowid = (SELECT max(rowid) FROM t1);
 264         SELECT md5sum(x) FROM t1 WHERE rowid != (SELECT max(rowid) FROM t1);
 265       COMMIT;
 266     }]
 267
 268     if {[llength $results]!=4
 269      || [lindex $results 0] != "ok"
 270      || [lindex $results 1] != [lindex $results 2]
 271      || [lindex $results 2] != [lindex $results 3]
 272     } {
 273       error "Failed read transaction: $results"
 274     }
 275   }
 276
 277   proc write_transaction {} {
 278     db eval {
 279       BEGIN;
 280         INSERT INTO t1 VALUES(randomblob(101 + $::E(pid)));
 281         INSERT INTO t1 VALUES(randomblob(101 + $::E(pid)));
 282         INSERT INTO t1 SELECT md5sum(x) FROM t1;
 283       COMMIT;
 284     }
 285   }
 286
 287   # Turn off auto-checkpoint. Otherwise, an auto-checkpoint run by a
 288   # writer may cause the dedicated checkpoint thread to return an
 289   # SQLITE_BUSY error.
 290   #
 291   db eval { PRAGMA wal_autocheckpoint = 0 }
 292
 293   set nRun 0
 294   while {[tt_continue]} {
 295     read_transaction
 296     write_transaction
 297     incr nRun
 298   }
 299   set nRun
 300
 301 } -thread ckpt 1 {
 302   set nRun 0
 303   while {[tt_continue]} {
 304     db eval "PRAGMA wal_checkpoint"
 305     usleep 500
 306     incr nRun
 307   }
 308   set nRun
 309 }
 310
 311 #--------------------------------------------------------------------------
 312 # This test has clients run the following procedure as fast as possible
 313 # in a loop:
 314 #
 315 #   1. Open a database handle.
 316 #   2. Execute a read-only transaction on the db.
 317 #   3. Do "PRAGMA journal_mode = XXX", where XXX is one of WAL or DELETE.
 318 #      Ignore any SQLITE_BUSY error.
 319 #   4. Execute a write transaction to insert a row into the db.
 320 #   5. Run "PRAGMA integrity_check"
 321 #
 322 # At present, there are 4 clients in total. 2 do "journal_mode = WAL", and
 323 # two do "journal_mode = DELETE".
 324 #
 325 # Each client returns a string of the form "W w, R r", where W is the
 326 # number of write-transactions performed using a WAL journal, and D is
 327 # the number of write-transactions performed using a rollback journal.
 328 # For example, "192 w, 185 r".
 329 #
 330 do_thread_test2 walthread-2 -seconds $seconds(walthread-2) -init {
 331   execsql { CREATE TABLE t1(x INTEGER PRIMARY KEY, y UNIQUE) }
 332 } -thread RB 2 {
 333
 334   db close
 335   set nRun 0
 336   set nDel 0
 337   while {[tt_continue]} {
 338     sqlite3 db test.db
 339     db busy busyhandler
 340     db eval { SELECT * FROM sqlite_master }
 341     catch { db eval { PRAGMA journal_mode = DELETE } }
 342     db eval {
 343       BEGIN;
 344       INSERT INTO t1 VALUES(NULL, randomblob(100+$E(pid)));
 345     }
 346     incr nRun 1
 347     incr nDel [file exists test.db-journal]
 348     if {[file exists test.db-journal] + [file exists test.db-wal] != 1} {
 349       error "File-system looks bad..."
 350     }
 351     db eval COMMIT
 352
 353     integrity_check
 354     db close
 355   }
 356   list $nRun $nDel
 357   set {} "[expr $nRun-$nDel] w, $nDel r"
 358
 359 } -thread WAL 2 {
 360   db close
 361   set nRun 0
 362   set nDel 0
 363   while {[tt_continue]} {
 364     sqlite3 db test.db
 365     db busy busyhandler
 366     db eval { SELECT * FROM sqlite_master }
 367     catch { db eval { PRAGMA journal_mode = WAL } }
 368     db eval {
 369       BEGIN;
 370       INSERT INTO t1 VALUES(NULL, randomblob(110+$E(pid)));
 371     }
 372     incr nRun 1
 373     incr nDel [file exists test.db-journal]
 374     if {[file exists test.db-journal] + [file exists test.db-wal] != 1} {
 375       error "File-system looks bad..."
 376     }
 377     db eval COMMIT
 378
 379     integrity_check
 380     db close
 381   }
 382   set {} "[expr $nRun-$nDel] w, $nDel r"
 383 }
 384
 385 do_thread_test walthread-3 -seconds $seconds(walthread-3) -init {
 386   execsql {
 387     PRAGMA journal_mode = WAL;
 388     CREATE TABLE t1(cnt PRIMARY KEY, sum1, sum2);
 389     CREATE INDEX i1 ON t1(sum1);
 390     CREATE INDEX i2 ON t1(sum2);
 391     INSERT INTO t1 VALUES(0, 0, 0);
 392   }
 393 } -thread t 10 {
 394
 395   set nextwrite $E(pid)
 396
 397   proc wal_hook {zDb nEntry} {
 398     if {$nEntry>10} {
 399       set rc [catch { db eval {PRAGMA wal_checkpoint} } msg]
 400       if {$rc && $msg != "database is locked"} { error $msg }
 401     }
 402     return 0
 403   }
 404   db wal_hook wal_hook
 405
 406   while {[tt_continue]} {
 407     set max 0
 408     while { $max != ($nextwrite-1) && [tt_continue] } {
 409       set max [db eval { SELECT max(cnt) FROM t1 }]
 410     }
 411
 412     if {[tt_continue]} {
 413       set sum1 [db eval { SELECT sum(cnt) FROM t1 }]
 414       set sum2 [db eval { SELECT sum(sum1) FROM t1 }]
 415       db eval { INSERT INTO t1 VALUES($nextwrite, $sum1, $sum2) }
 416       incr nextwrite $E(nthread)
 417       integrity_check
 418     }
 419   }
 420
 421   set {} ok
 422 } -check {
 423   puts "  Final db contains [db eval {SELECT count(*) FROM t1}] rows"
 424   puts "  Final integrity-check says: [db eval {PRAGMA integrity_check}]"
 425
 426   # Check that the contents of the database are Ok.
 427   set c 0
 428   set s1 0
 429   set s2 0
 430   db eval { SELECT cnt, sum1, sum2 FROM t1 ORDER BY cnt } {
 431     if {$c != $cnt || $s1 != $sum1 || $s2 != $sum2} {
 432       error "database content is invalid"
 433     }
 434     incr s2 $s1
 435     incr s1 $c
 436     incr c 1
 437   }
 438 }
 439
 440 do_thread_test2 walthread-4 -seconds $seconds(walthread-4) -init {
 441   execsql {
 442     PRAGMA journal_mode = WAL;
 443     CREATE TABLE t1(a INTEGER PRIMARY KEY, b UNIQUE);
 444   }
 445 } -thread r 1 {
 446   # This connection only ever reads the database. Therefore the
 447   # busy-handler is not required. Disable it to check that this is true.
 448   #
 449   # UPDATE: That is no longer entirely true - as we don't use a blocking
 450   # lock to enter RECOVER state. Which means there is a small chance a
 451   # reader can see an SQLITE_BUSY.
 452   #
 453   while {[tt_continue]} {
 454     integrity_check
 455   }
 456   set {} ok
 457 } -thread w 1 {
 458
 459   proc wal_hook {zDb nEntry} {
 460     if {$nEntry>15} {db eval {PRAGMA wal_checkpoint}}
 461     return 0
 462   }
 463   db wal_hook wal_hook
 464   set row 1
 465   while {[tt_continue]} {
 466     db eval { REPLACE INTO t1 VALUES($row, randomblob(300)) }
 467     incr row
 468     if {$row == 10} { set row 1 }
 469   }
 470
 471   set {} ok
 472 }
 473
 474
 475 # This test case attempts to provoke a deadlock condition that existed in
 476 # the unix VFS at one point. The problem occurred only while recovering a
 477 # very large wal file (one that requires a wal-index larger than the
 478 # initial default allocation of 64KB).
 479 #
 480 do_thread_test walthread-5 -seconds $seconds(walthread-5) -init {
 481
 482   proc log_file_size {nFrame pgsz} {
 483     expr {12 + ($pgsz+16)*$nFrame}
 484   }
 485
 486   execsql {
 487     PRAGMA page_size = 1024;
 488     PRAGMA journal_mode = WAL;
 489     CREATE TABLE t1(x);
 490     BEGIN;
 491       INSERT INTO t1 VALUES(randomblob(900));
 492       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*     2 */
 493       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*     4 */
 494       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*     8 */
 495       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*    16 */
 496       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*    32 */
 497       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*    64 */
 498       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*   128 */
 499       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*   256 */
 500       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*   512 */
 501       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*  1024 */
 502       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*  2048 */
 503       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*  4096 */
 504       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /*  8192 */
 505       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /* 16384 */
 506       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /* 32768 */
 507       INSERT INTO t1 SELECT randomblob(900) FROM t1;      /* 65536 */
 508     COMMIT;
 509   }
 510
 511   forcecopy test.db-wal bak.db-wal
 512   forcecopy test.db bak.db
 513   db close
 514
 515   forcecopy bak.db-wal test.db-wal
 516   forcecopy bak.db test.db
 517
 518   if {[file size test.db-wal] < [log_file_size [expr 64*1024] 1024]} {
 519     error "Somehow failed to create a large log file"
 520   }
 521   puts "Database with large log file recovered. Now running clients..."
 522 } -thread T 5 {
 523   db eval { SELECT count(*) FROM t1 }
 524 }
 525 unset -nocomplain seconds
 526
 527 finish_test