MDEV-35343 DML debug logging

Usage:

mtr --mysqld=--debug=d,dml,query:i:o,/tmp/dml.log

Example output:

T@6    : dispatch_command: query: insert into t1 values ('a')
T@6    : handler::ha_write_row: exit: INSERT: t1(a) = 0
T@6    : dispatch_command: query: alter ignore table t1 add unique index (data)
T@6    : handler::ha_write_row: exit: INSERT: t1(a) = 0
T@6    : dispatch_command: query: alter ignore table t1 add unique index (data)
T@6    : handler::ha_write_row: exit: INSERT: t1(a) = 0

T@6    : dispatch_command: query: replace into t1 values ('b'), ('c'), ('a'), ('b')
T@6    : handler::ha_write_row: exit: INSERT: t1(b) = 0
T@6    : handler::ha_write_row: exit: INSERT: t1(c) = 0
T@6    : handler::ha_write_row: exit: INSERT: t1(a) = 121
T@6    : write_record: exit: DELETE: t1(a) = 0
T@6    : handler::ha_write_row: exit: INSERT: t1(a) = 0
T@6    : handler::ha_write_row: exit: INSERT: t1(b) = 121
T@6    : write_record: exit: DELETE: t1(b) = 0
T@6    : handler::ha_write_row: exit: INSERT: t1(b) = 0

sql/filesort.cc

@@ -634,13 +634,6 @@ static uchar *read_buffpek_from_file(IO_CACHE *buffpek_pointers, uint count,
 }
 
 #ifndef DBUG_OFF
-
-/* Buffer where record is returned */
-char dbug_print_row_buff[512];
-
-/* Temporary buffer for printing a column */
-char dbug_print_row_buff_tmp[512];
-
 /*
   Print table's current row into a buffer and return a pointer to it.
 
@@ -653,20 +646,35 @@ char dbug_print_row_buff_tmp[512];
   Only columns in table->read_set are printed
 */
 
-const char* dbug_print_table_row(TABLE *table)
+const char* dbug_print_row(TABLE *table, const uchar *rec, bool print_names)
 {
   Field **pfield;
-  String tmp(dbug_print_row_buff_tmp,
+  const size_t alloc_size= 512;
-             sizeof(dbug_print_row_buff_tmp),&my_charset_bin);
+  char *row_buff= (char *) alloc_root(&table->mem_root, alloc_size);
+  char *row_buff_tmp= (char *) alloc_root(&table->mem_root, alloc_size);
+  String tmp(row_buff_tmp, alloc_size, &my_charset_bin);
+  String output(row_buff, alloc_size, &my_charset_bin);
 
-  String output(dbug_print_row_buff, sizeof(dbug_print_row_buff),
+  auto move_back_lambda= [table, rec]() mutable {
-                &my_charset_bin);
+    table->move_fields(table->field, table->record[0], rec);
+  };
+  auto move_back_guard= make_scope_exit(move_back_lambda, false);
+
+  if (rec != table->record[0])
+  {
+    table->move_fields(table->field, rec, table->record[0]);
+    move_back_guard.engage();
+  }
+
+  SCOPE_VALUE(table->read_set, (table->read_set && table->write_set) ?
+                                table->write_set : table->read_set);
 
   output.length(0);
   output.append(table->alias);
   output.append("(");
   bool first= true;
-
+  if (print_names)
+  {
     for (pfield= table->field; *pfield ; pfield++)
     {
       if (table->read_set && !bitmap_is_set(table->read_set, (*pfield)->field_index))
@@ -675,15 +683,16 @@ const char* dbug_print_table_row(TABLE *table)
       if (first)
         first= false;
       else
-      output.append(",");
+        output.append(", ");
 
       output.append((*pfield)->field_name.str ?
                     (*pfield)->field_name.str: "NULL");
     }
 
     output.append(")=(");
-
     first= true;
+  }
+
   for (pfield= table->field; *pfield ; pfield++)
   {
     Field *field=  *pfield;
@@ -694,7 +703,7 @@ const char* dbug_print_table_row(TABLE *table)
     if (first)
       first= false;
     else
-      output.append(",");
+      output.append(", ");
 
     if (field->is_null())
       output.append("NULL");
@@ -713,12 +722,9 @@ const char* dbug_print_table_row(TABLE *table)
 }
 
 
-const char* dbug_print_row(TABLE *table, uchar *rec)
+const char* dbug_print_table_row(TABLE *table)
 {
-  table->move_fields(table->field, rec, table->record[0]);
+  return dbug_print_row(table, table->record[0]);
-  const char* ret= dbug_print_table_row(table);
-  table->move_fields(table->field, table->record[0], rec);
-  return ret;
 }
 
 

sql/handler.cc

@@ -7350,6 +7350,7 @@ int handler::ha_write_row(const uchar *buf)
 
   TABLE_IO_WAIT(tracker, PSI_TABLE_WRITE_ROW, MAX_KEY, error,
                       { error= write_row(buf); })
+  DBUG_PRINT("dml", ("INSERT: %s = %d", dbug_print_row(table, buf, false), error));
 
   MYSQL_INSERT_ROW_DONE(error);
   if (likely(!error))
@@ -7410,6 +7411,8 @@ int handler::ha_update_row(const uchar *old_data, const uchar *new_data)
 
   TABLE_IO_WAIT(tracker, PSI_TABLE_UPDATE_ROW, active_index, 0,
                       { error= update_row(old_data, new_data);})
+  DBUG_PRINT("dml", ("UPDATE: %s => %s = %d", dbug_print_row(table, old_data, false),
+                     dbug_print_row(table, new_data, false), error));
 
   MYSQL_UPDATE_ROW_DONE(error);
   if (likely(!error))
@@ -7489,6 +7492,7 @@ int handler::ha_delete_row(const uchar *buf)
 
   TABLE_IO_WAIT(tracker, PSI_TABLE_DELETE_ROW, active_index, error,
     { error= delete_row(buf);})
+  DBUG_PRINT("dml", ("DELETE: %s = %d", dbug_print_row(table, buf, false), error));
   MYSQL_DELETE_ROW_DONE(error);
   if (likely(!error))
   {

sql/handler.h

@@ -5322,4 +5322,8 @@ bool non_existing_table_error(int error);
 
 int get_select_field_pos(Alter_info *alter_info, int select_field_count,
                          bool versioned);
+
+#ifndef DBUG_OFF
+const char* dbug_print_row(TABLE *table, const uchar *rec, bool print_names= true);
+#endif /* DBUG_OFF */
 #endif /* HANDLER_INCLUDED */