Return-Path: 
 <derby-dev-return-103068-apmail-db-derby-dev-archive=db.apache.org@db.apache.org>
X-Original-To: apmail-db-derby-dev-archive@www.apache.org
Delivered-To: apmail-db-derby-dev-archive@www.apache.org
Received: from mail.apache.org (hermes.apache.org [140.211.11.3])
	by minotaur.apache.org (Postfix) with SMTP id 20608D2DD
	for <apmail-db-derby-dev-archive@www.apache.org>;
 Thu, 16 May 2013 06:53:20 +0000 (UTC)
Received: (qmail 48816 invoked by uid 500); 16 May 2013 06:53:19 -0000
Delivered-To: apmail-db-derby-dev-archive@db.apache.org
Received: (qmail 48467 invoked by uid 500); 16 May 2013 06:53:18 -0000
Mailing-List: contact derby-dev-help@db.apache.org; run by ezmlm
Precedence: bulk
List-Help: <mailto:derby-dev-help@db.apache.org>
List-Unsubscribe: <mailto:derby-dev-unsubscribe@db.apache.org>
List-Post: <mailto:derby-dev@db.apache.org>
List-Id: <derby-dev.db.apache.org>
Reply-To: <derby-dev@db.apache.org>
Delivered-To: mailing list derby-dev@db.apache.org
Received: (qmail 47868 invoked by uid 99); 16 May 2013 06:53:17 -0000
Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28)
    by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 16 May 2013 06:53:17 +0000
Date: Thu, 16 May 2013 06:53:17 +0000 (UTC)
From: "Dag H. Wanvik (JIRA)" <jira@apache.org>
To: derby-dev@db.apache.org
Message-ID: <JIRA.12640488.1364986467445.330390.1368687197492@arcas>
In-Reply-To: <JIRA.12640488.1364986467445@arcas>
References: <JIRA.12640488.1364986467445@arcas>
Subject: [jira] [Comment Edited] (DERBY-6148) Peculiar sorting behaviour
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394


    [ https://issues.apache.org/jira/browse/DERBY-6148?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13659298#comment-13659298 ] 

Dag H. Wanvik edited comment on DERBY-6148 at 5/16/13 6:52 AM:
---------------------------------------------------------------

Uploading a patch which makes the failing query work and regressions passed. It is not for commit; I need add new regression tests at the minimum.

The previous hypothesis about lacking reset/forgetting info from the first (discarded) join permutation proved to not be the reason for the error.  I believe the root cause is an incorrect assumption in OrderByList#sortRequired(RowOrdering, JBitSet, OptimizableList). DERBY-3926 added the OptimizableList argument to this method. 

In the logic, that argument is treated as the join ordering under consideration, cf. the Javadoc of RequiredRowOrdering#sortRequired; the interface OrderByList's method implements (quote):

* "@param optimizableList	The current join order being considered by 
*    the optimizer. We need to look into this to determine if the outer
*    optimizables are single row resultset if the order by column is
*    on an inner optimizable and that inner optimizable is not a one
*    row resultset. DERBY-3926

However, debugging, I see that the argument passed in from OptimizerImpl is always OptimizerImpl#optimizableList which is not permuted when join orders are considered. The permutation is described by OptimizerImpl#proposedJoinOrder, which is a map into OptimizerImpl#optimizableList.  See for example usage ca line 556:

....optimizableList.getOptimizable(proposedJoinOrder[joinPosition]).getBestAccessPath()....

Now in OrderByList#sortRequired, there is this piece of code:

    // If we have come across the optimizable for the order
    // by column in the join order, then we do not need to
    // look at the inner optimizables in the join order. As
    // long as the outer optimizables are one row
    // resultset, or is ordered on the order by column (see
    // below check), we are fine to consider sort
    // avoidance.
    if (considerOptimizable.getTableNumber() == 
        cr.getTableNumber())
        break;

This test is meant to determine that the column reference cr (the current order by column under consideration) references the current (outer) optimizable. It will only get this this test for inner tables if the outer has only one row. And in the query that works as intended so when I textually reordered the FROM tables to match the chosen join order, that's exactly what happens: ITEMS_USAGE is the outer table and the cr's table number doesn't match it (both colums reference TESTS), so the break is not performed.

However, in the failing case, this test actually checks against the *inner* table (TESTS), since the proposedJoinOrder map isn't used, so the break is executed. Then later in the same method, ca line 622, we check whether the order by columns are ordered against the rowOrdering of the current access path (the index on the unique constraint TESTS_1 which does contain both the order by columns), so sort avoidance is accepted.

After I introduce the indirection map into the method, the check shown above will always fail for outer ITEMS_USAGE (no matter its textual order in the join): execution proceeds to the check for single row in the outer optimizable (ca. line 605), which fails, since the outer table (ITEMS_USAGE) may have more than one row with even with equality predicate on user ('TAMMY'), so sort avoidance is not accepted.

                
      was (Author: dagw):
    Uploading a patch which makes the failing query work and regressions passed. It is not for commit; I need add new regression tests at the minimum.

The previous hypothesis about lacking reset/forgetting info from the first (discarded) join permutation proved to not be the reason for the error.  I believe the root cause is an incorrect assumption in OrderByList#sortRequired(RowOrdering, JBitSet, OptimizableList). DERBY-3926 added the OptimizableList argument to this method. 

In the logic, that argument is treated as the join ordering under consideration, cf. the Javadoc of RequiredRowOrdering#sortRequired; the interface OrderByList's method implements (quote):

* "@param optimizableList	The current join order being considered by 
*    the optimizer. We need to look into this to determine if the outer
*    optimizables are single row resultset if the order by column is
*    on an inner optimizable and that inner optimizable is not a one
*    row resultset. DERBY-3926

However, debugging, I see that the argument passed in from OptimizerImpl is always OptimizerImpl#optimizableList which is not permuted when join orders are considered. The permutation is described by OptimizerImpl#proposedJoinOrder, which is a map into OptimizerImpl#optimizableList.  See for example usage ca line 556:

....optimizableList.getOptimizable(proposedJoinOrder[joinPosition]).getBestAccessPath()....

Now in OrderByList#sortRequired, there is this piece of code:

    // If we have come across the optimizable for the order
    // by column in the join order, then we do not need to
    // look at the inner optimizables in the join order. As
    // long as the outer optimizables are one row
    // resultset, or is ordered on the order by column (see
    // below check), we are fine to consider sort
    // avoidance.
    if (considerOptimizable.getTableNumber() == 
        cr.getTableNumber())
        break;

This test is meant to determine that the column reference cr (the current order by column under consideration) references the current (outer) optimizable. And in the query that works, when I reordered the FROM tables to match the chosen join order, that's exactly what happens: ITEMS_USAGE is the outer table and the cr's table number doesn't match it, so the break is not performed.

However, in the failing case, this test actually checks against the *inner* table (TESTS), since the proposedJoinOrder map isn't used, so the break is executed. Then later in the same method, ca line 622, we check whether the order by columns are ordered against the rowOrdering of the current access path (the index on the unique constraint TESTS_1 which does contain both the order by column), so sort avoidance is accepted.

After I introduce the indirection map into the method, the check shown above will always fail for outer ITEMS_USAGE (no matter its textual order in the join): execution proceeds to the check for single row in the outer optimizable (ca. line 605), which fails, since the outer table (ITEMS_USAGE) may have more than one row with even with equality predicate on user ('TAMMY'), so sort avoidance is not accepted.

                  
> 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, derby-6148-1.diff, derby-6148-1.status, preprocessed1.txt, preprocessed2.txt, 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