DB-777 when a tokudb lock timeout occurs print info about the conflicting queries to the error log

2 files changed, 43 insertions, 2 deletions

diff --git a/storage/tokudb/hatoku_defines.h b/storage/tokudb/hatoku_defines.h
index 22a6c780c19..d5f8ef26efd 100644
--- a/storage/tokudb/hatoku_defines.h
+++ b/storage/tokudb/hatoku_defines.h
@@ -161,6 +161,8 @@ PATENT RIGHTS GRANT:
 #define TOKU_INCLUDE_UPSERT 1
 #if defined(MARIADB_BASE_VERSION)
 #define TOKU_INCLUDE_EXTENDED_KEYS 1
+#else
+#define TOKU_INCLUDE_LOCK_TIMEOUT_QUERY_STRING 1
 #endif
 #define TOKU_INCLUDE_HANDLERTON_HANDLE_FATAL_SIGNAL 0
 
diff --git a/storage/tokudb/hatoku_hton.cc b/storage/tokudb/hatoku_hton.cc
index 42f2fddfabf..640869ce047 100644
--- a/storage/tokudb/hatoku_hton.cc
+++ b/storage/tokudb/hatoku_hton.cc
@@ -1961,6 +1961,33 @@ static int tokudb_fractal_tree_block_map_done(void *p) {
     return 0;
 }
 
+#if TOKU_INCLUDE_LOCK_TIMEOUT_QUERY_STRING
+struct tokudb_search_txn_extra {
+    bool match_found;
+    uint64_t match_txn_id;
+    uint64_t match_client_id;
+};
+
+static int tokudb_search_txn_callback(uint64_t txn_id, uint64_t client_id, iterate_row_locks_callback iterate_locks, void *locks_extra, void *extra) {
+    struct tokudb_search_txn_extra *e = reinterpret_cast<struct tokudb_search_txn_extra *>(extra);
+    if (e->match_txn_id == txn_id) {
+        e->match_found = true;
+        e->match_client_id = client_id;
+        return 1;
+    }
+    return 0;
+}
+
+static bool tokudb_txn_id_to_client_id(THD *thd, uint64_t blocking_txnid, uint64_t *blocking_client_id) {
+    struct tokudb_search_txn_extra e = { false, blocking_txnid, 0};
+    (void) db_env->iterate_live_transactions(db_env, tokudb_search_txn_callback, &e);
+    if (e.match_found) {
+        *blocking_client_id = e.match_client_id;
+    }
+    return e.match_found;
+}
+#endif
+
 static void tokudb_pretty_key(const DB *db, const DBT *key, const char *default_key, String *out) {
     if (key->data == NULL) {
         out->append(default_key);
@@ -2010,8 +2037,9 @@ static void tokudb_lock_timeout_callback(DB *db, uint64_t requesting_txnid, cons
         // generate a JSON document with the lock timeout info
         String log_str;
         log_str.append("{");
+        uint64_t mysql_thread_id = thd->thread_id;
         log_str.append("\"mysql_thread_id\":");
-        log_str.append_ulonglong(thd->thread_id);
+        log_str.append_ulonglong(mysql_thread_id);
         log_str.append(", \"dbname\":");
         log_str.append("\""); log_str.append(tokudb_get_index_name(db)); log_str.append("\"");
         log_str.append(", \"requesting_txnid\":");
@@ -2051,7 +2079,18 @@ static void tokudb_lock_timeout_callback(DB *db, uint64_t requesting_txnid, cons
         }
         // dump to stderr
         if (lock_timeout_debug & 2) {
-            sql_print_error("%s: %s", tokudb_hton_name, log_str.c_ptr());
+            sql_print_error("%s: lock timeout %s", tokudb_hton_name, log_str.c_ptr());
+            LEX_STRING *qs = thd_query_string(thd);
+            sql_print_error("%s: requesting_thread_id:%" PRIu64 " q:%.*s", tokudb_hton_name, mysql_thread_id, (int) qs->length, qs->str);
+#if TOKU_INCLUDE_LOCK_TIMEOUT_QUERY_STRING
+            uint64_t blocking_thread_id = 0;
+            if (tokudb_txn_id_to_client_id(thd, blocking_txnid, &blocking_thread_id)) {
+                String blocking_qs;
+                if (get_thread_query_string(blocking_thread_id, blocking_qs) == 0) {
+                    sql_print_error("%s: blocking_thread_id:%" PRIu64 " q:%.*s", tokudb_hton_name, blocking_thread_id, blocking_qs.length(), blocking_qs.c_ptr());
+                }
+            }
+#endif
         }
     }
 }