Performance regression with 10.2.1.0, oddly throughput drops with fix for derby-1543

[Sunitha Kambhampati <ks...@gmail.com>]

I ran some simple performance tests with the 10.2.1.0 beta jars and one 
of the tests
( lets just say the name of the test is ScanCoveredIdxInt), the 
throughput is about *56%* of the 10.1.3 release.

BRIEF DESCRIPTION OF TEST:
The test has a setup phase, runtest phase and then the cleanup phase. 
The timed portion of the test is the
runtest phase.
What the test does:
-- setup includes - drop table, create table, inserting 20000 rows. each 
row is approximately 100bytes each.  ,
creating a unique composite index.
-- runtest which is the timed part of the test is multiple iterations of 
a select which should only
involve an index scan of the data and number of rows that qualify is 
10000 rows.
-- cleanup - drops the table.
-- The runtest part is iterated 400 times and the runtest part is timed.  
(scroll to the end of this mail for code snippets from the test).

Each testrun involves the setup phase, and then runtest phase and 
cleanup..  
The select query is iterated 400 times.
The testrun is repeated four times and the average throughput is 
calculated from the last three testruns.
First testrun result is ignored.
                          
ibm142/linux (2.8intel xeon cpu, hyperthreading enabled,4gbram,scsi 
disks).  Throughput unit is 10000rows/sec
Throughput with 10.1.3  - 24
Throughput with 10.2.1.0 - 13
(Measurement is throughput, so higher number the better).

Tried different things but the short story is:
1)The test does a create database and then drop table;create table;load 
data into table.
if the 'create database' step is removed from the testrun, the 
throughput of 10.1.3 and 10.2.1.0
are in the same range.
2)If the checkpoint was added after the load of the test, then the 
throughput of the select query
for both 10.1.3 and 10.2.1.0 are in similar range.

This (#1) to me doesnt make much sense. I would have thought it was some 
weird i/o sync happening.

Testing with different jars, it turns out at revision *#426847*, the 
throughput drops. Among several runs,
this behavior is consistent.  I tested with the previous revision 
(426825)and the throughput is good.

This revision  #426847  fixes DERBY-1543  
http://svn.apache.org/viewvc?rev=426847&view=rev

"1) Now Derby raises an SQLWarning when SQL authorization is ON without 
authentication at connect time.
This is done by checking if AuthenticationService being used is an 
instance of NoneAuthenticationServiceImpl.
Since this is the default authentication service with Derby, it should 
always be present.

2) Added code to drop permission descriptors from SYSTABLEPERMS, 
SYSCOLPERMS and SYSROUTINEPERMS
when the object they provide permission for is dropped. This includes 
tables, views and routines
and these descriptors needs to be removed from permissionCache as well."

Does this make sense?  Or am I just seeing some other i/o side effect in 
my test ?   Appreciate your input.  Thanks.

Just noting some observations of the other things that I had already tried:
-------------------------------------------------------------------
1) Changing the  test to only time the select without load being part of 
the same jvm run, the throughput for 10.2.1.0 is closer to 10.1.3 ( ~ 94%).
(Details - do the load separately. remove the drop table in cleanup and 
thus time only the select part. )
Throughput with 10.1.3 - 59
Throughput with 10.2.1.0 - 55
I guess, since the main purpose of the test is to time the select, the 
test should have just had select as part of the jvm run.

2) I logged query plans using the derby.language.logQueryPlan and 
checked the derby.log for both 10.1.3 run and 10.2.1.0 run.  The 
throughput at this time was similar.  Note, logQueryPlan prints plans 
and it is pretty verbose.. so slowing down execution.  In any case, FWIW 
- the query plans looked the same for both 10.1.3 and 10.2.1.0.  An 
index scan is used, the estimates were also the same.

 From #1, somehow it seems that the work related to load is being 
delayed and thus affecting the select part of the test.  

Some theories :
a)-- Maybe it was the changes that went in as part of derby-888 that 
improves performance of page allocation that could have affected it.
This change writes pages to the OS at allocation time but doesnt sync 
them. Before the writes would have all been synced so no OS work to do 
after the load.
 -- A checkpoint is getting triggered , that could be affecting the 
select portion of the run.
c)-- something wrong with optimizer.  But #2 observation rules this out.

Further things tried:
To prove that it maybe a result of (a),  I tried to build jars just 
before the derby-888 changes and ran tests.
Modified test , pre and post 888 , throughput changes not seen.  This is 
ok.   Of interest is the throughput value (130000 rows/sec).
Original test case with load+select,  post 888, the inserts are done 
much faster than pre-888. This is expected and ok.

Checkpoint case:
With load+ explicit checkpoint and then time the test.
* post 888 shows little improvements over the pre 888.  (pre - 12, post 
is 14.6).
* 10.1.3 and 10.2.1.0 throughput in same range. (10.1.3 - 14.3 ,10.2 - 12.6)

Modified test(#1) and putting checkpoint interval to 100mb, to avoid a 
checkpoint during the testrun    10.2 is about 90% of 10.1.3.
Original test with putting checkpoint interval to 100mb, to avoid any 
checkpoitns from happening. 10.2 and 10.1 are similar range.
-------------------------------------------------------------

Pseudo code: 
setup:
....
            execSQL("drop table " + getTableName());
        catch (SQLException se)
        {
            out.println("Caught expected SQL exception " + se.toString());
        }

        execSQL("create table " + getTableName() + " ("
            + "i1 int, i2 int, i3 int, i4 int, i5 int, "
            + "c6 char(20), c7 char(20), c8 char(20), c9 char(20))");

        conn.setAutoCommit(false);
        loadData();   //loads 20000 rows.

        execSQL(
            "create unique index " +
            getTableName() + "x on " + getTableName() + "(i1, i3)");
         selectStatement =
                       conn.prepareStatement(
                            "select i1 from " + getTableName() +
                                " where i1 > ? and i1 <= ?");

                   conn.commit();

runpart:
    public void run() throws Exception
    {
        // set begin scan to start 1/4 into the data set.
        selectStatement.setInt(1, ((getRowCount() * 2) / 4));

        // set end scan to end 3/4 into the data set.
        selectStatement.setInt(2, (((getRowCount() * 2) / 4) * 3));

        ResultSet rs = selectStatement.executeQuery();
        while (rs.next())
        {
            int i = rs.getInt(1);
        }
        rs.close();
       conn.commit();
    }