db-derby-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From John English <john.fore...@gmail.com>
Subject Re: Peculiar sorting behaviour?
Date Tue, 02 Apr 2013 18:39:14 GMT
On 02/04/2013 20:05, Katherine Marsden wrote:
> In derby.properties set:
>
> derby.language.logStatementText=true
> derby.language.logQueryPlan=true
>      If you can post  the two plans, someone might be able to give you the
> optimizer overrides to force the plan with incorrect sorting.

Here it is (long!). It starts with the incorrect query; I then change the ORDER 
BY clause and reload the page, which then gives the correct results. There are 
some other queries mixed in, but I wasn't sure what would be relevant so I left 
it uncut.

Tue Apr 02 21:14:23 IDT 2013 Thread[qtp31568925-37,5,main] (XID = 7222148), 
(SESSIONID = 26), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT tests.id,tests.item,title FROM tests,item_usage WHERE 
username=? AND user_role>=3 AND item_usage.item=tests.item ORDER BY 
tests.item,title :End prepared statement with 1 parameters begin parameter #1: 
TAMMY :end parameter
Tue Apr 02 21:14:23 IDT 2013 Thread[qtp31568925-37,5,main] (XID = 7222148), 
(SESSIONID = 26), SELECT tests.id,tests.item,title FROM tests,item_usage WHERE 
username=? AND user_role>=3 AND item_usage.item=tests.item ORDER BY 
tests.item,title ******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 30
Number of reads from hash table = 30
Number of writes to hash table = 30
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 19.34
   optimizer estimated cost: 5186.92
Source result set:
   Project-Restrict ResultSet (7):
   Number of opens = 1
   Rows seen = 30
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 19.34
     optimizer estimated cost: 5186.92
   Source result set:
     Nested Loop Join ResultSet:
     Number of opens = 1
     Rows seen from the left = 5
     Rows seen from the right = 30
     Rows filtered = 0
     Rows returned = 30
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 19.34
       optimizer estimated cost: 5186.92
     Left result set:
       Project-Restrict ResultSet (4):
       Number of opens = 1
       Rows seen = 5
       Rows filtered = 0
       restriction = true
       projection = true
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         restriction time (milliseconds) = 0
         projection time (milliseconds) = 0
         optimizer estimated row count: 1.80
         optimizer estimated cost: 17.01
       Source result set:
         Index Row to Base Row ResultSet for ITEM_USAGE:
         Number of opens = 1
         Rows seen = 5
         Columns accessed from heap = {0, 1, 2}
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           optimizer estimated row count: 1.80
           optimizer estimated cost: 17.01
           Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_1 at 
read uncommitted isolation level using share row locking chosen by the optimizer
           Number of opens = 1
           Rows seen = 5
           Rows filtered = 0
           Fetch Size = 1
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             next time in milliseconds/row = 0

           scan information:
             Bit set of columns fetched=All
             Number of columns fetched=2
             Number of deleted rows visited=0
             Number of pages visited=2
             Number of rows qualified=5
             Number of rows visited=6
             Scan type=btree
             Tree height=2
             start position:
               >= on first 1 column(s).
               Ordered null semantics on the following columns:
             stop position:
               > on first 1 column(s).
               Ordered null semantics on the following columns:
             qualifiers:
               None
             optimizer estimated row count: 1.80
             optimizer estimated cost: 17.01

     Right result set:
       Index Row to Base Row ResultSet for TESTS:
       Number of opens = 5
       Rows seen = 30
       Columns accessed from heap = {0, 1, 2}
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         optimizer estimated row count: 19.34
         optimizer estimated cost: 5169.91
         Index Scan ResultSet for TESTS using constraint TESTS_1 at read 
uncommitted isolation level using share row locking chosen by the optimizer
         Number of opens = 5
         Rows seen = 30
         Rows filtered = 0
         Fetch Size = 1
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           next time in milliseconds/row = 0

         scan information:
           Bit set of columns fetched={0, 2}
           Number of columns fetched=2
           Number of deleted rows visited=9
           Number of pages visited=5
           Number of rows qualified=30
           Number of rows visited=43
           Scan type=btree
           Tree height=1
           start position:
             >= on first 1 column(s).
             Ordered null semantics on the following columns:
             0
           stop position:
             > on first 1 column(s).
             Ordered null semantics on the following columns:
             0
           qualifiers:
             None
           optimizer estimated row count: 19.34
           optimizer estimated cost: 5169.91



Tue Apr 02 21:14:23 IDT 2013 Thread[qtp31568925-37,5,main] (XID = 7222148), 
(SESSIONID = 26), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:23 IDT 2013 Thread[qtp31568925-37,5,main] (XID = 7222148), 
(SESSIONID = 26), (DATABASE = ../db/db_copy), (DRDAID = null), Rolling back
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222149), 
(SESSIONID = 27), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222149), 
(SESSIONID = 27), (DATABASE = ../db/db_copy), (DRDAID = null), Rolling back
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222150), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222151), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT items.item,title,user_role FROM items,item_usage 
WHERE items.item=item_usage.item AND username=? AND user_role>? ORDER BY 
item_usage.item :End prepared statement with 2 parameters begin parameter #1: 
TAMMY :end parameter begin parameter #2: -1 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222151), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222152), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM items WHERE item=? :End prepared statement 
with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222152), 
(SESSIONID = 28), SELECT * FROM items WHERE item=? ******* Scroll Insensitive 
ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.80
Source result set:
   Index Row to Base Row ResultSet for ITEMS:
   Number of opens = 1
   Rows seen = 1
   Columns accessed from heap = {1, 2}
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.80
     Index Scan ResultSet for ITEMS using constraint ITEMS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
     Number of opens = 1
     Rows seen = 1
     Rows filtered = 0
     Fetch Size = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       next time in milliseconds/row = 0

     scan information:
       Bit set of columns fetched=All
       Number of columns fetched=2
       Number of deleted rows visited=0
       Number of pages visited=1
       Number of rows qualified=1
       Number of rows visited=1
       Scan type=btree
       Tree height=1
       start position:
         >= on first 1 column(s).
         Ordered null semantics on the following columns:
       stop position:
         > on first 1 column(s).
         Ordered null semantics on the following columns:
       qualifiers:
         None
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.80


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222152), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222153), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM item_usage WHERE item=? AND user_role>0 :End 
prepared statement with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222153), 
(SESSIONID = 28), SELECT * FROM item_usage WHERE item=? AND user_role>0 ******* 
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 7
Number of reads from hash table = 7
Number of writes to hash table = 7
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 55.77
   optimizer estimated cost: 439.00
Source result set:
   Project-Restrict ResultSet (3):
   Number of opens = 1
   Rows seen = 271
   Rows filtered = 264
   restriction = true
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 55.77
     optimizer estimated cost: 439.00
   Source result set:
     Index Row to Base Row ResultSet for ITEM_USAGE:
     Number of opens = 1
     Rows seen = 271
     Columns accessed from heap = {0, 1, 2}
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 55.77
       optimizer estimated cost: 439.00
       Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
       Number of opens = 1
       Rows seen = 271
       Rows filtered = 0
       Fetch Size = 16
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         next time in milliseconds/row = 0

       scan information:
         Bit set of columns fetched=All
         Number of columns fetched=2
         Number of deleted rows visited=2
         Number of pages visited=4
         Number of rows qualified=271
         Number of rows visited=274
         Scan type=btree
         Tree height=2
         start position:
           >= on first 1 column(s).
           Ordered null semantics on the following columns:
         stop position:
           > on first 1 column(s).
           Ordered null semantics on the following columns:
         qualifiers:
           None
         optimizer estimated row count: 55.77
         optimizer estimated cost: 439.00


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222153), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222154), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM items WHERE item=? :End prepared statement 
with 1 parameters begin parameter #1: 61108 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222154), 
(SESSIONID = 28), SELECT * FROM items WHERE item=? ******* Scroll Insensitive 
ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.80
Source result set:
   Index Row to Base Row ResultSet for ITEMS:
   Number of opens = 1
   Rows seen = 1
   Columns accessed from heap = {1, 2}
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.80
     Index Scan ResultSet for ITEMS using constraint ITEMS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
     Number of opens = 1
     Rows seen = 1
     Rows filtered = 0
     Fetch Size = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       next time in milliseconds/row = 0

     scan information:
       Bit set of columns fetched=All
       Number of columns fetched=2
       Number of deleted rows visited=0
       Number of pages visited=1
       Number of rows qualified=1
       Number of rows visited=1
       Scan type=btree
       Tree height=1
       start position:
         >= on first 1 column(s).
         Ordered null semantics on the following columns:
       stop position:
         > on first 1 column(s).
         Ordered null semantics on the following columns:
       qualifiers:
         None
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.80


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222154), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222155), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM item_usage WHERE item=? AND user_role>0 :End 
prepared statement with 1 parameters begin parameter #1: 61108 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222155), 
(SESSIONID = 28), SELECT * FROM item_usage WHERE item=? AND user_role>0 ******* 
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 55.77
   optimizer estimated cost: 439.00
Source result set:
   Project-Restrict ResultSet (3):
   Number of opens = 1
   Rows seen = 1
   Rows filtered = 0
   restriction = true
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 55.77
     optimizer estimated cost: 439.00
   Source result set:
     Index Row to Base Row ResultSet for ITEM_USAGE:
     Number of opens = 1
     Rows seen = 1
     Columns accessed from heap = {0, 1, 2}
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 55.77
       optimizer estimated cost: 439.00
       Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
       Number of opens = 1
       Rows seen = 1
       Rows filtered = 0
       Fetch Size = 16
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         next time in milliseconds/row = 0

       scan information:
         Bit set of columns fetched=All
         Number of columns fetched=2
         Number of deleted rows visited=0
         Number of pages visited=2
         Number of rows qualified=1
         Number of rows visited=2
         Scan type=btree
         Tree height=2
         start position:
           >= on first 1 column(s).
           Ordered null semantics on the following columns:
         stop position:
           > on first 1 column(s).
           Ordered null semantics on the following columns:
         qualifiers:
           None
         optimizer estimated row count: 55.77
         optimizer estimated cost: 439.00


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222155), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222156), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM items WHERE item=? :End prepared statement 
with 1 parameters begin parameter #1: 61303 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222156), 
(SESSIONID = 28), SELECT * FROM items WHERE item=? ******* Scroll Insensitive 
ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.80
Source result set:
   Index Row to Base Row ResultSet for ITEMS:
   Number of opens = 1
   Rows seen = 1
   Columns accessed from heap = {1, 2}
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.80
     Index Scan ResultSet for ITEMS using constraint ITEMS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
     Number of opens = 1
     Rows seen = 1
     Rows filtered = 0
     Fetch Size = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       next time in milliseconds/row = 0

     scan information:
       Bit set of columns fetched=All
       Number of columns fetched=2
       Number of deleted rows visited=0
       Number of pages visited=1
       Number of rows qualified=1
       Number of rows visited=1
       Scan type=btree
       Tree height=1
       start position:
         >= on first 1 column(s).
         Ordered null semantics on the following columns:
       stop position:
         > on first 1 column(s).
         Ordered null semantics on the following columns:
       qualifiers:
         None
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.80


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222156), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222157), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM item_usage WHERE item=? AND user_role>0 :End 
prepared statement with 1 parameters begin parameter #1: 61303 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222157), 
(SESSIONID = 28), SELECT * FROM item_usage WHERE item=? AND user_role>0 ******* 
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 3
Number of reads from hash table = 3
Number of writes to hash table = 3
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 55.77
   optimizer estimated cost: 439.00
Source result set:
   Project-Restrict ResultSet (3):
   Number of opens = 1
   Rows seen = 146
   Rows filtered = 143
   restriction = true
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 55.77
     optimizer estimated cost: 439.00
   Source result set:
     Index Row to Base Row ResultSet for ITEM_USAGE:
     Number of opens = 1
     Rows seen = 146
     Columns accessed from heap = {0, 1, 2}
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 55.77
       optimizer estimated cost: 439.00
       Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
       Number of opens = 1
       Rows seen = 146
       Rows filtered = 0
       Fetch Size = 16
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         next time in milliseconds/row = 0

       scan information:
         Bit set of columns fetched=All
         Number of columns fetched=2
         Number of deleted rows visited=0
         Number of pages visited=4
         Number of rows qualified=146
         Number of rows visited=147
         Scan type=btree
         Tree height=2
         start position:
           >= on first 1 column(s).
           Ordered null semantics on the following columns:
         stop position:
           > on first 1 column(s).
           Ordered null semantics on the following columns:
         qualifiers:
           None
         optimizer estimated row count: 55.77
         optimizer estimated cost: 439.00


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222157), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222158), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM items WHERE item=? :End prepared statement 
with 1 parameters begin parameter #1: 7205731 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222158), 
(SESSIONID = 28), SELECT * FROM items WHERE item=? ******* Scroll Insensitive 
ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.80
Source result set:
   Index Row to Base Row ResultSet for ITEMS:
   Number of opens = 1
   Rows seen = 1
   Columns accessed from heap = {1, 2}
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.80
     Index Scan ResultSet for ITEMS using constraint ITEMS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
     Number of opens = 1
     Rows seen = 1
     Rows filtered = 0
     Fetch Size = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       next time in milliseconds/row = 0

     scan information:
       Bit set of columns fetched=All
       Number of columns fetched=2
       Number of deleted rows visited=0
       Number of pages visited=1
       Number of rows qualified=1
       Number of rows visited=1
       Scan type=btree
       Tree height=1
       start position:
         >= on first 1 column(s).
         Ordered null semantics on the following columns:
       stop position:
         > on first 1 column(s).
         Ordered null semantics on the following columns:
       qualifiers:
         None
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.80


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222158), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222159), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM item_usage WHERE item=? AND user_role>0 :End 
prepared statement with 1 parameters begin parameter #1: 7205731 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222159), 
(SESSIONID = 28), SELECT * FROM item_usage WHERE item=? AND user_role>0 ******* 
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 2
Number of reads from hash table = 2
Number of writes to hash table = 2
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 55.77
   optimizer estimated cost: 439.00
Source result set:
   Project-Restrict ResultSet (3):
   Number of opens = 1
   Rows seen = 28
   Rows filtered = 26
   restriction = true
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 55.77
     optimizer estimated cost: 439.00
   Source result set:
     Index Row to Base Row ResultSet for ITEM_USAGE:
     Number of opens = 1
     Rows seen = 28
     Columns accessed from heap = {0, 1, 2}
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 55.77
       optimizer estimated cost: 439.00
       Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
       Number of opens = 1
       Rows seen = 28
       Rows filtered = 0
       Fetch Size = 16
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         next time in milliseconds/row = 0

       scan information:
         Bit set of columns fetched=All
         Number of columns fetched=2
         Number of deleted rows visited=1
         Number of pages visited=2
         Number of rows qualified=28
         Number of rows visited=30
         Scan type=btree
         Tree height=2
         start position:
           >= on first 1 column(s).
           Ordered null semantics on the following columns:
         stop position:
           > on first 1 column(s).
           Ordered null semantics on the following columns:
         qualifiers:
           None
         optimizer estimated row count: 55.77
         optimizer estimated cost: 439.00


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222159), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222160), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM items WHERE item=? :End prepared statement 
with 1 parameters begin parameter #1: XY101 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222160), 
(SESSIONID = 28), SELECT * FROM items WHERE item=? ******* Scroll Insensitive 
ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.80
Source result set:
   Index Row to Base Row ResultSet for ITEMS:
   Number of opens = 1
   Rows seen = 1
   Columns accessed from heap = {1, 2}
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.80
     Index Scan ResultSet for ITEMS using constraint ITEMS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
     Number of opens = 1
     Rows seen = 1
     Rows filtered = 0
     Fetch Size = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       next time in milliseconds/row = 0

     scan information:
       Bit set of columns fetched=All
       Number of columns fetched=2
       Number of deleted rows visited=0
       Number of pages visited=1
       Number of rows qualified=1
       Number of rows visited=1
       Scan type=btree
       Tree height=1
       start position:
         >= on first 1 column(s).
         Ordered null semantics on the following columns:
       stop position:
         > on first 1 column(s).
         Ordered null semantics on the following columns:
       qualifiers:
         None
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.80


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222160), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222161), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM item_usage WHERE item=? AND user_role>0 :End 
prepared statement with 1 parameters begin parameter #1: XY101 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222161), 
(SESSIONID = 28), SELECT * FROM item_usage WHERE item=? AND user_role>0 ******* 
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 2
Number of reads from hash table = 2
Number of writes to hash table = 2
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 55.77
   optimizer estimated cost: 439.00
Source result set:
   Project-Restrict ResultSet (3):
   Number of opens = 1
   Rows seen = 3
   Rows filtered = 1
   restriction = true
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 55.77
     optimizer estimated cost: 439.00
   Source result set:
     Index Row to Base Row ResultSet for ITEM_USAGE:
     Number of opens = 1
     Rows seen = 3
     Columns accessed from heap = {0, 1, 2}
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 55.77
       optimizer estimated cost: 439.00
       Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
       Number of opens = 1
       Rows seen = 3
       Rows filtered = 0
       Fetch Size = 16
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         next time in milliseconds/row = 0

       scan information:
         Bit set of columns fetched=All
         Number of columns fetched=2
         Number of deleted rows visited=2
         Number of pages visited=2
         Number of rows qualified=3
         Number of rows visited=5
         Scan type=btree
         Tree height=2
         start position:
           >= on first 1 column(s).
           Ordered null semantics on the following columns:
         stop position:
           > on first 1 column(s).
           Ordered null semantics on the following columns:
         qualifiers:
           None
         optimizer estimated row count: 55.77
         optimizer estimated cost: 439.00


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222161), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222161), 
(SESSIONID = 28), SELECT items.item,title,user_role FROM items,item_usage WHERE 
items.item=item_usage.item AND username=? AND user_role>? ORDER BY 
item_usage.item ******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 5
Number of reads from hash table = 5
Number of writes to hash table = 5
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.80
   optimizer estimated cost: 27.45
Source result set:
   Project-Restrict ResultSet (9):
   Number of opens = 1
   Rows seen = 5
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.80
     optimizer estimated cost: 27.45
   Source result set:
     Sort ResultSet:
     Number of opens = 1
     Rows input = 5
     Rows returned = 5
     Eliminate duplicates = false
     In sorted order = false
     Sort information:
       Number of rows input=5
       Number of rows output=5
       Sort type=internal
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 1.80
       optimizer estimated cost: 27.45
     Source result set:
       Project-Restrict ResultSet (7):
       Number of opens = 1
       Rows seen = 5
       Rows filtered = 0
       restriction = false
       projection = true
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         restriction time (milliseconds) = 0
         projection time (milliseconds) = 0
         optimizer estimated row count: 1.80
         optimizer estimated cost: 27.45
       Source result set:
         Nested Loop Exists Join ResultSet:
         Number of opens = 1
         Rows seen from the left = 5
         Rows seen from the right = 5
         Rows filtered = 0
         Rows returned = 5
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           optimizer estimated row count: 1.80
           optimizer estimated cost: 27.45
         Left result set:
           Project-Restrict ResultSet (4):
           Number of opens = 1
           Rows seen = 5
           Rows filtered = 0
           restriction = true
           projection = true
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             restriction time (milliseconds) = 0
             projection time (milliseconds) = 0
             optimizer estimated row count: 1.80
             optimizer estimated cost: 17.01
           Source result set:
             Index Row to Base Row ResultSet for ITEM_USAGE:
             Number of opens = 1
             Rows seen = 5
             Columns accessed from heap = {0, 1, 2}
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0
               optimizer estimated row count: 1.80
               optimizer estimated cost: 17.01
               Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_1 
at read uncommitted isolation level using share row locking chosen by the optimizer
               Number of opens = 1
               Rows seen = 5
               Rows filtered = 0
               Fetch Size = 16
                 constructor time (milliseconds) = 0
                 open time (milliseconds) = 0
                 next time (milliseconds) = 0
                 close time (milliseconds) = 0
                 next time in milliseconds/row = 0

               scan information:
                 Bit set of columns fetched=All
                 Number of columns fetched=2
                 Number of deleted rows visited=0
                 Number of pages visited=2
                 Number of rows qualified=5
                 Number of rows visited=6
                 Scan type=btree
                 Tree height=2
                 start position:
                   >= on first 1 column(s).
                   Ordered null semantics on the following columns:
                 stop position:
                   > on first 1 column(s).
                   Ordered null semantics on the following columns:
                 qualifiers:
                   None
                 optimizer estimated row count: 1.80
                 optimizer estimated cost: 17.01

         Right result set:
           Index Row to Base Row ResultSet for ITEMS:
           Number of opens = 5
           Rows seen = 5
           Columns accessed from heap = {1}
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             optimizer estimated row count: 1.80
             optimizer estimated cost: 10.43
             Index Scan ResultSet for ITEMS using constraint ITEMS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
             Number of opens = 5
             Rows seen = 5
             Rows filtered = 0
             Fetch Size = 1
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0
               next time in milliseconds/row = 0

             scan information:
               Bit set of columns fetched=All
               Number of columns fetched=2
               Number of deleted rows visited=0
               Number of pages visited=5
               Number of rows qualified=5
               Number of rows visited=5
               Scan type=btree
               Tree height=1
               start position:
                 >= on first 1 column(s).
                 Ordered null semantics on the following columns:
                 0
               stop position:
                 > on first 1 column(s).
                 Ordered null semantics on the following columns:
                 0
               qualifiers:
                 None
               optimizer estimated row count: 1.80
               optimizer estimated cost: 10.43




Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222161), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222162), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM items WHERE item=? :End prepared statement 
with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222162), 
(SESSIONID = 28), SELECT * FROM items WHERE item=? ******* Scroll Insensitive 
ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.80
Source result set:
   Index Row to Base Row ResultSet for ITEMS:
   Number of opens = 1
   Rows seen = 1
   Columns accessed from heap = {1, 2}
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.80
     Index Scan ResultSet for ITEMS using constraint ITEMS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
     Number of opens = 1
     Rows seen = 1
     Rows filtered = 0
     Fetch Size = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       next time in milliseconds/row = 0

     scan information:
       Bit set of columns fetched=All
       Number of columns fetched=2
       Number of deleted rows visited=0
       Number of pages visited=1
       Number of rows qualified=1
       Number of rows visited=1
       Scan type=btree
       Tree height=1
       start position:
         >= on first 1 column(s).
         Ordered null semantics on the following columns:
       stop position:
         > on first 1 column(s).
         Ordered null semantics on the following columns:
       qualifiers:
         None
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.80


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222162), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222163), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM item_usage WHERE item=? AND user_role>0 :End 
prepared statement with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222163), 
(SESSIONID = 28), SELECT * FROM item_usage WHERE item=? AND user_role>0 ******* 
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 7
Number of reads from hash table = 7
Number of writes to hash table = 7
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 55.77
   optimizer estimated cost: 439.00
Source result set:
   Project-Restrict ResultSet (3):
   Number of opens = 1
   Rows seen = 271
   Rows filtered = 264
   restriction = true
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 55.77
     optimizer estimated cost: 439.00
   Source result set:
     Index Row to Base Row ResultSet for ITEM_USAGE:
     Number of opens = 1
     Rows seen = 271
     Columns accessed from heap = {0, 1, 2}
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 55.77
       optimizer estimated cost: 439.00
       Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
       Number of opens = 1
       Rows seen = 271
       Rows filtered = 0
       Fetch Size = 16
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         next time in milliseconds/row = 0

       scan information:
         Bit set of columns fetched=All
         Number of columns fetched=2
         Number of deleted rows visited=2
         Number of pages visited=4
         Number of rows qualified=271
         Number of rows visited=274
         Scan type=btree
         Tree height=2
         start position:
           >= on first 1 column(s).
           Ordered null semantics on the following columns:
         stop position:
           > on first 1 column(s).
           Ordered null semantics on the following columns:
         qualifiers:
           None
         optimizer estimated row count: 55.77
         optimizer estimated cost: 439.00


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222163), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222164), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM item_usage WHERE item=? AND username=? :End 
prepared statement with 2 parameters begin parameter #1: 60001 :end parameter 
begin parameter #2: TAMMY :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222164), 
(SESSIONID = 28), SELECT * FROM item_usage WHERE item=? AND username=? ******* 
Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.36
Source result set:
   Index Row to Base Row ResultSet for ITEM_USAGE:
   Number of opens = 1
   Rows seen = 1
   Columns accessed from heap = {2}
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.36
     Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
     Number of opens = 1
     Rows seen = 1
     Rows filtered = 0
     Fetch Size = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       next time in milliseconds/row = 0

     scan information:
       Bit set of columns fetched=All
       Number of columns fetched=3
       Number of deleted rows visited=0
       Number of pages visited=2
       Number of rows qualified=1
       Number of rows visited=1
       Scan type=btree
       Tree height=2
       start position:
         >= on first 2 column(s).
         Ordered null semantics on the following columns:
       stop position:
         > on first 2 column(s).
         Ordered null semantics on the following columns:
       qualifiers:
         None
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.36


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222164), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222165), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT item FROM item_usage WHERE username=? AND user_role>0 
ORDER BY item :End prepared statement with 1 parameters begin parameter #1: 
TAMMY :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222165), 
(SESSIONID = 28), SELECT item FROM item_usage WHERE username=? AND user_role>0 
ORDER BY item ******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 5
Number of reads from hash table = 5
Number of writes to hash table = 5
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.80
   optimizer estimated cost: 17.20
Source result set:
   Project-Restrict ResultSet (4):
   Number of opens = 1
   Rows seen = 5
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.80
     optimizer estimated cost: 17.20
   Source result set:
     Project-Restrict ResultSet (3):
     Number of opens = 1
     Rows seen = 5
     Rows filtered = 0
     restriction = true
     projection = true
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       restriction time (milliseconds) = 0
       projection time (milliseconds) = 0
       optimizer estimated row count: 1.80
       optimizer estimated cost: 17.20
     Source result set:
       Index Row to Base Row ResultSet for ITEM_USAGE:
       Number of opens = 1
       Rows seen = 5
       Columns accessed from heap = {0, 1, 2}
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         optimizer estimated row count: 1.80
         optimizer estimated cost: 17.20
         Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_PK at 
read uncommitted isolation level using share row locking chosen by the optimizer
         Number of opens = 1
         Rows seen = 5
         Rows filtered = 0
         Fetch Size = 1
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           next time in milliseconds/row = 0

         scan information:
           Bit set of columns fetched={0, 2}
           Number of columns fetched=2
           Number of deleted rows visited=2
           Number of pages visited=2
           Number of rows qualified=5
           Number of rows visited=8
           Scan type=btree
           Tree height=2
           start position:
             >= on first 1 column(s).
             Ordered null semantics on the following columns:
           stop position:
             > on first 1 column(s).
             Ordered null semantics on the following columns:
           qualifiers:
             None
           optimizer estimated row count: 1.80
           optimizer estimated cost: 17.20


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222165), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222166), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT * FROM users WHERE username=? AND manager IS NOT NULL 
:End prepared statement with 1 parameters begin parameter #1: TAMMY :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222166), 
(SESSIONID = 28), SELECT * FROM users WHERE username=? AND manager IS NOT NULL 
******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 5.59
Source result set:
   Project-Restrict ResultSet (3):
   Number of opens = 1
   Rows seen = 1
   Rows filtered = 0
   restriction = true
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 5.59
   Source result set:
     Index Row to Base Row ResultSet for USERS:
     Number of opens = 1
     Rows seen = 1
     Columns accessed from heap = {1, 2, 3, 4, 5, 6, 7, 8, 9, 10}
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 1.00
       optimizer estimated cost: 5.59
       Index Scan ResultSet for USERS using constraint USERS_PK at read 
uncommitted isolation level using share row locking chosen by the optimizer
       Number of opens = 1
       Rows seen = 1
       Rows filtered = 0
       Fetch Size = 1
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         next time in milliseconds/row = 0

       scan information:
         Bit set of columns fetched=All
         Number of columns fetched=2
         Number of deleted rows visited=0
         Number of pages visited=2
         Number of rows qualified=1
         Number of rows visited=1
         Scan type=btree
         Tree height=2
         start position:
           >= on first 1 column(s).
           Ordered null semantics on the following columns:
         stop position:
           > on first 1 column(s).
           Ordered null semantics on the following columns:
         qualifiers:
           None
         optimizer estimated row count: 1.00
         optimizer estimated cost: 5.59


Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222166), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222167), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT count(*) AS msgs FROM messages WHERE item IS NULL AND 
id>? :End prepared statement with 1 parameters begin parameter #1: 1 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222167), 
(SESSIONID = 28), SELECT count(*) AS msgs FROM messages WHERE item IS NULL AND 
id>? ******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 1.57
Source result set:
   Project-Restrict ResultSet (6):
   Number of opens = 1
   Rows seen = 1
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 1.57
   Source result set:
     Scalar Aggregate ResultSet:
     Number of opens = 1
     Rows input = 0
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 0.00
       optimizer estimated cost: 1.57
     Index Key Optimization = false
     Source result set:
       Project-Restrict ResultSet (5):
       Number of opens = 1
       Rows seen = 0
       Rows filtered = 0
       restriction = false
       projection = true
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         restriction time (milliseconds) = 0
         projection time (milliseconds) = 0
         optimizer estimated row count: 0.00
         optimizer estimated cost: 1.57
       Source result set:
         Project-Restrict ResultSet (4):
         Number of opens = 1
         Rows seen = 0
         Rows filtered = 0
         restriction = true
         projection = true
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           restriction time (milliseconds) = 0
           projection time (milliseconds) = 0
           optimizer estimated row count: 0.00
           optimizer estimated cost: 1.57
         Source result set:
           Index Row to Base Row ResultSet for MESSAGES:
           Number of opens = 1
           Rows seen = 0
           Columns accessed from heap = {0, 1}
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             optimizer estimated row count: 0.00
             optimizer estimated cost: 1.57
             Index Scan ResultSet for MESSAGES using constraint MESSAGES_1 at 
read uncommitted isolation level using share row locking chosen by the optimizer
             Number of opens = 1
             Rows seen = 0
             Rows filtered = 0
             Fetch Size = 16
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0

             scan information:
               Bit set of columns fetched=All
               Number of columns fetched=2
               Number of deleted rows visited=0
               Number of pages visited=1
               Number of rows qualified=0
               Number of rows visited=0
               Scan type=btree
               Tree height=1
               start position:
                 >= on first 1 column(s).
                 Ordered null semantics on the following columns:
                 0
               stop position:
                 > on first 1 column(s).
                 Ordered null semantics on the following columns:
                 0
               qualifiers:
                 None
               optimizer estimated row count: 0.00
               optimizer estimated cost: 1.57



Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222167), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222168), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT count(*) AS msgs FROM messages WHERE item=? AND id>? 
:End prepared statement with 2 parameters begin parameter #1: 60001 :end 
parameter begin parameter #2: 1 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222168), 
(SESSIONID = 28), SELECT count(*) AS msgs FROM messages WHERE item=? AND id>? 
******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 83.86
Source result set:
   Project-Restrict ResultSet (6):
   Number of opens = 1
   Rows seen = 1
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 83.86
   Source result set:
     Scalar Aggregate ResultSet:
     Number of opens = 1
     Rows input = 0
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 0.20
       optimizer estimated cost: 83.86
     Index Key Optimization = false
     Source result set:
       Project-Restrict ResultSet (5):
       Number of opens = 1
       Rows seen = 0
       Rows filtered = 0
       restriction = false
       projection = true
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         restriction time (milliseconds) = 0
         projection time (milliseconds) = 0
         optimizer estimated row count: 0.20
         optimizer estimated cost: 83.86
       Source result set:
         Project-Restrict ResultSet (4):
         Number of opens = 1
         Rows seen = 0
         Rows filtered = 0
         restriction = true
         projection = true
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           restriction time (milliseconds) = 0
           projection time (milliseconds) = 0
           optimizer estimated row count: 0.20
           optimizer estimated cost: 83.86
         Source result set:
           Index Row to Base Row ResultSet for MESSAGES:
           Number of opens = 1
           Rows seen = 0
           Columns accessed from heap = {0, 1}
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             optimizer estimated row count: 0.20
             optimizer estimated cost: 83.86
             Index Scan ResultSet for MESSAGES using constraint MESSAGES_1 at 
read uncommitted isolation level using share row locking chosen by the optimizer
             Number of opens = 1
             Rows seen = 0
             Rows filtered = 0
             Fetch Size = 16
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0

             scan information:
               Bit set of columns fetched=All
               Number of columns fetched=2
               Number of deleted rows visited=1
               Number of pages visited=1
               Number of rows qualified=0
               Number of rows visited=1
               Scan type=btree
               Tree height=1
               start position:
                 >= on first 1 column(s).
                 Ordered null semantics on the following columns:
               stop position:
                 > on first 1 column(s).
                 Ordered null semantics on the following columns:
               qualifiers:
                 None
               optimizer estimated row count: 0.20
               optimizer estimated cost: 83.86



Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222168), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222169), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT COUNT(*) FROM edits_view WHERE item=? :End prepared 
statement with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222169), 
(SESSIONID = 28), SELECT COUNT(*) FROM edits_view WHERE item=? ******* Scroll 
Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 1001.34
Source result set:
   Project-Restrict ResultSet (5):
   Number of opens = 1
   Rows seen = 1
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 1001.34
   Source result set:
     Scalar Aggregate ResultSet:
     Number of opens = 1
     Rows input = 4
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 4.10
       optimizer estimated cost: 1001.34
     Index Key Optimization = false
     Source result set:
       Project-Restrict ResultSet (4):
       Number of opens = 1
       Rows seen = 4
       Rows filtered = 0
       restriction = false
       projection = true
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         restriction time (milliseconds) = 0
         projection time (milliseconds) = 0
         optimizer estimated row count: 4.10
         optimizer estimated cost: 1001.34
       Source result set:
         Index Row to Base Row ResultSet for XMLTEMP:
         Number of opens = 1
         Rows seen = 4
         Columns accessed from heap = {0, 1, 5}
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           optimizer estimated row count: 4.10
           optimizer estimated cost: 1001.34
           Index Scan ResultSet for XMLTEMP using constraint XMLTEMP_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
           Number of opens = 1
           Rows seen = 4
           Rows filtered = 0
           Fetch Size = 1
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             next time in milliseconds/row = 0

           scan information:
             Bit set of columns fetched=All
             Number of columns fetched=3
             Number of deleted rows visited=6
             Number of pages visited=1
             Number of rows qualified=4
             Number of rows visited=11
             Scan type=btree
             Tree height=1
             start position:
               >= on first 1 column(s).
               Ordered null semantics on the following columns:
             stop position:
               > on first 1 column(s).
               Ordered null semantics on the following columns:
             qualifiers:
               None
             optimizer estimated row count: 4.10
             optimizer estimated cost: 1001.34



Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222169), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222170), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT title,DateTimeFormat(t_time,null) AS 
t_time,username,link FROM edits_view WHERE item=? ORDER BY username ASC,1 ASC 
:End prepared statement with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222170), 
(SESSIONID = 28), SELECT title,DateTimeFormat(t_time,null) AS 
t_time,username,link FROM edits_view WHERE item=? ORDER BY username ASC,1 ASC 
******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 4
Number of reads from hash table = 4
Number of writes to hash table = 4
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 4.10
   optimizer estimated cost: 1001.34
Source result set:
   Sort ResultSet:
   Number of opens = 1
   Rows input = 4
   Rows returned = 4
   Eliminate duplicates = false
   In sorted order = false
   Sort information:
     Number of rows input=4
     Number of rows output=4
     Sort type=internal
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 4.10
     optimizer estimated cost: 1001.34
   Source result set:
     Project-Restrict ResultSet (3):
     Number of opens = 1
     Rows seen = 4
     Rows filtered = 0
     restriction = false
     projection = true
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       restriction time (milliseconds) = 0
       projection time (milliseconds) = 0
       optimizer estimated row count: 4.10
       optimizer estimated cost: 1001.34
     Source result set:
       Index Row to Base Row ResultSet for XMLTEMP:
       Number of opens = 1
       Rows seen = 4
       Columns accessed from heap = {0, 1, 5}
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         optimizer estimated row count: 4.10
         optimizer estimated cost: 1001.34
         Index Scan ResultSet for XMLTEMP using constraint XMLTEMP_2 at read 
uncommitted isolation level using share row locking chosen by the optimizer
         Number of opens = 1
         Rows seen = 4
         Rows filtered = 0
         Fetch Size = 1
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           next time in milliseconds/row = 0

         scan information:
           Bit set of columns fetched=All
           Number of columns fetched=3
           Number of deleted rows visited=6
           Number of pages visited=1
           Number of rows qualified=4
           Number of rows visited=11
           Scan type=btree
           Tree height=1
           start position:
             >= on first 1 column(s).
             Ordered null semantics on the following columns:
           stop position:
             > on first 1 column(s).
             Ordered null semantics on the following columns:
           qualifiers:
             None
           optimizer estimated row count: 4.10
           optimizer estimated cost: 1001.34



Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222170), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222171), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT COUNT(*) FROM tests_view WHERE item=? :End prepared 
statement with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222171), 
(SESSIONID = 28), SELECT COUNT(*) FROM tests_view WHERE item=? ******* Scroll 
Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.00
   optimizer estimated cost: 2873.71
Source result set:
   Project-Restrict ResultSet (8):
   Number of opens = 1
   Rows seen = 1
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.00
     optimizer estimated cost: 2873.71
   Source result set:
     Scalar Aggregate ResultSet:
     Number of opens = 1
     Rows input = 1
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 10.75
       optimizer estimated cost: 2873.71
     Index Key Optimization = false
     Source result set:
       Attached subqueries:
         Begin Subquery Number 0
         Any ResultSet  (Attached to 4):
         Number of opens = 5
         Rows seen = 5
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           optimizer estimated row count: 36.00
           optimizer estimated cost: 23.54
         Source result set:
           Project-Restrict ResultSet (6):
           Number of opens = 5
           Rows seen = 40
           Rows filtered = 36
           restriction = true
           projection = true
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             restriction time (milliseconds) = 0
             projection time (milliseconds) = 0
             optimizer estimated row count: 36.00
             optimizer estimated cost: 23.54
           Source result set:
             Union ResultSet:
             Number of opens = 5
             Rows seen from the left = 39
             Rows seen from the right = 1
             Rows returned = 40
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0
               optimizer estimated row count: 11.00
               optimizer estimated cost: 0.00
             Left result set:
               Union ResultSet:
               Number of opens = 5
               Rows seen from the left = 38
               Rows seen from the right = 1
               Rows returned = 39
                 constructor time (milliseconds) = 0
                 open time (milliseconds) = 0
                 next time (milliseconds) = 0
                 close time (milliseconds) = 0
                 optimizer estimated row count: 10.00
                 optimizer estimated cost: 0.00
               Left result set:
                 Union ResultSet:
                 Number of opens = 5
                 Rows seen from the left = 36
                 Rows seen from the right = 2
                 Rows returned = 38
                   constructor time (milliseconds) = 0
                   open time (milliseconds) = 0
                   next time (milliseconds) = 0
                   close time (milliseconds) = 0
                   optimizer estimated row count: 9.00
                   optimizer estimated cost: 0.00
                 Left result set:
                   Union ResultSet:
                   Number of opens = 5
                   Rows seen from the left = 33
                   Rows seen from the right = 3
                   Rows returned = 36
                     constructor time (milliseconds) = 0
                     open time (milliseconds) = 0
                     next time (milliseconds) = 0
                     close time (milliseconds) = 0
                     optimizer estimated row count: 8.00
                     optimizer estimated cost: 0.00
                   Left result set:
                     Union ResultSet:
                     Number of opens = 5
                     Rows seen from the left = 29
                     Rows seen from the right = 4
                     Rows returned = 33
                       constructor time (milliseconds) = 0
                       open time (milliseconds) = 0
                       next time (milliseconds) = 0
                       close time (milliseconds) = 0
                       optimizer estimated row count: 7.00
                       optimizer estimated cost: 0.00
                     Left result set:
                       Union ResultSet:
                       Number of opens = 5
                       Rows seen from the left = 25
                       Rows seen from the right = 4
                       Rows returned = 29
                         constructor time (milliseconds) = 0
                         open time (milliseconds) = 0
                         next time (milliseconds) = 0
                         close time (milliseconds) = 0
                         optimizer estimated row count: 6.00
                         optimizer estimated cost: 0.00
                       Left result set:
                         Union ResultSet:
                         Number of opens = 5
                         Rows seen from the left = 20
                         Rows seen from the right = 5
                         Rows returned = 25
                           constructor time (milliseconds) = 0
                           open time (milliseconds) = 0
                           next time (milliseconds) = 0
                           close time (milliseconds) = 0
                           optimizer estimated row count: 5.00
                           optimizer estimated cost: 0.00
                         Left result set:
                           Union ResultSet:
                           Number of opens = 5
                           Rows seen from the left = 15
                           Rows seen from the right = 5
                           Rows returned = 20
                             constructor time (milliseconds) = 0
                             open time (milliseconds) = 0
                             next time (milliseconds) = 0
                             close time (milliseconds) = 0
                             optimizer estimated row count: 4.00
                             optimizer estimated cost: 0.00
                           Left result set:
                             Union ResultSet:
                             Number of opens = 5
                             Rows seen from the left = 10
                             Rows seen from the right = 5
                             Rows returned = 15
                               constructor time (milliseconds) = 0
                               open time (milliseconds) = 0
                               next time (milliseconds) = 0
                               close time (milliseconds) = 0
                               optimizer estimated row count: 3.00
                               optimizer estimated cost: 0.00
                             Left result set:
                               Union ResultSet:
                               Number of opens = 5
                               Rows seen from the left = 5
                               Rows seen from the right = 5
                               Rows returned = 10
                                 constructor time (milliseconds) = 0
                                 open time (milliseconds) = 0
                                 next time (milliseconds) = 0
                                 close time (milliseconds) = 0
                                 optimizer estimated row count: 2.00
                                 optimizer estimated cost: 0.00
                               Left result set:
                                 Row ResultSet:
                                 Number of opens = 5
                                 Rows returned = 5
                                   constructor time (milliseconds) = 0
                                   open time (milliseconds) = 0
                                   next time (milliseconds) = 0
                                   close time (milliseconds) = 0
                                   optimizer estimated row count: 1.00
                                   optimizer estimated cost: 0.00

                               Right result set:
                                 Row ResultSet:
                                 Number of opens = 5
                                 Rows returned = 5
                                   constructor time (milliseconds) = 0
                                   open time (milliseconds) = 0
                                   next time (milliseconds) = 0
                                   close time (milliseconds) = 0
                                   optimizer estimated row count: 1.00
                                   optimizer estimated cost: 0.00


                             Right result set:
                               Row ResultSet:
                               Number of opens = 5
                               Rows returned = 5
                                 constructor time (milliseconds) = 0
                                 open time (milliseconds) = 0
                                 next time (milliseconds) = 0
                                 close time (milliseconds) = 0
                                 optimizer estimated row count: 1.00
                                 optimizer estimated cost: 0.00


                           Right result set:
                             Row ResultSet:
                             Number of opens = 5
                             Rows returned = 5
                               constructor time (milliseconds) = 0
                               open time (milliseconds) = 0
                               next time (milliseconds) = 0
                               close time (milliseconds) = 0
                               optimizer estimated row count: 1.00
                               optimizer estimated cost: 0.00


                         Right result set:
                           Row ResultSet:
                           Number of opens = 5
                           Rows returned = 5
                             constructor time (milliseconds) = 0
                             open time (milliseconds) = 0
                             next time (milliseconds) = 0
                             close time (milliseconds) = 0
                             optimizer estimated row count: 1.00
                             optimizer estimated cost: 0.00


                       Right result set:
                         Row ResultSet:
                         Number of opens = 4
                         Rows returned = 4
                           constructor time (milliseconds) = 0
                           open time (milliseconds) = 0
                           next time (milliseconds) = 0
                           close time (milliseconds) = 0
                           optimizer estimated row count: 1.00
                           optimizer estimated cost: 0.00


                     Right result set:
                       Row ResultSet:
                       Number of opens = 4
                       Rows returned = 4
                         constructor time (milliseconds) = 0
                         open time (milliseconds) = 0
                         next time (milliseconds) = 0
                         close time (milliseconds) = 0
                         optimizer estimated row count: 1.00
                         optimizer estimated cost: 0.00


                   Right result set:
                     Row ResultSet:
                     Number of opens = 3
                     Rows returned = 3
                       constructor time (milliseconds) = 0
                       open time (milliseconds) = 0
                       next time (milliseconds) = 0
                       close time (milliseconds) = 0
                       optimizer estimated row count: 1.00
                       optimizer estimated cost: 0.00


                 Right result set:
                   Row ResultSet:
                   Number of opens = 2
                   Rows returned = 2
                     constructor time (milliseconds) = 0
                     open time (milliseconds) = 0
                     next time (milliseconds) = 0
                     close time (milliseconds) = 0
                     optimizer estimated row count: 1.00
                     optimizer estimated cost: 0.00


               Right result set:
                 Row ResultSet:
                 Number of opens = 1
                 Rows returned = 1
                   constructor time (milliseconds) = 0
                   open time (milliseconds) = 0
                   next time (milliseconds) = 0
                   close time (milliseconds) = 0
                   optimizer estimated row count: 1.00
                   optimizer estimated cost: 0.00


             Right result set:
               Row ResultSet:
               Number of opens = 1
               Rows returned = 1
                 constructor time (milliseconds) = 0
                 open time (milliseconds) = 0
                 next time (milliseconds) = 0
                 close time (milliseconds) = 0
                 optimizer estimated row count: 1.00
                 optimizer estimated cost: 0.00


         End Subquery Number 0
       Project-Restrict ResultSet (4):
       Number of opens = 1
       Rows seen = 5
       Rows filtered = 4
       restriction = true
       projection = true
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         restriction time (milliseconds) = 0
         projection time (milliseconds) = 0
         optimizer estimated row count: 10.75
         optimizer estimated cost: 2873.71
       Source result set:
         Index Row to Base Row ResultSet for TESTS:
         Number of opens = 1
         Rows seen = 5
         Columns accessed from heap = {0, 9, 21, 22, 23}
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           optimizer estimated row count: 10.75
           optimizer estimated cost: 2873.71
           Index Scan ResultSet for TESTS using constraint TESTS_1 at read 
uncommitted isolation level using share row locking chosen by the optimizer
           Number of opens = 1
           Rows seen = 5
           Rows filtered = 0
           Fetch Size = 1
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             next time in milliseconds/row = 0

           scan information:
             Bit set of columns fetched=All
             Number of columns fetched=3
             Number of deleted rows visited=0
             Number of pages visited=1
             Number of rows qualified=5
             Number of rows visited=6
             Scan type=btree
             Tree height=1
             start position:
               >= on first 1 column(s).
               Ordered null semantics on the following columns:
             stop position:
               > on first 1 column(s).
               Ordered null semantics on the following columns:
             qualifiers:
               None
             optimizer estimated row count: 10.75
             optimizer estimated cost: 2873.71



Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222171), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222172), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT title,DateTimeFormat(t_time,null) AS 
t_time,author,link FROM tests_view WHERE item=? ORDER BY author ASC,1 ASC :End 
prepared statement with 1 parameters begin parameter #1: 60001 :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222172), 
(SESSIONID = 28), SELECT title,DateTimeFormat(t_time,null) AS t_time,author,link 
FROM tests_view WHERE item=? ORDER BY author ASC,1 ASC ******* Scroll 
Insensitive ResultSet:
Number of opens = 1
Rows seen = 1
Number of reads from hash table = 1
Number of writes to hash table = 1
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 10.75
   optimizer estimated cost: 2873.71
Source result set:
   Sort ResultSet:
   Number of opens = 1
   Rows input = 1
   Rows returned = 1
   Eliminate duplicates = false
   In sorted order = false
   Sort information:
     Number of rows input=1
     Number of rows output=1
     Sort type=internal
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     optimizer estimated row count: 10.75
     optimizer estimated cost: 2873.71
   Source result set:
     Attached subqueries:
       Begin Subquery Number 0
       Any ResultSet  (Attached to 3):
       Number of opens = 5
       Rows seen = 5
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         optimizer estimated row count: 387.00
         optimizer estimated cost: 253.09
       Source result set:
         Project-Restrict ResultSet (5):
         Number of opens = 5
         Rows seen = 40
         Rows filtered = 36
         restriction = true
         projection = true
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           restriction time (milliseconds) = 0
           projection time (milliseconds) = 0
           optimizer estimated row count: 387.00
           optimizer estimated cost: 253.09
         Source result set:
           Union ResultSet:
           Number of opens = 5
           Rows seen from the left = 39
           Rows seen from the right = 1
           Rows returned = 40
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             optimizer estimated row count: 11.00
             optimizer estimated cost: 0.00
           Left result set:
             Union ResultSet:
             Number of opens = 5
             Rows seen from the left = 38
             Rows seen from the right = 1
             Rows returned = 39
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0
               optimizer estimated row count: 10.00
               optimizer estimated cost: 0.00
             Left result set:
               Union ResultSet:
               Number of opens = 5
               Rows seen from the left = 36
               Rows seen from the right = 2
               Rows returned = 38
                 constructor time (milliseconds) = 0
                 open time (milliseconds) = 0
                 next time (milliseconds) = 0
                 close time (milliseconds) = 0
                 optimizer estimated row count: 9.00
                 optimizer estimated cost: 0.00
               Left result set:
                 Union ResultSet:
                 Number of opens = 5
                 Rows seen from the left = 33
                 Rows seen from the right = 3
                 Rows returned = 36
                   constructor time (milliseconds) = 0
                   open time (milliseconds) = 0
                   next time (milliseconds) = 0
                   close time (milliseconds) = 0
                   optimizer estimated row count: 8.00
                   optimizer estimated cost: 0.00
                 Left result set:
                   Union ResultSet:
                   Number of opens = 5
                   Rows seen from the left = 29
                   Rows seen from the right = 4
                   Rows returned = 33
                     constructor time (milliseconds) = 0
                     open time (milliseconds) = 0
                     next time (milliseconds) = 0
                     close time (milliseconds) = 0
                     optimizer estimated row count: 7.00
                     optimizer estimated cost: 0.00
                   Left result set:
                     Union ResultSet:
                     Number of opens = 5
                     Rows seen from the left = 25
                     Rows seen from the right = 4
                     Rows returned = 29
                       constructor time (milliseconds) = 0
                       open time (milliseconds) = 0
                       next time (milliseconds) = 0
                       close time (milliseconds) = 0
                       optimizer estimated row count: 6.00
                       optimizer estimated cost: 0.00
                     Left result set:
                       Union ResultSet:
                       Number of opens = 5
                       Rows seen from the left = 20
                       Rows seen from the right = 5
                       Rows returned = 25
                         constructor time (milliseconds) = 0
                         open time (milliseconds) = 0
                         next time (milliseconds) = 0
                         close time (milliseconds) = 0
                         optimizer estimated row count: 5.00
                         optimizer estimated cost: 0.00
                       Left result set:
                         Union ResultSet:
                         Number of opens = 5
                         Rows seen from the left = 15
                         Rows seen from the right = 5
                         Rows returned = 20
                           constructor time (milliseconds) = 0
                           open time (milliseconds) = 0
                           next time (milliseconds) = 0
                           close time (milliseconds) = 0
                           optimizer estimated row count: 4.00
                           optimizer estimated cost: 0.00
                         Left result set:
                           Union ResultSet:
                           Number of opens = 5
                           Rows seen from the left = 10
                           Rows seen from the right = 5
                           Rows returned = 15
                             constructor time (milliseconds) = 0
                             open time (milliseconds) = 0
                             next time (milliseconds) = 0
                             close time (milliseconds) = 0
                             optimizer estimated row count: 3.00
                             optimizer estimated cost: 0.00
                           Left result set:
                             Union ResultSet:
                             Number of opens = 5
                             Rows seen from the left = 5
                             Rows seen from the right = 5
                             Rows returned = 10
                               constructor time (milliseconds) = 0
                               open time (milliseconds) = 0
                               next time (milliseconds) = 0
                               close time (milliseconds) = 0
                               optimizer estimated row count: 2.00
                               optimizer estimated cost: 0.00
                             Left result set:
                               Row ResultSet:
                               Number of opens = 5
                               Rows returned = 5
                                 constructor time (milliseconds) = 0
                                 open time (milliseconds) = 0
                                 next time (milliseconds) = 0
                                 close time (milliseconds) = 0
                                 optimizer estimated row count: 1.00
                                 optimizer estimated cost: 0.00

                             Right result set:
                               Row ResultSet:
                               Number of opens = 5
                               Rows returned = 5
                                 constructor time (milliseconds) = 0
                                 open time (milliseconds) = 0
                                 next time (milliseconds) = 0
                                 close time (milliseconds) = 0
                                 optimizer estimated row count: 1.00
                                 optimizer estimated cost: 0.00


                           Right result set:
                             Row ResultSet:
                             Number of opens = 5
                             Rows returned = 5
                               constructor time (milliseconds) = 0
                               open time (milliseconds) = 0
                               next time (milliseconds) = 0
                               close time (milliseconds) = 0
                               optimizer estimated row count: 1.00
                               optimizer estimated cost: 0.00


                         Right result set:
                           Row ResultSet:
                           Number of opens = 5
                           Rows returned = 5
                             constructor time (milliseconds) = 0
                             open time (milliseconds) = 0
                             next time (milliseconds) = 0
                             close time (milliseconds) = 0
                             optimizer estimated row count: 1.00
                             optimizer estimated cost: 0.00


                       Right result set:
                         Row ResultSet:
                         Number of opens = 5
                         Rows returned = 5
                           constructor time (milliseconds) = 0
                           open time (milliseconds) = 0
                           next time (milliseconds) = 0
                           close time (milliseconds) = 0
                           optimizer estimated row count: 1.00
                           optimizer estimated cost: 0.00


                     Right result set:
                       Row ResultSet:
                       Number of opens = 4
                       Rows returned = 4
                         constructor time (milliseconds) = 0
                         open time (milliseconds) = 0
                         next time (milliseconds) = 0
                         close time (milliseconds) = 0
                         optimizer estimated row count: 1.00
                         optimizer estimated cost: 0.00


                   Right result set:
                     Row ResultSet:
                     Number of opens = 4
                     Rows returned = 4
                       constructor time (milliseconds) = 0
                       open time (milliseconds) = 0
                       next time (milliseconds) = 0
                       close time (milliseconds) = 0
                       optimizer estimated row count: 1.00
                       optimizer estimated cost: 0.00


                 Right result set:
                   Row ResultSet:
                   Number of opens = 3
                   Rows returned = 3
                     constructor time (milliseconds) = 0
                     open time (milliseconds) = 0
                     next time (milliseconds) = 0
                     close time (milliseconds) = 0
                     optimizer estimated row count: 1.00
                     optimizer estimated cost: 0.00


               Right result set:
                 Row ResultSet:
                 Number of opens = 2
                 Rows returned = 2
                   constructor time (milliseconds) = 0
                   open time (milliseconds) = 0
                   next time (milliseconds) = 0
                   close time (milliseconds) = 0
                   optimizer estimated row count: 1.00
                   optimizer estimated cost: 0.00


             Right result set:
               Row ResultSet:
               Number of opens = 1
               Rows returned = 1
                 constructor time (milliseconds) = 0
                 open time (milliseconds) = 0
                 next time (milliseconds) = 0
                 close time (milliseconds) = 0
                 optimizer estimated row count: 1.00
                 optimizer estimated cost: 0.00


           Right result set:
             Row ResultSet:
             Number of opens = 1
             Rows returned = 1
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0
               optimizer estimated row count: 1.00
               optimizer estimated cost: 0.00


       End Subquery Number 0
     Project-Restrict ResultSet (3):
     Number of opens = 1
     Rows seen = 5
     Rows filtered = 4
     restriction = true
     projection = true
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       restriction time (milliseconds) = 0
       projection time (milliseconds) = 0
       optimizer estimated row count: 10.75
       optimizer estimated cost: 2873.71
     Source result set:
       Index Row to Base Row ResultSet for TESTS:
       Number of opens = 1
       Rows seen = 5
       Columns accessed from heap = {0, 9, 21, 22, 23}
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         optimizer estimated row count: 10.75
         optimizer estimated cost: 2873.71
         Index Scan ResultSet for TESTS using constraint TESTS_1 at read 
uncommitted isolation level using share row locking chosen by the optimizer
         Number of opens = 1
         Rows seen = 5
         Rows filtered = 0
         Fetch Size = 1
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           next time in milliseconds/row = 0

         scan information:
           Bit set of columns fetched=All
           Number of columns fetched=3
           Number of deleted rows visited=0
           Number of pages visited=1
           Number of rows qualified=5
           Number of rows visited=6
           Scan type=btree
           Tree height=1
           start position:
             >= on first 1 column(s).
             Ordered null semantics on the following columns:
           stop position:
             > on first 1 column(s).
             Ordered null semantics on the following columns:
           qualifiers:
             None
           optimizer estimated row count: 10.75
           optimizer estimated cost: 2873.71



Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222172), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222173), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Begin compiling 
prepared statement: SELECT tests.id,tests.item,title FROM tests,item_usage WHERE 
username=? AND user_role>=3 AND item_usage.item=tests.item ORDER BY 
item_usage.item,title :End prepared statement
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222173), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), End compiling 
prepared statement: SELECT tests.id,tests.item,title FROM tests,item_usage WHERE 
username=? AND user_role>=3 AND item_usage.item=tests.item ORDER BY 
item_usage.item,title :End prepared statement
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222173), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Executing 
prepared statement: SELECT tests.id,tests.item,title FROM tests,item_usage WHERE 
username=? AND user_role>=3 AND item_usage.item=tests.item ORDER BY 
item_usage.item,title :End prepared statement with 1 parameters begin parameter 
#1: TAMMY :end parameter
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222173), 
(SESSIONID = 28), SELECT tests.id,tests.item,title FROM tests,item_usage WHERE 
username=? AND user_role>=3 AND item_usage.item=tests.item ORDER BY 
item_usage.item,title ******* Scroll Insensitive ResultSet:
Number of opens = 1
Rows seen = 30
Number of reads from hash table = 30
Number of writes to hash table = 30
   constructor time (milliseconds) = 0
   open time (milliseconds) = 0
   next time (milliseconds) = 0
   close time (milliseconds) = 0
   optimizer estimated row count: 1.80
   optimizer estimated cost: 5186.92
Source result set:
   Project-Restrict ResultSet (9):
   Number of opens = 1
   Rows seen = 30
   Rows filtered = 0
   restriction = false
   projection = true
     constructor time (milliseconds) = 0
     open time (milliseconds) = 0
     next time (milliseconds) = 0
     close time (milliseconds) = 0
     restriction time (milliseconds) = 0
     projection time (milliseconds) = 0
     optimizer estimated row count: 1.80
     optimizer estimated cost: 5186.92
   Source result set:
     Sort ResultSet:
     Number of opens = 1
     Rows input = 30
     Rows returned = 30
     Eliminate duplicates = false
     In sorted order = false
     Sort information:
       Number of rows input=30
       Number of rows output=30
       Sort type=internal
       constructor time (milliseconds) = 0
       open time (milliseconds) = 0
       next time (milliseconds) = 0
       close time (milliseconds) = 0
       optimizer estimated row count: 19.34
       optimizer estimated cost: 5186.92
     Source result set:
       Project-Restrict ResultSet (7):
       Number of opens = 1
       Rows seen = 30
       Rows filtered = 0
       restriction = false
       projection = true
         constructor time (milliseconds) = 0
         open time (milliseconds) = 0
         next time (milliseconds) = 0
         close time (milliseconds) = 0
         restriction time (milliseconds) = 0
         projection time (milliseconds) = 0
         optimizer estimated row count: 19.34
         optimizer estimated cost: 5186.92
       Source result set:
         Nested Loop Join ResultSet:
         Number of opens = 1
         Rows seen from the left = 5
         Rows seen from the right = 30
         Rows filtered = 0
         Rows returned = 30
           constructor time (milliseconds) = 0
           open time (milliseconds) = 0
           next time (milliseconds) = 0
           close time (milliseconds) = 0
           optimizer estimated row count: 19.34
           optimizer estimated cost: 5186.92
         Left result set:
           Project-Restrict ResultSet (4):
           Number of opens = 1
           Rows seen = 5
           Rows filtered = 0
           restriction = true
           projection = true
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             restriction time (milliseconds) = 0
             projection time (milliseconds) = 0
             optimizer estimated row count: 1.80
             optimizer estimated cost: 17.01
           Source result set:
             Index Row to Base Row ResultSet for ITEM_USAGE:
             Number of opens = 1
             Rows seen = 5
             Columns accessed from heap = {0, 1, 2}
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0
               optimizer estimated row count: 1.80
               optimizer estimated cost: 17.01
               Index Scan ResultSet for ITEM_USAGE using constraint ITEM_USAGE_1 
at read uncommitted isolation level using share row locking chosen by the optimizer
               Number of opens = 1
               Rows seen = 5
               Rows filtered = 0
               Fetch Size = 16
                 constructor time (milliseconds) = 0
                 open time (milliseconds) = 0
                 next time (milliseconds) = 0
                 close time (milliseconds) = 0
                 next time in milliseconds/row = 0

               scan information:
                 Bit set of columns fetched=All
                 Number of columns fetched=2
                 Number of deleted rows visited=0
                 Number of pages visited=2
                 Number of rows qualified=5
                 Number of rows visited=6
                 Scan type=btree
                 Tree height=2
                 start position:
                   >= on first 1 column(s).
                   Ordered null semantics on the following columns:
                 stop position:
                   > on first 1 column(s).
                   Ordered null semantics on the following columns:
                 qualifiers:
                   None
                 optimizer estimated row count: 1.80
                 optimizer estimated cost: 17.01

         Right result set:
           Index Row to Base Row ResultSet for TESTS:
           Number of opens = 5
           Rows seen = 30
           Columns accessed from heap = {0, 1, 2}
             constructor time (milliseconds) = 0
             open time (milliseconds) = 0
             next time (milliseconds) = 0
             close time (milliseconds) = 0
             optimizer estimated row count: 19.34
             optimizer estimated cost: 5169.91
             Index Scan ResultSet for TESTS using constraint TESTS_1 at read 
uncommitted isolation level using share row locking chosen by the optimizer
             Number of opens = 5
             Rows seen = 30
             Rows filtered = 0
             Fetch Size = 16
               constructor time (milliseconds) = 0
               open time (milliseconds) = 0
               next time (milliseconds) = 0
               close time (milliseconds) = 0
               next time in milliseconds/row = 0

             scan information:
               Bit set of columns fetched={0, 2}
               Number of columns fetched=2
               Number of deleted rows visited=9
               Number of pages visited=5
               Number of rows qualified=30
               Number of rows visited=43
               Scan type=btree
               Tree height=1
               start position:
                 >= on first 1 column(s).
                 Ordered null semantics on the following columns:
                 0
               stop position:
                 > on first 1 column(s).
                 Ordered null semantics on the following columns:
                 0
               qualifiers:
                 None
               optimizer estimated row count: 19.34
               optimizer estimated cost: 5169.91




Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222173), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Committing
Tue Apr 02 21:14:56 IDT 2013 Thread[qtp31568925-35,5,main] (XID = 7222173), 
(SESSIONID = 28), (DATABASE = ../db/db_copy), (DRDAID = null), Rolling back

-- 
John English

Mime
View raw message