Mailing-List: contact derby-dev-help@db.apache.org; run by ezmlm
Precedence: bulk
Reply-To: <derby-dev@db.apache.org>
Date: Sat, 11 May 2013 08:23:16 +0000 (UTC)
From: "Dag H. Wanvik (JIRA)" <jira@apache.org>
To: derby-dev@db.apache.org
Message-ID: <JIRA.12640488.1364986467445.305243.1368260596421@arcas>
In-Reply-To: <JIRA.12640488.1364986467445@arcas>
References: <JIRA.12640488.1364986467445@arcas>
Subject: [jira] [Updated] (DERBY-6148) Peculiar sorting behaviour
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit


     [ https://issues.apache.org/jira/browse/DERBY-6148?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Dag H. Wanvik updated DERBY-6148:
---------------------------------

    Attachment: q2.txt
                q1.txt
    
> Peculiar sorting behaviour
> --------------------------
>
>                 Key: DERBY-6148
>                 URL: https://issues.apache.org/jira/browse/DERBY-6148
>             Project: Derby
>          Issue Type: Bug
>          Components: SQL
>    Affects Versions: 10.9.1.0
>         Environment: Windows 7 64-bit, Ubuntu 32-bit; JRE 1.7.0_11+
>            Reporter: John English
>         Attachments: bug.zip, bug.zip, q1.txt, q2.txt
>
>
> I have a query that looks like this:
>   SELECT tests.id,tests.item,title FROM tests,item_usage
>   WHERE username=? AND user_role>?
>   AND item_usage.item=tests.item
>   ORDER BY tests.item,title
> The result ordering is by item code followed by title, but the item codes are listed in the order in which they appear in the ITEMS table where they are the primary key rather than in ascending order as expected. If however I change the ORDER BY clause to sort by item_usage.item rather than tests.item, it works correctly, even though the two values are the same!
> The same thing happens in another unrelated query involving item_usage, and the same workaround cures it.
> The relevant tables are defined like so:
>   CREATE TABLE item_usage (
>     username    VARCHAR(15)   NOT NULL,
>     item        VARCHAR(15)   NOT NULL,
>     value       SMALLINT      DEFAULT 0,
>     CONSTRAINT item_usage_pk  PRIMARY KEY (username,item),
>     CONSTRAINT item_usage_1   FOREIGN KEY (username)
>                               REFERENCES users(username)
>                               ON DELETE CASCADE,
>     CONSTRAINT item_usage_2   FOREIGN KEY (item)
>                               REFERENCES items(item)
>                               ON DELETE CASCADE,
>     CONSTRAINT item_usage_3   CHECK (value BETWEEN 0 AND 4)
>   );
>   CREATE TABLE tests (
>     id          INTEGER       GENERATED ALWAYS AS IDENTITY,
>     item        VARCHAR(15)   NOT NULL,
>     title       VARCHAR(255)  NOT NULL,
>     disp        SMALLINT      NOT NULL DEFAULT 0,
>     starttime   TIMESTAMP     DEFAULT NULL,
>     endtime     TIMESTAMP     DEFAULT NULL,
>     offsetx     INTEGER       NOT NULL DEFAULT 0,
>     offsety     INTEGER       NOT NULL DEFAULT 0,
>     rate        INTEGER       NOT NULL DEFAULT 0,
>     duration    INTEGER       NOT NULL DEFAULT 0,
>     calibrate   INTEGER       NOT NULL DEFAULT 0,
>     deadline    TIMESTAMP     DEFAULT NULL,
>     stepsize    INTEGER       NOT NULL DEFAULT 0,
>     interval    INTEGER       NOT NULL DEFAULT 0,
>     stand       CHAR(1)       DEFAULT NULL,
>     hidden      CHAR(1)       DEFAULT NULL,
>     repeated    CHAR(1)       DEFAULT NULL,
>     private     CHAR(1)       DEFAULT NULL,
>     sequential  CHAR(1)       DEFAULT NULL,
>     final       CHAR(1)       DEFAULT NULL,
>     notes       CLOB          DEFAULT NULL,
>     testxml     CLOB          NOT NULL,
>     author      VARCHAR(15)   NOT NULL,
>     time        TIMESTAMP     NOT NULL,
>     CONSTRAINT tests_pk       PRIMARY KEY (id),
>     CONSTRAINT tests_1        UNIQUE (item, title),
>     CONSTRAINT tests_2        FOREIGN KEY (item)
>                               REFERENCES items(item)
>                               ON DELETE CASCADE,
>     CONSTRAINT tests_3        CHECK (disp BETWEEN 0 AND 100),
>     CONSTRAINT tests_4        CHECK (rate BETWEEN 0 AND 100),
>     CONSTRAINT tests_5        CHECK (stepsize BETWEEN 0 AND 100)
>   );
> If I run the query manually I get this, as expected:
>   ID  ITEM    TITLE
>   37  60001   Test 1
>   42  60001   Test 2
>   51  60001   Test 3
>   17  61303   Test 2a
>   16  61303   Test 2b
>   7   7205731 Test 2a
>   8   7205731 Test 2b
> Now, this is actually part of a web app that should turn this into a list of options in a <select> item using the following code:
>   while (query.next()) {
>     println("<option value='" + query.getInt("id") + "'>"
>             + encode(query.getString("item") + ": "
>             + query.getString("title")) + "</option>");
>   }
> What I actually get is this:
>   <option value="17">61303: Test 2a</option>
>   <option value="16">61303: Test 2b</option>
>   <option value="7">7205731: Test 2a</option>
>   <option value="8">7205731: Test 2b</option>
>   <option value="37">60001: Test 1</option>
>   <option value="42">60001: Test 2</option>
>   <option value="51">60001: Test 3</option>
> The results are sorted by item then by title, but the item order is the order in which they were originally inserted into the items table (where the item and item description are stored, referenced by item_usage.item) rather than by item code. 
> I've tried to reproduce this behaviour in a simple example, but without success. I have logged the query plans for both versions; the log output is as follows, with the INCORRECT query (using ORDER BY tests.item) followed later by the CORRECT query (using ORDER BY item_usage.item):
> 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

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira