#109 Cursor.newIterable appears to cycle through remaining index values after matching range

[Gord Thompson]

Further to http://stackoverflow.com/q/25907985/2144390

hmm, i wonder if there is a bug in the index lookups where it's not fast failing at the end of the matching range.

There seems to be some evidence to that effect, if Cursor.newIterable().addMatchPattern() is intended to recognize that condition and quit looking.

For a table [Invoices]

Code      InvoiceDate
--------  ------------
1301/001  2014-09-10
1301/002  2014-09-12
1301/998  2014-11-01
1301/999  2014-12-01

and a table [InvoicesLignes] with 100,000 rows

LineItemID  Code
----------  --------
         1  1301/001
         2  1301/998
         3  1301/999
         4  1301/500
         5  1301/500
         6  1301/500
...
     99995  1301/500
     99996  1301/500
     99997  1301/500
     99998  1301/002
     99999  1301/002
    100000  1301/001

the code

Table invoices = db_opened.getTable("Invoices");
Table invoices_lignes = db_opened.getTable("InvoicesLignes");

Cursor cursor = CursorBuilder.createCursor(invoices_lignes.getIndex("Code"));

for(Row row : invoices) {
    long start = System.currentTimeMillis( );
    System.out.println(String.format("Invoice (Code) %s: start", row.get("Code")));

    for (Row crow : cursor.newIterable().addMatchPattern("Code", row.get("Code"))) {
        System.out.println(String.format("LineItemID %d: %d ms since start", crow.get("LineItemID"), System.currentTimeMillis() - start));
    }

    System.out.println(String.format("Loop elapsed time: %d ms since start", System.currentTimeMillis() - start));
    System.out.println();
}

produces

Invoice (Code) 1301/001: start
LineItemID 1: 36 ms since start
LineItemID 99999: 42 ms since start
Loop elapsed time: 2025 ms since start

Invoice (Code) 1301/002: start
LineItemID 99997: 1 ms since start
LineItemID 99998: 2 ms since start
Loop elapsed time: 1540 ms since start

Invoice (Code) 1301/998: start
LineItemID 2: 1 ms since start
Loop elapsed time: 1 ms since start

Invoice (Code) 1301/999: start
LineItemID 3: 1 ms since start
Loop elapsed time: 1 ms since start

The loops processing [Code] values near the beginning of the index order have significant "hang time" between the moment that the last child record is retrieved and the time that the loop exits. If the loop is processing a [Code] value at the end of the index order don't display that same delay before exiting the loop.

[James Ahlborn]

Heh, thanks for doing the investigation on that!

[Gord Thompson]

Happy to help! The above test was done with an .mdb on my local hard drive. I just repeated the test after moving the .mdb file to a network share and I got

Invoice (Code) 1301/001: start
LineItemID 1: 37 ms since start
LineItemID 100000: 60 ms since start
Loop elapsed time: 11075 ms since start

Invoice (Code) 1301/002: start
LineItemID 99998: 2 ms since start
LineItemID 99999: 3 ms since start
Loop elapsed time: 1822 ms since start

Invoice (Code) 1301/998: start
LineItemID 2: 1 ms since start
Loop elapsed time: 2 ms since start

Invoice (Code) 1301/999: start
LineItemID 3: 1 ms since start
Loop elapsed time: 1 ms since start

By comparison, the approach in my answer on Stack Overflow

Table invoices = db_opened.getTable("Invoices");
Table invoices_lignes = db_opened.getTable("InvoicesLignes");

for(Row row : invoices) {
    long start = System.currentTimeMillis( );
    System.out.println(String.format("Invoice (Code) %s: start", row.get("Code")));

    IndexCursor cursor = new CursorBuilder(invoices_lignes)
            .setIndexByName("Code")
            .setSpecificEntry(row.get("Code"))
            .toIndexCursor();
    for (Row crow : cursor) {
        System.out.println(String.format("LineItemID %d: %d ms since start", crow.get("LineItemID"), System.currentTimeMillis() - start));
    }

    System.out.println(String.format("Loop elapsed time: %d ms since start", System.currentTimeMillis() - start));
    System.out.println();
}

produced this

Invoice (Code) 1301/001: start
LineItemID 1: 68 ms since start
LineItemID 100000: 87 ms since start
Loop elapsed time: 88 ms since start

Invoice (Code) 1301/002: start
LineItemID 99998: 1 ms since start
LineItemID 99999: 2 ms since start
Loop elapsed time: 3 ms since start

Invoice (Code) 1301/998: start
LineItemID 2: 2 ms since start
Loop elapsed time: 3 ms since start

Invoice (Code) 1301/999: start
LineItemID 3: 1 ms since start
Loop elapsed time: 2 ms since start

[James Ahlborn]

I've checked in a fix for this into trunk, although i don't have a great way of verifying that it fixes this issue.

[Gord Thompson]

i don't have a great way of verifying that it fixes this issue

It certainly seems to. My previous test under 2.0.5 with the .mdb file on the network share produced

Invoice (Code) 1301/001: start
LineItemID 1: 37 ms since start
LineItemID 100000: 60 ms since start
Loop elapsed time: 11075 ms since start

Invoice (Code) 1301/002: start
LineItemID 99998: 2 ms since start
LineItemID 99999: 3 ms since start
Loop elapsed time: 1822 ms since start

Invoice (Code) 1301/998: start
LineItemID 2: 1 ms since start
Loop elapsed time: 2 ms since start

Invoice (Code) 1301/999: start
LineItemID 3: 1 ms since start
Loop elapsed time: 1 ms since start

I just tested the same thing using "jackcess-2.0.6-SNAPSHOT.jar" and I got

Invoice (Code) 1301/001: start
LineItemID 1: 39 ms since start
LineItemID 100000: 56 ms since start
Loop elapsed time: 57 ms since start

Invoice (Code) 1301/002: start
LineItemID 99998: 2 ms since start
LineItemID 99999: 3 ms since start
Loop elapsed time: 5 ms since start

Invoice (Code) 1301/998: start
LineItemID 2: 1 ms since start
Loop elapsed time: 2 ms since start

Invoice (Code) 1301/999: start
LineItemID 3: 1 ms since start
Loop elapsed time: 2 ms since start

[James Ahlborn]

Fixed in trunk, will be in the 2.0.6 release.