indexWait just after indexCreate takes 10 seconds

[neumino]

In a table with 100 documents with two fields (id and field -- field is set to 0 or 10)

r.db('test').table('test').indexDrop('field');
r.db('test').table('test').indexCreate('field');
r.db('test').table('test').indexWait('field');

Takes 10 seconds to complete on 1.12 while it takes 2ms on 1.11.

The data explorer execute the queries in a synchronous way.
However, if I drop, create the index, and then paste the query with indexWait (so leaving something like 1 second between the queries), indexWait immediatly returns.

Also, it seems to always take 10 seconds even if I add more documents.

Putting in 1.12.x

Not sure to who this issue belongs to, but I guess @danielmewes it's yours. Feel free to reassign the issue if I'm wrong.

[danielmewes]

I can reproduce this.
It's pretty weird actually.
If I issue another indexWait('field') on a different connection while the first one is waiting, the other one returns immediately. I can also use the index in a query after roughly 1 second (i.e. r.table('test').getAll(10, {index: 'field'}) works).

[neumino]

@danielmewes I've also see something interesting but that I've seen it only with rethinkdbdash.
I tried a few times witht he data explorer but without success.

If I do a indexCreate query, then an indexWait query and then a getAll query with the secondary index, I sometime get an error that the index is not ready.

I haven't tried to reproduce it with the official driver though, but I don't think this is a bug in my driver.

[danielmewes]

Ok so the 10 seconds duration is because that's the polling interval for indexWait().

From src/rdb_protocol/terms/sindex.cc:

/* We wait 10 seconds between polls to the indexes. */
int64_t poll_ms = 10000;
[...]
class sindex_wait_term_t : public op_term_t {
    [...]
    virtual counted_t<val_t> eval_impl(scope_env_t *env, UNUSED eval_flags_t flags) {
        [...]
        for (;;) {
            counted_t<const datum_t> statuses =
                table->sindex_status(env->env, sindexes);
            if (all_ready(statuses)) {
                return new_val(statuses);
            } else {
                nap(poll_ms, env->env->interruptor);
            }
        }
    }
    [...]

[danielmewes]

The reason for why you didn't see it with 1.11 is very likely that sindex creation now uses hard durability (it was part of the fix for #2071). That means that it's waiting for i/o, which it didn't do in 1.11. As a consequence, when you run indexWait() immediately after the indexCreate(), it will have a much higher chance of not being finished constructing yet. And then indexWait() will wait for 10 seconds before trying again.

I think we might want to change how the polling period works (poll more frequently initially, and then increase up to a maximum of 10s or something), but apart from that this doesn't seem to be a bug.

[danielmewes]

The thing where you can't use an index even after sindexWait() returned is clearly a bug, though unrelated to the 10s duration.

[neumino]

The script below throws something like one out of four times.

RqlRuntimeError: Index `field` was accessed before its construction was finished. in:
r.table("test").getAll(0, {index: "field"})

var r = require('./js');


r.connect({}, function(error, conn) {
    if (error) throw error;

    r.table("test").indexDrop("field").run(conn, function(error, result) {
        r.table("test").indexCreate("field").run(conn, function(error, result) {
            if (error) throw error;

            r.table("test").indexWait("field").run(conn, function(error, result) {
                if (error) throw error;

                r.table("test").getAll(0, {index: "field"}).run(conn, function(error, result) {
                    if (error) throw error;
                    conn.close();
                })
            })
        })
    })
});

[nviennot]

Related: #2179

[danielmewes]

The fix for both the broken indexWait() and the problem that indexWait() frequently takes 10 seconds is in code review 1375 by @mlucy .

[danielmewes]

The fix is merged into next (6fee468) and v1.12.x (effee21).

It will be part of RethinkDB 1.12.1.