MDEV-11713 Optimize DBUG_PRINT and introduce DBUG_LOG

MariaDB Server is unnecessarily evaluating the arguments of
DBUG_PRINT() macros when the label is not defined.

The macro DBUG_LOG() for C++ operator<< output which was added for
InnoDB diagnostics in MySQL 5.7 is missing from MariaDB. Unlike the
MySQL 5.7 implementation, MariaDB will avoid allocating and
initializing the output string when the label is not defined.

Introduce DBUG_OUT("crypt") and DBUG_OUT("checksum") for some InnoDB
diagnostics, replacing some use of ib::info().

dbug/dbug.c

@@ -1213,7 +1213,7 @@ void _db_return_(struct _db_stack_frame_ *_stack_frame_)
  *
  *  SYNOPSIS
  *
- *      VOID _db_pargs_(_line_, keyword)
+ *      int _db_pargs_(_line_, keyword)
  *      int _line_;
  *      char *keyword;
  *
@@ -1226,12 +1226,14 @@ void _db_return_(struct _db_stack_frame_ *_stack_frame_)
  *
  */
 
-void _db_pargs_(uint _line_, const char *keyword)
+int _db_pargs_(uint _line_, const char *keyword)
 {
   CODE_STATE *cs;
-  get_code_state_or_return;
+  get_code_state_or_return 0;
   cs->u_line= _line_;
   cs->u_keyword= keyword;
+
+  return DEBUGGING && _db_keyword_(cs, cs->u_keyword, 0);
 }
 
 
@@ -1265,27 +1267,24 @@ void _db_doprnt_(const char *format,...)
 {
   va_list args;
   CODE_STATE *cs;
+  int save_errno;
+
   get_code_state_or_return;
 
   va_start(args,format);
 
   if (!cs->locked)
     pthread_mutex_lock(&THR_LOCK_dbug);
-  if (_db_keyword_(cs, cs->u_keyword, 0))
-  {
-    int save_errno=errno;
-    DoPrefix(cs, cs->u_line);
-    if (TRACING)
-      Indent(cs, cs->level + 1);
-    else
-      (void) fprintf(cs->stack->out_file->file, "%s: ", cs->func);
-    (void) fprintf(cs->stack->out_file->file, "%s: ", cs->u_keyword);
-    DbugVfprintf(cs->stack->out_file->file, format, args);
-    DbugFlush(cs);
-    errno=save_errno;
-  }
-  else if (!cs->locked)
-    pthread_mutex_unlock(&THR_LOCK_dbug);
+  save_errno=errno;
+  DoPrefix(cs, cs->u_line);
+  if (TRACING)
+    Indent(cs, cs->level + 1);
+  else
+    (void) fprintf(cs->stack->out_file->file, "%s: ", cs->func);
+  (void) fprintf(cs->stack->out_file->file, "%s: ", cs->u_keyword);
+  DbugVfprintf(cs->stack->out_file->file, format, args);
+  DbugFlush(cs);
+  errno=save_errno;
 
   va_end(args);
 }

include/my_dbug.h

@@ -1,5 +1,5 @@
 /* Copyright (c) 2000, 2010, Oracle and/or its affiliates. 
-   Copyright (C) 2000-2011 Monty Program Ab
+   Copyright (C) 2000, 2017, MariaDB Corporation Ab
 
    This program is free software; you can redistribute it and/or modify
    it under the terms of the GNU General Public License as published by
@@ -50,7 +50,7 @@ extern  void _db_set_init_(const char *control);
 extern void _db_enter_(const char *_func_, const char *_file_, uint _line_,
                        struct _db_stack_frame_ *_stack_frame_);
 extern  void _db_return_(struct _db_stack_frame_ *_stack_frame_);
-extern  void _db_pargs_(uint _line_,const char *keyword);
+extern  int _db_pargs_(uint _line_,const char *keyword);
 extern  void _db_doprnt_(const char *format,...)
   ATTRIBUTE_FORMAT(printf, 1, 2);
 extern  void _db_dump_(uint _line_,const char *keyword,
@@ -91,7 +91,7 @@ extern  const char* _db_get_func_(void);
 #define DBUG_EVALUATE_IF(keyword,a1,a2) \
         (_db_keyword_(0,(keyword), 1) ? (a1) : (a2))
 #define DBUG_PRINT(keyword,arglist) \
-        do {_db_pargs_(__LINE__,keyword); _db_doprnt_ arglist;} while(0)
+        do if (_db_pargs_(__LINE__,keyword)) _db_doprnt_ arglist; while(0)
 #define DBUG_PUSH(a1) _db_push_ (a1)
 #define DBUG_POP() _db_pop_ ()
 #define DBUG_SET(a1) _db_set_ (a1)
@@ -193,8 +193,18 @@ void debug_sync_point(const char* lock_name, uint lock_timeout);
 #define DBUG_SYNC_POINT(lock_name,lock_timeout)
 #endif /* EXTRA_DEBUG */
 
-#ifdef	__cplusplus
+#ifdef __cplusplus
 }
+# ifdef DBUG_OFF
+#  define DBUG_LOG(keyword, v) do {} while (0)
+# else
+#  include <sstream>
+#  define DBUG_LOG(keyword, v) do { \
+  if (_db_pargs_(__LINE__, keyword)) { \
+    std::ostringstream _db_s; _db_s << v; \
+    _db_doprnt_("%s", _db_s.str().c_str()); \
+  }} while (0)
+# endif
 #endif
 
 #endif /* _my_dbug_h */

storage/innobase/buf/buf0buf.cc

@@ -128,11 +128,6 @@ struct set_numa_interleave_t
 #define NUMA_MEMPOLICY_INTERLEAVE_IN_SCOPE
 #endif /* HAVE_LIBNUMA */
 
-/* Enable this for checksum error messages. */
-//#ifdef UNIV_DEBUG
-//#define UNIV_DEBUG_LEVEL2 1
-//#endif
-
 /*
 		IMPLEMENTATION OF THE BUFFER POOL
 		=================================
@@ -661,12 +656,10 @@ buf_page_is_checksum_valid_crc32(
 	}
 
 invalid:
-#ifdef UNIV_DEBUG_LEVEL2
-	ib::info() << "Page checksum crc32 not valid"
+	DBUG_LOG("checksum", "Page checksum crc32 not valid"
 		   << " field1 " << checksum_field1
 		   << " field2 " << checksum_field2
-		   << " crc32 " << crc32;
-#endif
+		 << " crc32 " << crc32);
 	return(false);
 }
 
@@ -738,13 +731,13 @@ buf_page_is_checksum_valid_innodb(
 
 	if (checksum_field2 != mach_read_from_4(read_buf + FIL_PAGE_LSN)
 	    && checksum_field2 != old_checksum) {
-#ifdef UNIV_DEBUG_LEVEL2
-		ib::info() << "Page checksum crc32 not valid"
-			   << " field1 " << checksum_field1
-			   << " field2 " << checksum_field2
-			   << " crc32 " << buf_calc_page_old_checksum(read_buf)
-			   << " lsn " << mach_read_from_4(read_buf + FIL_PAGE_LSN);
-#endif
+		DBUG_LOG("checksum",
+			 "Page checksum crc32 not valid"
+			 << " field1 " << checksum_field1
+			 << " field2 " << checksum_field2
+			 << " crc32 " << buf_calc_page_old_checksum(read_buf)
+			 << " lsn " << mach_read_from_4(
+				 read_buf + FIL_PAGE_LSN));
 		return(false);
 	}
 
@@ -754,13 +747,13 @@ buf_page_is_checksum_valid_innodb(
 	(always equal to 0), to FIL_PAGE_SPACE_OR_CHKSUM */
 
 	if (checksum_field1 != 0 && checksum_field1 != new_checksum) {
-#ifdef UNIV_DEBUG_LEVEL2
-		ib::info() << "Page checksum crc32 not valid"
-			   << " field1 " << checksum_field1
-			   << " field2 " << checksum_field2
-			   << " crc32 " << buf_calc_page_new_checksum(read_buf)
-			   << " lsn " << mach_read_from_4(read_buf + FIL_PAGE_LSN);
-#endif
+		DBUG_LOG("checksum",
+			 "Page checksum crc32 not valid"
+			 << " field1 " << checksum_field1
+			 << " field2 " << checksum_field2
+			 << " crc32 " << buf_calc_page_new_checksum(read_buf)
+			 << " lsn " << mach_read_from_4(
+				 read_buf + FIL_PAGE_LSN));
 		return(false);
 	}
 
@@ -790,13 +783,16 @@ buf_page_is_checksum_valid_none(
 #endif	/* UNIV_INNOCHECKSUM */
 	)
 {
-#ifdef UNIV_DEBUG_LEVEL2
-	if (!(checksum_field1 == checksum_field2 || checksum_field1 == BUF_NO_CHECKSUM_MAGIC)) {
-		ib::info() << "Page checksum crc32 not valid"
-			   << " field1 " << checksum_field1
-			   << " field2 " << checksum_field2
-			   << " crc32 " << BUF_NO_CHECKSUM_MAGIC
-			   << " lsn " << mach_read_from_4(read_buf + FIL_PAGE_LSN);
+#ifndef DBUG_OFF
+	if (checksum_field1 != checksum_field2
+	    && checksum_field1 != BUF_NO_CHECKSUM_MAGIC) {
+		DBUG_LOG("checksum",
+			 "Page checksum crc32 not valid"
+			 << " field1 " << checksum_field1
+			 << " field2 " << checksum_field2
+			 << " crc32 " << BUF_NO_CHECKSUM_MAGIC
+			 << " lsn " << mach_read_from_4(read_buf
+							+ FIL_PAGE_LSN));
 	}
 #endif
 
@@ -3467,12 +3463,6 @@ page_found:
 	buf_pool->watch[]. However, it is not in the critical code path
 	as this function will be called only by the purge thread. */
 
-/* Enable this for checksum error messages. Currently on by
-default on UNIV_DEBUG for encryption bugs. */
-#ifdef UNIV_DEBUG
-#define UNIV_DEBUG_LEVEL2 1
-#endif
-
 	/* To obey latching order first release the hash_lock. */
 	rw_lock_x_unlock(*hash_lock);
 

storage/innobase/fil/fil0fil.cc

@@ -1691,12 +1691,17 @@ fil_space_create(
 		space->page_0_crypt_read = true;
 	}
 
-#ifdef UNIV_DEBUG
-	ib::info() << "Created tablespace for space " << space->id
-		<< " name " << space->name
-		<< " key_id " << (space->crypt_data ? space->crypt_data->key_id : 0)
-		<< " encryption " << (space->crypt_data ? space->crypt_data->encryption : 0);
-#endif
+	DBUG_LOG("tablespace",
+		 "Tablespace for space " << id << " name " << name
+		 << create_table ? " created" : " opened");
+	if (crypt_data) {
+		DBUG_LOG("crypt",
+			 "Tablespace " << id << " name " << name
+			 << " encryption " << crypt_data->encryption
+			 << " key id " << crypt_data->key_id
+			 << ":" << fil_crypt_get_mode(crypt_data)
+			 << " " << fil_crypt_get_type(crypt_data));
+	}
 
 	space->encryption_type = Encryption::NONE;
 
@@ -1718,15 +1723,6 @@ fil_space_create(
 		fil_system->max_assigned_id = id;
 	}
 
-#ifdef UNIV_DEBUG
-	if (crypt_data) {
-		/* If table could be encrypted print info */
-		ib::info() << "Tablespace ID " << id << " name " << space->name
-			   << ":" << fil_crypt_get_mode(crypt_data)
-			   << " " << fil_crypt_get_type(crypt_data);
-	}
-#endif
-
 	mutex_exit(&fil_system->mutex);
 
 	return(space);
@@ -7735,4 +7731,4 @@ fil_system_exit(void)
 {
 	ut_ad(mutex_own(&fil_system->mutex));
 	mutex_exit(&fil_system->mutex);
-}
+}

storage/innobase/fsp/fsp0fsp.cc

@@ -3730,11 +3730,15 @@ fseg_free_page(
 				the adaptive hash index */
 	mtr_t*		mtr)	/*!< in/out: mini-transaction */
 {
+	DBUG_ENTER("fseg_free_page");
 	fseg_inode_t*		seg_inode;
 	buf_block_t*		iblock;
 	const fil_space_t*	space = mtr_x_lock_space(space_id, mtr);
 	const page_size_t	page_size(space->flags);
 
+	DBUG_LOG("fseg_free_page", "space_id: " << space_id
+		 << ", page_no: " << page);
+
 	seg_inode = fseg_inode_get(seg_header, space_id, page_size, mtr,
 				   &iblock);
 	fil_block_check_type(iblock, FIL_PAGE_INODE, mtr);
@@ -3744,6 +3748,8 @@ fseg_free_page(
 	fseg_free_page_low(seg_inode, page_id, page_size, ahi, mtr);
 
 	ut_d(buf_page_set_file_page_was_freed(page_id));
+
+	DBUG_VOID_RETURN;
 }
 
 /**********************************************************************//**

storage/innobase/row/row0upd.cc

@@ -3473,26 +3473,14 @@ void upd_node_t::dbug_trace()
 
 	for (upd_cascade_t::const_iterator i = cascade_upd_nodes->begin();
 	     i != cascade_upd_nodes->end(); ++i) {
-
-		const upd_node_t*	update_node = *i;
-		ib::info() << "cascade_upd_nodes: Cascade to table: " <<
-			update_node->table->name;
-		/* JAN: TODO: MySQL 5.7
 		DBUG_LOG("upd_node_t", "cascade_upd_nodes: Cascade to table: "
-			 << update_node->table->name);
-		*/
+			 << (*i)->table->name);
 	}
 
 	for (upd_cascade_t::const_iterator j = new_upd_nodes->begin();
 	     j != new_upd_nodes->end(); ++j) {
-
-		const upd_node_t*	update_node = *j;
-		ib::info() << "cascade_upd_nodes: Cascade to table: " <<
-			update_node->table->name;
-		/* JAN: TODO: MySQL 5.7
 		DBUG_LOG("upd_node_t", "new_upd_nodes: Cascade to table: "
-			 << update_node->table->name);
-		*/
+			 << (*j)->table->name);
 	}
 
 	DBUG_VOID_RETURN;