Tokutek/mysql56#54 fix to tokudb::external_lock for the alter table assert bug, plus a rewrite of the tokudb debug tracing

3 files changed, 72 insertions, 52 deletions

diff --git a/storage/tokudb/ha_tokudb.cc b/storage/tokudb/ha_tokudb.cc
index 55a1617a81c..8f5452c352e 100644
--- a/storage/tokudb/ha_tokudb.cc
+++ b/storage/tokudb/ha_tokudb.cc
@@ -1324,7 +1324,7 @@ int ha_tokudb::open_main_dictionary(const char* name, bool is_read_only, DB_TXN*
     }
     
     if (tokudb_debug & TOKUDB_DEBUG_OPEN) {
-        TOKUDB_TRACE("open:%s:file=%p", newname, share->file);
+        TOKUDB_HANDLER_TRACE("open:%s:file=%p", newname, share->file);
     }
 
     error = 0;
@@ -1376,7 +1376,7 @@ int ha_tokudb::open_secondary_dictionary(DB** ptr, KEY* key_info, const char* na
         goto cleanup;
     }
     if (tokudb_debug & TOKUDB_DEBUG_OPEN) {
-        TOKUDB_TRACE("open:%s:file=%p", newname, *ptr);
+        TOKUDB_HANDLER_TRACE("open:%s:file=%p", newname, *ptr);
     }
 cleanup:
     if (error) {
@@ -1848,7 +1848,7 @@ int ha_tokudb::open(const char *name, int mode, uint test_if_locked) {
     ref_length = share->ref_length;     // If second open
     
     if (tokudb_debug & TOKUDB_DEBUG_OPEN) {
-        TOKUDB_TRACE("tokudbopen:%p:share=%p:file=%p:table=%p:table->s=%p:%d", 
+        TOKUDB_HANDLER_TRACE("tokudbopen:%p:share=%p:file=%p:table=%p:table->s=%p:%d", 
                      this, share, share->file, table, table->s, share->use_count);
     }
 
@@ -2145,7 +2145,7 @@ int ha_tokudb::close(void) {
 int ha_tokudb::__close() {
     TOKUDB_HANDLER_DBUG_ENTER("");
     if (tokudb_debug & TOKUDB_DEBUG_OPEN) 
-        TOKUDB_TRACE("close:%p", this);
+        TOKUDB_HANDLER_TRACE("close:%p", this);
     tokudb_my_free(rec_buff);
     tokudb_my_free(rec_update_buff);
     tokudb_my_free(blob_buff);
@@ -4860,7 +4860,7 @@ int ha_tokudb::index_read(uchar * buf, const uchar * key, uint key_len, enum ha_
         }
         break;
     default:
-        TOKUDB_TRACE("unsupported:%d", find_flag);
+        TOKUDB_HANDLER_TRACE("unsupported:%d", find_flag);
         error = HA_ERR_UNSUPPORTED;
         break;
     }
@@ -4870,7 +4870,7 @@ int ha_tokudb::index_read(uchar * buf, const uchar * key, uint key_len, enum ha_
     }
     
     if (error && (tokudb_debug & TOKUDB_DEBUG_ERROR)) {
-        TOKUDB_TRACE("error:%d:%d", error, find_flag);
+        TOKUDB_HANDLER_TRACE("error:%d:%d", error, find_flag);
     }
     trx->stmt_progress.queried++;
     track_progress(thd);
@@ -6005,17 +6005,15 @@ int ha_tokudb::acquire_table_lock (DB_TXN* trans, TABLE_LOCK_TYPE lt) {
         goto cleanup;
     }
     else if (lt == lock_write) {
-        if (tokudb_debug & TOKUDB_DEBUG_LOCK)
-            TOKUDB_TRACE("%s", __FUNCTION__);
         for (uint i = 0; i < curr_num_DBs; i++) {
             DB* db = share->key_file[i];
             error = db->pre_acquire_table_lock(db, trans);
             if (error == EINVAL) 
-                TOKUDB_TRACE("%s %d db=%p trans=%p", __FUNCTION__, i, db, trans);
+                TOKUDB_HANDLER_TRACE("%d db=%p trans=%p", i, db, trans);
             if (error) break;
         }
         if (tokudb_debug & TOKUDB_DEBUG_LOCK)
-            TOKUDB_TRACE("%s error=%d", __FUNCTION__, error);
+            TOKUDB_HANDLER_TRACE("error=%d", error);
         if (error) goto cleanup;
     }
     else {
@@ -6057,7 +6055,7 @@ int ha_tokudb::create_txn(THD* thd, tokudb_trx_data* trx) {
             goto cleanup;
         }
         if (tokudb_debug & TOKUDB_DEBUG_TXN) {
-            TOKUDB_TRACE("just created master %p", trx->all);
+            TOKUDB_HANDLER_TRACE("trx %p just created master %p", trx, trx->all);
         }
         trx->sp_level = trx->all;
         trans_register_ha(thd, true, tokudb_hton);
@@ -6065,7 +6063,7 @@ int ha_tokudb::create_txn(THD* thd, tokudb_trx_data* trx) {
     DBUG_PRINT("trans", ("starting transaction stmt"));
     if (trx->stmt) { 
         if (tokudb_debug & TOKUDB_DEBUG_TXN) {
-            TOKUDB_TRACE("warning:stmt=%p", trx->stmt);
+            TOKUDB_HANDLER_TRACE("warning:stmt=%p", trx->stmt);
         }
     }
     uint32_t txn_begin_flags;
@@ -6094,7 +6092,7 @@ int ha_tokudb::create_txn(THD* thd, tokudb_trx_data* trx) {
     }
     trx->sub_sp_level = trx->stmt;
     if (tokudb_debug & TOKUDB_DEBUG_TXN) {
-        TOKUDB_TRACE("just created stmt %p %p", trx->sp_level, trx->stmt);
+        TOKUDB_HANDLER_TRACE("trx %p just created stmt %p %p", trx, trx->sp_level, trx->stmt);
     }
     reset_stmt_progress(&trx->stmt_progress);
     trans_register_ha(thd, false, tokudb_hton);
@@ -6126,9 +6124,11 @@ static const char *lock_type_str(int lock_type) {
 //      error otherwise
 //
 int ha_tokudb::external_lock(THD * thd, int lock_type) {
-    TOKUDB_HANDLER_DBUG_ENTER("cmd=%d %d %s", thd_sql_command(thd), lock_type, lock_type_str(lock_type));
+    TOKUDB_HANDLER_DBUG_ENTER("cmd %d lock %d %s %s", thd_sql_command(thd), lock_type, lock_type_str(lock_type), share->table_name);
     if (tokudb_debug & TOKUDB_DEBUG_LOCK)
-        TOKUDB_TRACE("%s cmd=%d %d %s", __FUNCTION__, thd_sql_command(thd), lock_type, lock_type_str(lock_type));
+        TOKUDB_HANDLER_TRACE("cmd %d lock %d %s %s", thd_sql_command(thd), lock_type, lock_type_str(lock_type), share->table_name);
+    if (0)
+        TOKUDB_HANDLER_TRACE("q %s", thd->query());
 
     int error = 0;
     tokudb_trx_data *trx = NULL;
@@ -6137,6 +6137,9 @@ int ha_tokudb::external_lock(THD * thd, int lock_type) {
         error = create_tokudb_trx_data_instance(&trx);
         if (error) { goto cleanup; }
         thd_data_set(thd, tokudb_hton->slot, trx);
+        if (tokudb_debug & TOKUDB_DEBUG_TXN) {
+            TOKUDB_HANDLER_TRACE("set trx %p", trx);
+        }
     }
     if (trx->all == NULL) {
         trx->sp_level = NULL;
@@ -6147,12 +6150,18 @@ int ha_tokudb::external_lock(THD * thd, int lock_type) {
             use_write_locks = true;
         }
         if (!trx->tokudb_lock_count++) {
-            assert(trx->stmt == 0);
-            transaction = NULL;    // Safety
-            error = create_txn(thd, trx);
-            if (error) {
-                trx->tokudb_lock_count--;  // We didn't get the lock
-                goto cleanup;
+            if (trx->stmt) {
+                if (tokudb_debug & TOKUDB_DEBUG_TXN) {
+                    TOKUDB_HANDLER_TRACE("stmt already set %p %p %p %p", trx->all, trx->stmt, trx->sp_level, trx->sub_sp_level);
+                }
+            } else {
+                assert(trx->stmt == 0);
+                transaction = NULL;    // Safety
+                error = create_txn(thd, trx);
+                if (error) {
+                    trx->tokudb_lock_count--;  // We didn't get the lock
+                    goto cleanup;
+                }
             }
         }
         transaction = trx->sub_sp_level;
@@ -6188,11 +6197,10 @@ int ha_tokudb::external_lock(THD * thd, int lock_type) {
     }
 cleanup:
     if (tokudb_debug & TOKUDB_DEBUG_LOCK)
-        TOKUDB_TRACE("%s error=%d", __FUNCTION__, error);
+        TOKUDB_HANDLER_TRACE("error=%d", error);
     TOKUDB_HANDLER_DBUG_RETURN(error);
 }
 
-
 /*
   When using LOCK TABLE's external_lock is only called when the actual
   TABLE LOCK is done.
@@ -6200,12 +6208,14 @@ cleanup:
 */
 
 int ha_tokudb::start_stmt(THD * thd, thr_lock_type lock_type) {
-    TOKUDB_HANDLER_DBUG_ENTER("cmd=%d %d", thd_sql_command(thd), lock_type);
-    int error = 0;
-
+    TOKUDB_HANDLER_DBUG_ENTER("cmd %d lock %d %s", thd_sql_command(thd), lock_type, share->table_name);
+    if (0)
+        TOKUDB_HANDLER_TRACE("q %s", thd->query());
 
+    int error = 0;
     tokudb_trx_data *trx = (tokudb_trx_data *) thd_data_get(thd, tokudb_hton->slot);
     DBUG_ASSERT(trx);
+
     /*
        note that trx->stmt may have been already initialized as start_stmt()
        is called for *each table* not for each storage engine,
@@ -6216,10 +6226,13 @@ int ha_tokudb::start_stmt(THD * thd, thr_lock_type lock_type) {
         if (error) {
             goto cleanup;
         }
+        if (tokudb_debug & TOKUDB_DEBUG_TXN) {
+            TOKUDB_HANDLER_TRACE("trx %p %p %p %p %p %u", trx, trx->all, trx->stmt, trx->sp_level, trx->sub_sp_level, trx->tokudb_lock_count);
+        }
     }
     else {
         if (tokudb_debug & TOKUDB_DEBUG_TXN) {
-            TOKUDB_TRACE("trx->stmt already existed");
+            TOKUDB_HANDLER_TRACE("trx->stmt %p already existed", trx->stmt);
         }
     }
     //
@@ -6318,7 +6331,7 @@ uint32_t ha_tokudb::get_cursor_isolation_flags(enum thr_lock_type lock_type, THD
 THR_LOCK_DATA **ha_tokudb::store_lock(THD * thd, THR_LOCK_DATA ** to, enum thr_lock_type lock_type) {
     TOKUDB_HANDLER_DBUG_ENTER("lock_type=%d cmd=%d", lock_type, thd_sql_command(thd));
     if (tokudb_debug & TOKUDB_DEBUG_LOCK) {
-        TOKUDB_TRACE("%s lock_type=%d cmd=%d", __FUNCTION__, lock_type, thd_sql_command(thd));
+        TOKUDB_HANDLER_TRACE("lock_type=%d cmd=%d", lock_type, thd_sql_command(thd));
     }
 
     if (lock_type != TL_IGNORE && lock.type == TL_UNLOCK) {
@@ -6353,7 +6366,7 @@ THR_LOCK_DATA **ha_tokudb::store_lock(THD * thd, THR_LOCK_DATA ** to, enum thr_l
     }
     *to++ = &lock;
     if (tokudb_debug & TOKUDB_DEBUG_LOCK)
-        TOKUDB_TRACE("%s lock_type=%d", __FUNCTION__, lock_type);
+        TOKUDB_HANDLER_TRACE("lock_type=%d", lock_type);
     DBUG_RETURN(to);
 }
 
@@ -6574,16 +6587,16 @@ void ha_tokudb::trace_create_table_info(const char *name, TABLE * form) {
     if (tokudb_debug & TOKUDB_DEBUG_OPEN) {
         for (i = 0; i < form->s->fields; i++) {
             Field *field = form->s->field[i];
-            TOKUDB_TRACE("field:%d:%s:type=%d:flags=%x", i, field->field_name, field->type(), field->flags);
+            TOKUDB_HANDLER_TRACE("field:%d:%s:type=%d:flags=%x", i, field->field_name, field->type(), field->flags);
         }
         for (i = 0; i < form->s->keys; i++) {
             KEY *key = &form->s->key_info[i];
-            TOKUDB_TRACE("key:%d:%s:%d", i, key->name, get_key_parts(key));
+            TOKUDB_HANDLER_TRACE("key:%d:%s:%d", i, key->name, get_key_parts(key));
             uint p;
             for (p = 0; p < get_key_parts(key); p++) {
                 KEY_PART_INFO *key_part = &key->key_part[p];
                 Field *field = key_part->field;
-                TOKUDB_TRACE("key:%d:%d:length=%d:%s:type=%d:flags=%x",
+                TOKUDB_HANDLER_TRACE("key:%d:%d:length=%d:%s:type=%d:flags=%x",
                              i, p, key_part->length, field->field_name, field->type(), field->flags);
             }
         }
@@ -7447,7 +7460,7 @@ void ha_tokudb::init_auto_increment() {
         commit_txn(txn, 0);
     }
     if (tokudb_debug & TOKUDB_DEBUG_AUTO_INCREMENT) {
-        TOKUDB_TRACE("init auto increment:%lld", share->last_auto_increment);
+        TOKUDB_HANDLER_TRACE("init auto increment:%lld", share->last_auto_increment);
     }
 }
 
@@ -7480,7 +7493,7 @@ void ha_tokudb::get_auto_increment(ulonglong offset, ulonglong increment, ulongl
     }
         
     if (tokudb_debug & TOKUDB_DEBUG_AUTO_INCREMENT) {
-        TOKUDB_TRACE("get_auto_increment(%lld,%lld,%lld):got:%lld:%lld",
+        TOKUDB_HANDLER_TRACE("get_auto_increment(%lld,%lld,%lld):got:%lld:%lld",
                      offset, increment, nb_desired_values, nr, nb_desired_values);
     }
     *first_value = nr;
diff --git a/storage/tokudb/hatoku_defines.h b/storage/tokudb/hatoku_defines.h
index 5faba56817a..88758ae8c4c 100644
--- a/storage/tokudb/hatoku_defines.h
+++ b/storage/tokudb/hatoku_defines.h
@@ -228,7 +228,7 @@ extern ulong tokudb_debug;
 #define TOKUDB_DEBUG_ANALYZE (1<<15)
 
 #define TOKUDB_TRACE(f, ...) \
-    fprintf(stderr, "%u %s:%u " f "\n", my_tid(), __FILE__, __LINE__, ##__VA_ARGS__);
+    fprintf(stderr, "%u %s:%u %s " f "\n", my_tid(), __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__);
 
 static inline unsigned int my_tid() {
     return (unsigned int)toku_os_gettid();
@@ -237,7 +237,7 @@ static inline unsigned int my_tid() {
 #define TOKUDB_DBUG_ENTER(f, ...)      \
 { \
     if (tokudb_debug & TOKUDB_DEBUG_ENTER) { \
-        TOKUDB_TRACE("%s " f, __FUNCTION__, ##__VA_ARGS__);      \
+        TOKUDB_TRACE(f, ##__VA_ARGS__);       \
     } \
 } \
     DBUG_ENTER(__FUNCTION__);
@@ -246,15 +246,18 @@ static inline unsigned int my_tid() {
 { \
     int rr = (r); \
     if ((tokudb_debug & TOKUDB_DEBUG_RETURN) || (rr != 0 && (tokudb_debug & TOKUDB_DEBUG_ERROR))) { \
-        TOKUDB_TRACE("%s return %d", __FUNCTION__, rr); \
+        TOKUDB_TRACE("return %d", rr); \
     } \
     DBUG_RETURN(rr); \
 }
 
+#define TOKUDB_HANDLER_TRACE(f, ...) \
+    fprintf(stderr, "%u %p %s:%u ha_tokudb::%s " f "\n", my_tid(), this, __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__);
+
 #define TOKUDB_HANDLER_DBUG_ENTER(f, ...)      \
 { \
     if (tokudb_debug & TOKUDB_DEBUG_ENTER) { \
-        fprintf(stderr, "%u %p %s:%u ha_tokudb::%s " f "\n", my_tid(), this, __FILE__, __LINE__, __FUNCTION__, ##__VA_ARGS__); \
+        TOKUDB_HANDLER_TRACE(f, ##__VA_ARGS__); \
     } \
 } \
     DBUG_ENTER(__FUNCTION__);
@@ -263,14 +266,14 @@ static inline unsigned int my_tid() {
 { \
     int rr = (r); \
     if ((tokudb_debug & TOKUDB_DEBUG_RETURN) || (rr != 0 && (tokudb_debug & TOKUDB_DEBUG_ERROR))) { \
-        fprintf(stderr, "%u %p %s:%u ha_tokudb::%s return %d" "\n", my_tid(), this, __FILE__, __LINE__, __FUNCTION__, rr); \
+        TOKUDB_HANDLER_TRACE("return %d", rr); \
     } \
     DBUG_RETURN(rr); \
 }
 
 #define TOKUDB_DBUG_DUMP(s, p, len) \
 { \
-    TOKUDB_TRACE("%s:%s", __FUNCTION__, s); \
+    TOKUDB_TRACE("%s", s); \
     uint i;                                                             \
     for (i=0; i<len; i++) {                                             \
         fprintf(stderr, "%2.2x", ((uchar*)p)[i]);                       \
diff --git a/storage/tokudb/hatoku_hton.cc b/storage/tokudb/hatoku_hton.cc
index 11d21921c0c..9a85e20bbd1 100644
--- a/storage/tokudb/hatoku_hton.cc
+++ b/storage/tokudb/hatoku_hton.cc
@@ -381,7 +381,7 @@ static int tokudb_init_func(void *p) {
     r = db_env->set_flags(db_env, tokudb_env_flags, 1);
     if (r) { // QQQ
         if (tokudb_debug & TOKUDB_DEBUG_INIT) 
-            TOKUDB_TRACE("%s:WARNING: flags=%x r=%d", __FUNCTION__, tokudb_env_flags, r); 
+            TOKUDB_TRACE("WARNING: flags=%x r=%d", tokudb_env_flags, r); 
         // goto error;
     }
 
@@ -452,17 +452,17 @@ static int tokudb_init_func(void *p) {
     
     uint32_t gbytes, bytes; int parts;
     r = db_env->get_cachesize(db_env, &gbytes, &bytes, &parts);
-    if (r == 0) 
-        if (tokudb_debug & TOKUDB_DEBUG_INIT) 
-            TOKUDB_TRACE("%s:tokudb_cache_size=%lld", __FUNCTION__, ((unsigned long long) gbytes << 30) + bytes);
+    if (tokudb_debug & TOKUDB_DEBUG_INIT) 
+        TOKUDB_TRACE("tokudb_cache_size=%lld r=%d", ((unsigned long long) gbytes << 30) + bytes, r);
 
     if (db_env->set_redzone) {
         r = db_env->set_redzone(db_env, tokudb_fs_reserve_percent);
-        if (r && (tokudb_debug & TOKUDB_DEBUG_INIT))
-            TOKUDB_TRACE("%s:%d r=%d", __FUNCTION__, __LINE__, r);
+        if (tokudb_debug & TOKUDB_DEBUG_INIT)
+            TOKUDB_TRACE("set_redzone r=%d", r);
     }
 
-    if (tokudb_debug & TOKUDB_DEBUG_INIT) TOKUDB_TRACE("%s:env open:flags=%x", __FUNCTION__, tokudb_init_flags);
+    if (tokudb_debug & TOKUDB_DEBUG_INIT) 
+        TOKUDB_TRACE("env open:flags=%x", tokudb_init_flags);
 
     r = db_env->set_generate_row_callback_for_put(db_env,generate_row_for_put);
     assert(r == 0);
@@ -476,7 +476,8 @@ static int tokudb_init_func(void *p) {
 
     r = db_env->open(db_env, tokudb_home, tokudb_init_flags, S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH);
 
-    if (tokudb_debug & TOKUDB_DEBUG_INIT) TOKUDB_TRACE("%s:env opened:return=%d", __FUNCTION__, r);
+    if (tokudb_debug & TOKUDB_DEBUG_INIT) 
+        TOKUDB_TRACE("env opened:return=%d", r);
 
     if (r) {
         DBUG_PRINT("info", ("env->open %d", r));
@@ -570,6 +571,9 @@ static int tokudb_close_connection(handlerton * hton, THD * thd) {
     int error = 0;
     tokudb_trx_data* trx = NULL;
     trx = (tokudb_trx_data *) thd_data_get(thd, tokudb_hton->slot);
+    if (tokudb_debug & TOKUDB_DEBUG_TXN) {
+        TOKUDB_TRACE("trx %p", trx);
+    }
     if (trx && trx->checkpoint_lock_taken) {
         error = db_env->checkpointing_resume(db_env);
     }
@@ -662,7 +666,7 @@ static int tokudb_commit(handlerton * hton, THD * thd, bool all) {
     DB_TXN *this_txn = *txn;
     if (this_txn) {
         if (tokudb_debug & TOKUDB_DEBUG_TXN) {
-            TOKUDB_TRACE("commit %u %p", all, this_txn);
+            TOKUDB_TRACE("commit trx %u trx %p txn %p", all, trx, this_txn);
         }
         // test hook to induce a crash on a debug build
         DBUG_EXECUTE_IF("tokudb_crash_commit_before", DBUG_SUICIDE(););
@@ -691,7 +695,7 @@ static int tokudb_rollback(handlerton * hton, THD * thd, bool all) {
     DB_TXN *this_txn = *txn;
     if (this_txn) {
         if (tokudb_debug & TOKUDB_DEBUG_TXN) {
-            TOKUDB_TRACE("rollback %u %p", all, this_txn);
+            TOKUDB_TRACE("rollback %u trx %p txn %p", all, trx, this_txn);
         }
         tokudb_cleanup_handlers(trx, this_txn);
         abort_txn_with_progress(this_txn, thd);
@@ -868,7 +872,7 @@ static int tokudb_discover(handlerton *hton, THD* thd, const char *db, const cha
 
 static int tokudb_discover2(handlerton *hton, THD* thd, const char *db, const char *name, bool translate_name,
                             uchar **frmblob, size_t *frmlen) {
-    TOKUDB_DBUG_ENTER("");
+    TOKUDB_DBUG_ENTER("%s %s", db, name);
     int error;
     DB* status_db = NULL;
     DB_TXN* txn = NULL;
@@ -1119,7 +1123,7 @@ static void tokudb_cleanup_log_files(void) {
         for (np = names; *np; ++np) {
 #if 1
             if (tokudb_debug)
-                TOKUDB_TRACE("%s:cleanup:%s", __FUNCTION__, *np);
+                TOKUDB_TRACE("cleanup:%s", *np);
 #else
             my_delete(*np, MYF(MY_WME));
 #endif