Issue 6347 - better fix for desyncronized vlv cache

ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.c

@@ -149,7 +149,7 @@ static inline void log_stack(int loglvl)
     }
 }
 
-void dbi_str(MDB_cursor *cursor, int dbi, char *dbistr)
+void dbi_str(MDB_cursor *cursor, int dbi, char dbistr[DBISTRMAXSIZE])
 {
     const char *str = "?";
     dbmdb_dbi_t * dbi1;
@@ -161,7 +161,7 @@ void dbi_str(MDB_cursor *cursor, int dbi, char *dbistr)
     if (dbi1 && dbi1->dbname) {
         str = dbi1->dbname;
     }
-    PR_snprintf(dbistr, DBGVAL2STRMAXSIZE, "dbi: %d <%s>", dbi, str);
+    PR_snprintf(dbistr, DBISTRMAXSIZE, "dbi: %d <%s>", dbi, str);
 }
 
 #ifdef DBMDB_DEBUG
@@ -297,7 +297,7 @@ dbg_mdb_cursor_open(const char *file, int lineno, const char *funcname, MDB_txn
 {
     int rc = mdb_cursor_open(txn, dbi, cursor);
     if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
-        char dbistr[DBGVAL2STRMAXSIZE];
+        char dbistr[DBISTRMAXSIZE];
         dbi_str(NULL, dbi, dbistr);
         dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_FORCE, "mdb_cursor_open(txn: %p, %s, cursor: %p)=%d", txn, dbistr, *cursor, rc);
     }
@@ -318,7 +318,7 @@ void
 dbg_mdb_cursor_close(const char *file, int lineno, const char *funcname, MDB_cursor *cursor)
 {
     if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, 0, cursor)) {
-        char dbistr[DBGVAL2STRMAXSIZE];
+        char dbistr[DBISTRMAXSIZE];
         dbi_str(cursor, 0, dbistr);
         mdb_cursor_close(cursor);
         dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_FORCE, "mdb_cursor_close(cursor: %p) %s", cursor, dbistr);
@@ -336,7 +336,7 @@ __dbg_mdb_cursor_get(const char *file, int lineno, const char *funcname, int log
     char datastr[DBGVAL2STRMAXSIZE];
     char flagsstr[DBGVAL2STRMAXSIZE];
     char cursorstr[DBGVAL2STRMAXSIZE];
-    char dbistr[DBGVAL2STRMAXSIZE];
+    char dbistr[DBISTRMAXSIZE];
     int sl = 0;
     if (dbg_should_log(loglvl, 0, cursor)) {
         dbi_str(cursor, 0, dbistr);
@@ -376,7 +376,7 @@ if (data->mv_size <= 511) return 0;
         char keystr[DBGVAL2STRMAXSIZE];
         char datastr[DBGVAL2STRMAXSIZE];
         char flagsstr[DBGVAL2STRMAXSIZE];
-        char dbistr[DBGVAL2STRMAXSIZE];
+        char dbistr[DBISTRMAXSIZE];
 
         dbi_str(NULL, dbi, dbistr);
         dbgval2str(keystr, sizeof keystr, key);
@@ -394,7 +394,7 @@ dbg_mdb_get(const char *file, int lineno, const char *funcname, MDB_txn *txn, MD
 {
     char keystr[DBGVAL2STRMAXSIZE];
     char datastr[DBGVAL2STRMAXSIZE];
-    char dbistr[DBGVAL2STRMAXSIZE];
+    char dbistr[DBISTRMAXSIZE];
 
     if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
         dbi_str(NULL, dbi, dbistr);
@@ -419,7 +419,7 @@ dbg_mdb_del(const char *file, int lineno, const char *funcname, MDB_txn *txn, MD
     if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
         char keystr[DBGVAL2STRMAXSIZE];
         char datastr[DBGVAL2STRMAXSIZE];
-        char dbistr[DBGVAL2STRMAXSIZE];
+        char dbistr[DBISTRMAXSIZE];
 
         dbi_str(NULL, dbi, dbistr);
         dbgval2str(keystr, sizeof keystr, key);
@@ -438,7 +438,7 @@ dbg_mdb_cursor_put(const char *file, int lineno, const char *funcname, MDB_curso
         char datastr[DBGVAL2STRMAXSIZE];
         char flagsstr[DBGVAL2STRMAXSIZE];
         char cursorstr[DBGVAL2STRMAXSIZE];
-        char dbistr[DBGVAL2STRMAXSIZE];
+        char dbistr[DBISTRMAXSIZE];
 
         dbi_str(cursor, 0, dbistr);
         dbgval2str(keystr, sizeof keystr, key);
@@ -467,32 +467,46 @@ dbg_mdb_drop(const char *file, int lineno, const char *funcname, MDB_txn *txn, M
 {
     int rc = mdb_drop(txn, dbi, del);
     if (dbg_should_log(DBGMDB_LEVEL_MDBAPI, dbi, NULL)) {
-        char dbistr[DBGVAL2STRMAXSIZE];
+        char dbistr[DBISTRMAXSIZE];
         dbi_str(NULL, dbi, dbistr);
         dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_FORCE, "mdb_drop(txn: %p, %s, del: %d)=%d", txn, dbistr, del, rc);
     }
     return rc;
 }
 
+int txn_loglvl()
+{
+    if (dbgmdb_level & DBGMDB_LEVEL_MDBAPI) {
+        return DBGMDB_LEVEL_MDBAPI;
+    }
+    if (dbgmdb_level & DBGMDB_LEVEL_TXN) {
+        return DBGMDB_LEVEL_TXN;
+    }
+    return 0;
+}
+
 int dbg_txn_begin(const char *file, int lineno, const char *funcname, MDB_env *env, MDB_txn *parent_txn, int flags, MDB_txn **txn)
 {
-    if (!(dbgmdb_level & DBGMDB_LEVEL_TXN)) {
+    int lvl = txn_loglvl();
+    if (lvl == 0) {
         return mdb_txn_begin(env, parent_txn, flags, txn);
     }
     char strflags[100];
     dbmdb_envflags2str(flags, strflags, sizeof strflags);
-    dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_BEGIN[%d]. txn_parent=%p, %s, stack is:", pthread_gettid(), parent_txn, strflags);
+    dbg_log(file, lineno, funcname, lvl, "TXN_BEGIN[%d]. txn_parent=%p, %s, stack is:", pthread_gettid(), parent_txn, strflags);
     log_stack(DBGMDB_LEVEL_TXN);
-    dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "Waiting ...\n");
+    dbg_log(file, lineno, funcname, lvl, "Waiting ...\n");
     int rc = mdb_txn_begin(env, parent_txn, flags, txn);
-    dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "Done. txn_begin(env=%p, txn_parent=%p, flags=0x%x, txn=0x%p) returned %d.",
+    dbg_log(file, lineno, funcname, lvl, "Done. txn_begin(env=%p, txn_parent=%p, flags=0x%x, txn=0x%p) returned %d.",
         env, parent_txn, flags, *txn, rc);
     return rc;
 }
 
 int dbg_txn_end(const char *file, int lineno, const char *funcname, MDB_txn *txn, int iscommit)
 {
-    if (!(dbgmdb_level & DBGMDB_LEVEL_TXN)) {
+    int lvl = txn_loglvl();
+    char *stackis = (lvl == DBGMDB_LEVEL_TXN) ? " stack is:" : "";
+    if (lvl == 0) {
         if (iscommit) {
             return mdb_txn_commit(txn);
         } else {
@@ -503,27 +517,29 @@ int dbg_txn_end(const char *file, int lineno, const char *funcname, MDB_txn *txn
     int rc = 0;
     if (iscommit) {
         rc = mdb_txn_commit(txn);
-        dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_COMMIT[%d] (txn=0x%p) returned %d. stack is:", pthread_gettid(), txn, rc);
+        dbg_log(file, lineno, funcname, lvl, "TXN_COMMIT[%d] (txn=0x%p) returned %d.%s", pthread_gettid(), txn, rc, stackis);
     } else {
         mdb_txn_abort(txn);
-        dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_ABORT[%d] (txn=0x%p). stack is:", pthread_gettid(), txn);
+        dbg_log(file, lineno, funcname, lvl, "TXN_ABORT[%d] (txn=0x%p).%s", pthread_gettid(), txn, stackis);
     }
+    if (lvl == DBGMDB_LEVEL_TXN) {
     log_stack(DBGMDB_LEVEL_TXN);
+    }
     return rc;
 }
 
 
 void dbg_txn_reset(const char *file, int lineno, const char *funcname, MDB_txn *txn)
 {
     mdb_txn_reset(txn);
-    dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_RESET[%d] (txn=0x%p). stack is:", pthread_gettid(), txn);
+    dbg_log(file, lineno, funcname, txn_loglvl(), "TXN_RESET[%d] (txn=0x%p). stack is:", pthread_gettid(), txn);
     log_stack(DBGMDB_LEVEL_TXN);
 }
 
 int dbg_txn_renew(const char *file, int lineno, const char *funcname, MDB_txn *txn)
 {
     int rc = mdb_txn_renew(txn);
-    dbg_log(file, lineno, funcname, DBGMDB_LEVEL_TXN, "TXN_RENEW[%d] (txn=0x%p) returned %d. stack is:", pthread_gettid(), txn, rc);
+    dbg_log(file, lineno, funcname, txn_loglvl(), "TXN_RENEW[%d] (txn=0x%p) returned %d. stack is:", pthread_gettid(), txn, rc);
     log_stack(DBGMDB_LEVEL_TXN);
     return rc;
 }
@@ -533,7 +549,7 @@ void dbmdb_log_dbi_set_fn(const char *file, int lineno, const char *funcname, co
     Dl_info info = {0};
     dladdr(fn, &info);
     /* Cannot use dbi_str here because slot is not yet up2date (so dbname is an argument) */
-    dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI,  "%s(txn=0x%p, dbi=%d <%s>, fn=0x%p <%s>)\n", action, txn, dbi, dbname, fn, info.dli_sname);
+    dbg_log(file, lineno, funcname, DBGMDB_LEVEL_MDBAPI, "%s(txn=0x%p, dbi=%d <%s>, fn=0x%p <%s>)\n", action, txn, dbi, dbname, fn, info.dli_sname);
 }
 
 int dbg_mdb_bulkop_cursor_get(const char *file, int lineno, const char *funcname, MDB_cursor *cursor, MDB_val *key, MDB_val *data, MDB_cursor_op op)

ldap/servers/slapd/back-ldbm/db-mdb/mdb_debug.h

@@ -20,11 +20,13 @@ void dbmdb_format_dbslist_info(char *info, dbmdb_dbi_t *dbi);
 
 #define DBGMDB_LEVEL_PRINTABLE 0xfff
 
+#define DBISTRMAXSIZE         80
 
 extern int dbgmdb_level; /* defined in mdb_debug.c */
 void dbg_log(const char *file, int lineno, const char *funcname, int loglevel, char *fmt, ...);
 void dbgval2str(char *buff, size_t bufsiz, MDB_val *val);
 void dbmdb_dbg_set_dbi_slots(dbmdb_dbi_t *slots);
+void dbi_str(MDB_cursor *cursor, int dbi, char dbistr[DBISTRMAXSIZE]);
 
 /* #define DBMDB_DEBUG 1 */
 #define DBGMDB_LEVEL_DEFAULT DBGMDB_LEVEL_MDBAPI+DBGMDB_LEVEL_TXN+DBGMDB_LEVEL_IMPORT+ \

ldap/servers/slapd/back-ldbm/db-mdb/mdb_import_threads.c

@@ -3413,6 +3413,7 @@ dbmdb_add_import_index(ImportCtx_t *ctx, const char *name, IndexInfo *ii)
         }
     }
 
+    DBG_LOG(DBGMDB_LEVEL_OTHER,"Calling dbmdb_open_dbi_from_filename for %s flags = 0x%x", mii->name, dbi_flags);
     dbmdb_open_dbi_from_filename(&mii->dbi, job->inst->inst_be, mii->name, mii->ai, dbi_flags);
     avl_insert(&ctx->indexes, mii, cmp_mii, NULL);
 }

ldap/servers/slapd/back-ldbm/db-mdb/mdb_instance.c

@@ -1245,6 +1245,8 @@ int dbmdb_open_dbi_from_filename(dbmdb_dbi_t **dbi, backend *be, const char *fil
     dbi_open_ctx_t octx = {0};
     dbi_txn_t *txn = NULL;
     int rc = 0;
+    DBG_LOG(DBGMDB_LEVEL_OTHER, "dbmdb_open_dbi_from_filename: filename=%s flags=0x%x", filename, flags);
+
 
     if (ctx->readonly || (flags&MDB_RDONLY)) {
         flags &= ~MDB_CREATE;
@@ -1292,32 +1294,40 @@ int dbmdb_open_dbi_from_filename(dbmdb_dbi_t **dbi, backend *be, const char *fil
         }
     }
     if (rc) {
+        DBG_LOG(DBGMDB_LEVEL_OTHER, "returning %d", rc);
         return rc;
     }
     if (!*dbi) {
+        DBG_LOG(DBGMDB_LEVEL_OTHER, "returning MDB_NOTFOUND");
         return MDB_NOTFOUND;
     }
+    DBG_LOG(DBGMDB_LEVEL_OTHER, "So far rc = %d", rc);
     if (ai && ai->ai_key_cmp_fn != (*dbi)->cmp_fn) {
         if (! (*dbi)->cmp_fn) {
             rc = dbmdb_update_dbi_cmp_fn(ctx, *dbi, ai->ai_key_cmp_fn, NULL);
         }
         (*dbi)->cmp_fn = ai->ai_key_cmp_fn;
     }
+    DBG_LOG(DBGMDB_LEVEL_OTHER, "So far rc = %d", rc);
 
     if (((*dbi)->state.state & DBIST_DIRTY) && !(flags & MDB_OPEN_DIRTY_DBI)) {
+        DBG_LOG(DBGMDB_LEVEL_OTHER, "returning MDB_NOTFOUND");
         return MDB_NOTFOUND;
     }
     if (!rc && !((*dbi)->state.state & DBIST_DIRTY) && (flags & MDB_MARK_DIRTY_DBI)) {
            dbistate_t st = (*dbi)->state;
            st.state |= DBIST_DIRTY;
            rc = dbmdb_update_dbi_state(ctx, *dbi, &st, NULL, PR_FALSE);
     }
+    DBG_LOG(DBGMDB_LEVEL_OTHER, "So far rc = %d", rc);
     if (!rc && (flags & MDB_TRUNCATE_DBI)) {
         octx.ctx = ctx;
         octx.dbi = *dbi;
         octx.deletion_flags = 0;
+        DBG_LOG(DBGMDB_LEVEL_OTHER, "truncating db");
         rc = dbi_remove(&octx);
     }
+    DBG_LOG(DBGMDB_LEVEL_OTHER, "returning rc=%d", rc);
     return rc;
 }
 
@@ -1401,11 +1411,14 @@ int dbmdb_recno_cache_get_mode(dbmdb_recno_cache_ctx_t *rcctx)
         rc = MDB_GET(txn, rcctx->rcdbi->dbi, &rcctx->key, &rcctx->data);
         if (rc == MDB_SUCCESS) {
             rcctx->mode = RCMODE_USE_CURSOR_TXN;
+            DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_USE_CURSOR_TXN rc=0", rcdbname);
+            return rc;
         }
         if (rc != MDB_NOTFOUND) {
             /* There was an error or cache is valid.
              * Im both cases there is no need to rebuilt the cache.
              */
+            DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_UNKNOWN rc=%d", rcdbname, rc);
             return rc;
         }
     }
@@ -1415,7 +1428,9 @@ int dbmdb_recno_cache_get_mode(dbmdb_recno_cache_ctx_t *rcctx)
         TXN_ABORT(txn);
         txn = NULL;
         rcctx->mode = RCMODE_USE_SUBTXN;
+        DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_USE_SUBTXN rc=0", rcdbname);
     } else if (rc == EINVAL) {
+        DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_get_mode(%s) mode=RCMODE_USE_NEW_THREAD rc=0", rcdbname);
         rcctx->mode = RCMODE_USE_NEW_THREAD;
         rc = 0;
     }

ldap/servers/slapd/back-ldbm/db-mdb/mdb_layer.c

@@ -2108,6 +2108,7 @@ void *dbmdb_recno_cache_build(void *arg)
     int len = 0;
     int rc = 0;
 
+    DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_recno_cache_build(%s)", rcctx->rcdbname);
     /* Open/creat cache dbi */
     rc = dbmdb_open_dbi_from_filename(&rcctx->rcdbi, rcctx->cursor->be, rcctx->rcdbname, NULL, MDB_CREATE);
     slapi_ch_free_string(&rcctx->rcdbname);
@@ -2131,31 +2132,13 @@ void *dbmdb_recno_cache_build(void *arg)
             txn_ctx.flags |= DBMDB_TXNCTX_NEED_COMMIT;
         }
     }
+    if (rc == 0) {
+        rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_FIRST);
+        recno = 1;
+    }
     while (rc == 0) {
         slapi_log_err(SLAPI_LOG_DEBUG, "dbmdb_recno_cache_build", "recno=%d\n", recno);
-        if (recno % RECNO_CACHE_INTERVAL != 1) {
-            recno++;
-            rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_NEXT);
-            continue;
-        }
-        /* close the txn from time to time to avoid locking all dbi page */
-        rc = dbmdb_end_recno_cache_txn(&txn_ctx, 0);
-        rc |= dbmdb_begin_recno_cache_txn(rcctx, &txn_ctx, rcctx->dbi->dbi);
-        if (rc) {
-            break;
-        }
-        /* Reset to new cursor to the old position */
-        if (recno == 1) {
-            rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_FIRST);
-        } else {
-            rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_SET);
-            if (rc == MDB_NOTFOUND) {
-                rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_SET_RANGE);
-            }
-        }
-        if (rc) {
-            break;
-        }
+        if (recno % RECNO_CACHE_INTERVAL == 1) {
         /* Prepare the cache data */
         len = sizeof(*rce) + data.mv_size + key.mv_size;
         rce = (dbmdb_recno_cache_elmt_t*)slapi_ch_malloc(len);
@@ -2188,6 +2171,7 @@ void *dbmdb_recno_cache_build(void *arg)
             }
         }
         slapi_ch_free(&rcdata.mv_data);
+        }
         rc = MDB_CURSOR_GET(txn_ctx.cursor, &key, &data, MDB_NEXT);
         recno++;
     }
@@ -2378,26 +2362,33 @@ int dbmdb_cursor_set_recno(dbi_cursor_t *cursor, MDB_val *dbmdb_key, MDB_val *db
     }
 
     memcpy(&recno, dbmdb_key->mv_data, sizeof (dbi_recno_t));
+#ifdef DBMDB_DEBUG
+    char dbistr[DBISTRMAXSIZE];
+    dbi_str(cursor->cur, 0, dbistr);
+    DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_cursor_set_recno: recno=%d dbi=%s", recno, dbistr);
+#endif
     dbmdb_generate_recno_cache_key_by_recno(&cache_key, recno);
     rc = dbmdb_recno_cache_lookup(cursor, &cache_key, &rce);
     if (rc ==0) {
         rc = MDB_CURSOR_GET(cursor->cur, &rce->key, &rce->data, MDB_SET_RANGE);
     }
     while (rc == 0 && recno > rce->recno) {
-        DBG_LOG(DBGMDB_LEVEL_VLV, "Current record index is %d Target is %d\n", rce->recno, recno);
+        DBG_LOG(DBGMDB_LEVEL_VLV, "Current record index is %d Target is %d", rce->recno, recno);
         rce->recno++;
         rc = MDB_CURSOR_GET(cursor->cur, &rce->key, &rce->data, MDB_NEXT);
     }
+#if 0
     if (rc == MDB_NOTFOUND) {
         /* Stay on last record if there are no more records */
         rc = 0;
     }
+#endif
     if (rc == 0 && dbmdb_data->mv_size == rce->data.mv_size) {
         /* Should always be the case */
-        DBG_LOG(DBGMDB_LEVEL_VLV, "SUCCESS\n");
+        DBG_LOG(DBGMDB_LEVEL_VLV, "SUCCESS");
         memcpy(dbmdb_data->mv_data , rce->data.mv_data, dbmdb_data->mv_size);
     } else {
-        DBG_LOG(DBGMDB_LEVEL_VLV, "FAILURE: rc=%d dbmdb_data->mv_size=%d rce->data.mv_size=%d\n", rc, dbmdb_data->mv_size, rce->data.mv_size);
+        DBG_LOG(DBGMDB_LEVEL_VLV, "FAILURE: rc=%d dbmdb_data->mv_size=%d rce->data.mv_size=%d", rc, dbmdb_data->mv_size, rce->data.mv_size);
     }
 
     slapi_ch_free((void**)&rce);
@@ -2878,11 +2869,12 @@ dbmdb_public_clear_vlv_cache(Slapi_Backend *be, dbi_txn_t *txn, dbi_db_t *db)
     MDB_val ok = { 0 };
     int rc = 0;
 
+    DBG_LOG(DBGMDB_LEVEL_VLV, "dbmdb_public_clear_vlv_cache(%s)", rcdbname);
     ok.mv_data = "OK";
     ok.mv_size = 2;
     rc = dbmdb_open_dbi_from_filename(&rcdbi, be, rcdbname, NULL, 0);
     if (rc == 0) {
-        rc = MDB_DEL(TXN(txn), rcdbi->dbi, &ok, &ok);
+        rc = MDB_DEL(TXN(txn), rcdbi->dbi, &ok, NULL);
     }
     slapi_ch_free_string(&rcdbname);
     return rc;

ldap/servers/slapd/back-ldbm/db-mdb/mdb_ldif2db.c

@@ -1423,7 +1423,7 @@ _get_and_add_parent_rdns(backend *be,
         key.mv_data = &storedid;
 
         memset(&data, 0, sizeof(data));
-        rc = mdb_get(TXN(cur->txn), cur->dbi->dbi, &key, &data);
+        rc = MDB_GET(TXN(cur->txn), cur->dbi->dbi, &key, &data);
         if (rc) {
             slapi_log_err(SLAPI_LOG_ERR, "_get_and_add_parent_rdns",
                           "Failed to position cursor at ID " ID_FMT "\n", id);