MDEV-27158: humanize the bytes in innodb info/error messagespreview-10.8-MDEV-27158-humanize-numbers-innodbbb-10.8-MDEV-27158-humanize-numbers-innodb

Log messages like total size = 17179869184, chunk size = 134217728
get hard to read. If we normalize it down to IEC units is easier.

Idea thanks to Axel Schwenke.

Review thanks to Eugene Kosov and Marko Mäkelä

$ mariadblocal --innodb-buffer-pool-size=30G --innodb-log-file-size=128M
Installing MariaDB/MySQL system tables in '/tmp/build-mariadb-server-10.7-datadir' ...
2021-12-09  9:54:04 0 [Note] /home/dan/repos/build-mariadb-server-10.7/sql/mysqld (server 10.7.2-MariaDB) starting as process 250473 ...
2021-12-09  9:54:04 0 [Note] InnoDB: The first data file './ibdata1' did not exist. A new tablespace will be created!
2021-12-09  9:54:04 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-12-09  9:54:04 0 [Note] InnoDB: Number of transaction pools: 1
2021-12-09  9:54:04 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2021-12-09  9:54:04 0 [Note] InnoDB: Using liburing
2021-12-09  9:54:04 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 128.000MiB
2021-12-09  9:54:04 0 [Note] InnoDB: Completed initialization of buffer pool
2021-12-09  9:54:04 0 [Note] InnoDB: Setting O_DIRECT on file ./ibdata1 failed
2021-12-09  9:54:04 0 [Note] InnoDB: Setting file './ibdata1' size to 12.000MiB. Physically writing the file full; Please wait ...
2021-12-09  9:54:04 0 [Note] InnoDB: File './ibdata1' size is now 12.000MiB.
2021-12-09  9:54:04 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 96.000MiB
2021-12-09  9:54:04 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2021-12-09  9:54:04 0 [Note] InnoDB: New log file created, LSN=10317
2021-12-09  9:54:04 0 [Note] InnoDB: Doublewrite buffer not found: creating new
2021-12-09  9:54:04 0 [Note] InnoDB: Doublewrite buffer created
2021-12-09  9:54:04 0 [Note] InnoDB: 128 rollback segments are active.
2021-12-09  9:54:04 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-12-09  9:54:04 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2021-12-09  9:54:04 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2021-12-09  9:54:04 0 [Note] InnoDB: 10.7.2 started; log sequence number 0; transaction id 3
OK
2021-12-09  9:54:04 0 [Note] sql/mysqld (server 10.7.2-MariaDB) starting as process 250501 ...
2021-12-09  9:54:04 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2021-12-09  9:54:04 0 [Note] InnoDB: Number of transaction pools: 1
2021-12-09  9:54:04 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2021-12-09  9:54:04 0 [Note] InnoDB: Using liburing
2021-12-09  9:54:04 0 [Note] InnoDB: Initializing buffer pool, total size = 30.000GiB, chunk size = 128.000MiB
2021-12-09  9:54:04 0 [Note] InnoDB: Completed initialization of buffer pool
2021-12-09  9:54:04 0 [Note] InnoDB: Setting O_DIRECT on file ./ibdata1 failed
2021-12-09  9:54:04 0 [Note] InnoDB: Resizing redo log from 96.000MiB to 128.000MiB; LSN=41361
2021-12-09  9:54:04 0 [Note] InnoDB: Starting to delete and rewrite log file.
2021-12-09  9:54:04 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 128.000MiB
2021-12-09  9:54:04 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2021-12-09  9:54:04 0 [Note] InnoDB: New log file created, LSN=41361
2021-12-09  9:54:04 0 [Note] InnoDB: 128 rollback segments are active.
2021-12-09  9:54:04 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2021-12-09  9:54:04 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2021-12-09  9:54:04 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2021-12-09  9:54:04 0 [Note] InnoDB: 10.7.2 started; log sequence number 41349; transaction id 14
2021-12-09  9:54:04 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/build-mariadb-server-10.7-datadir/ib_buffer_pool
2021-12-09  9:54:04 0 [Note] Plugin 'FEEDBACK' is disabled.
2021-12-09  9:54:04 0 [Note] InnoDB: Buffer pool(s) load completed at 211209  9:54:04
2021-12-09  9:54:04 0 [Note] sql/mysqld: ready for connections.
Version: '10.7.2-MariaDB'  socket: '/tmp/build-mariadb-server-10.7.sock'  port: 0  Source distribution
2021-12-09  9:56:57 0 [Note] sql/mysqld (initiated by: unknown): Normal shutdown
2021-12-09  9:56:57 0 [Note] InnoDB: FTS optimize thread exiting.
2021-12-09  9:56:57 0 [Note] InnoDB: Starting shutdown...
2021-12-09  9:56:57 0 [Note] InnoDB: Dumping buffer pool(s) to /tmp/build-mariadb-server-10.7-datadir/ib_buffer_pool
2021-12-09  9:56:57 0 [Note] InnoDB: Buffer pool(s) dump completed at 211209  9:56:57
2021-12-09  9:56:57 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2021-12-09  9:56:57 0 [Note] InnoDB: Shutdown completed; log sequence number 42602; transaction id 15
2021-12-09  9:56:57 0 [Note] sql/mysqld: Shutdown complete

11 files changed, 66 insertions, 31 deletions

diff --git a/mysql-test/suite/innodb/r/log_file.result b/mysql-test/suite/innodb/r/log_file.result
index 10479e5004a..ae60174de7b 100644
--- a/mysql-test/suite/innodb/r/log_file.result
+++ b/mysql-test/suite/innodb/r/log_file.result
@@ -290,7 +290,7 @@ WHERE engine='innodb'
 AND support IN ('YES', 'DEFAULT', 'ENABLED');
 1
 1
-NOT FOUND /Resizing redo log from 1\*\d+ to 3\*\d+ bytes; LSN=\d+/ in mysqld.1.err
+NOT FOUND /Resizing redo log from 1\*\d+ to 3\*\d+[KMGT]iB; LSN=\d+/ in mysqld.1.err
 # restart
 # Cleanup
 bak_ib_logfile0
diff --git a/mysql-test/suite/innodb/t/log_file.test b/mysql-test/suite/innodb/t/log_file.test
index f03bce804f6..366bcd82f61 100644
--- a/mysql-test/suite/innodb/t/log_file.test
+++ b/mysql-test/suite/innodb/t/log_file.test
@@ -211,7 +211,7 @@ eval $check_no_innodb;
 --source include/start_mysqld.inc
 eval $check_yes_innodb;
 --source include/shutdown_mysqld.inc
---let SEARCH_PATTERN=Resizing redo log from 1\*\d+ to 3\*\d+ bytes; LSN=\d+
+--let SEARCH_PATTERN=Resizing redo log from 1\*\d+ to 3\*\d+[KMGT]iB; LSN=\d+
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters=
diff --git a/storage/innobase/buf/buf0buf.cc b/storage/innobase/buf/buf0buf.cc
index c31d9aef8eb..6090d869bac 100644
--- a/storage/innobase/buf/buf0buf.cc
+++ b/storage/innobase/buf/buf0buf.cc
@@ -1638,11 +1638,15 @@ inline void buf_pool_t::resize()
 	ut_ad(srv_buf_pool_chunk_unit > 0);
 
 	ulint new_instance_size = srv_buf_pool_size >> srv_page_size_shift;
-
-	buf_resize_status("Resizing buffer pool from " ULINTPF " to "
-			  ULINTPF " (unit=" ULINTPF ").",
-			  srv_buf_pool_old_size, srv_buf_pool_size,
-			  srv_buf_pool_chunk_unit);
+	std::ostringstream str_old_size, str_new_size, str_chunk_size;
+	str_old_size << ib::bytes_iec{srv_buf_pool_old_size};
+	str_new_size << ib::bytes_iec{srv_buf_pool_size};
+	str_chunk_size << ib::bytes_iec{srv_buf_pool_chunk_unit};
+
+	buf_resize_status("Resizing buffer pool from %s to %s (unit=%s).",
+			  str_old_size.str().c_str(),
+			  str_new_size.str().c_str(),
+			  str_chunk_size.str().c_str());
 
 #ifdef BTR_CUR_HASH_ADAPT
 	/* disable AHI if needed */
diff --git a/storage/innobase/buf/buf0dump.cc b/storage/innobase/buf/buf0dump.cc
index bc39e6bfaec..b4b3dd75f30 100644
--- a/storage/innobase/buf/buf0dump.cc
+++ b/storage/innobase/buf/buf0dump.cc
@@ -315,11 +315,13 @@ buf_dump(
 					       n_pages * sizeof(*dump)));
 
 	if (dump == NULL) {
+		std::ostringstream str_bytes;
 		mysql_mutex_unlock(&buf_pool.mutex);
 		fclose(f);
+		str_bytes << ib::bytes_iec{n_pages * sizeof(*dump)};
 		buf_dump_status(STATUS_ERR,
-				"Cannot allocate " ULINTPF " bytes: %s",
-				(ulint) (n_pages * sizeof(*dump)),
+				"Cannot allocate %s: %s",
+				str_bytes.str().c_str(),
 				strerror(errno));
 		/* leave tmp_filename to exist */
 		return;
@@ -561,11 +563,14 @@ buf_load()
 	}
 
 	if (dump == NULL) {
+		std::ostringstream str_bytes;
 		fclose(f);
-		buf_load_status(STATUS_ERR,
-				"Cannot allocate " ULINTPF " bytes: %s",
-				dump_n * sizeof(*dump),
+		str_bytes << ib::bytes_iec{dump_n * sizeof(*dump)};
+		buf_dump_status(STATUS_ERR,
+				"Cannot allocate %s: %s",
+				str_bytes.str().c_str(),
 				strerror(errno));
+		/* leave tmp_filename to exist */
 		return;
 	}
 
diff --git a/storage/innobase/data/data0data.cc b/storage/innobase/data/data0data.cc
index 14a0b3e19fd..13efd7f3665 100644
--- a/storage/innobase/data/data0data.cc
+++ b/storage/innobase/data/data0data.cc
@@ -466,8 +466,10 @@ dfield_print_raw(
 		ulint	print_len = ut_min(len, static_cast<ulint>(1000));
 		ut_print_buf(f, dfield_get_data(dfield), print_len);
 		if (len != print_len) {
-			fprintf(f, "(total %lu bytes%s)",
-				(ulong) len,
+			std::ostringstream str_bytes;
+			str_bytes << ib::bytes_iec{len};
+			fprintf(f, "(total %s%s)",
+				str_bytes.str().c_str(),
 				dfield_is_ext(dfield) ? ", external" : "");
 		}
 	} else {
@@ -600,7 +602,7 @@ dtuple_convert_big_rec(
 	size = rec_get_converted_size(index, entry, *n_ext);
 
 	if (UNIV_UNLIKELY(size > 1000000000)) {
-		ib::warn() << "Tuple size is very big: " << size;
+		ib::warn() << "Tuple size is very big: " << ib::bytes_iec{size};
 		fputs("InnoDB: Tuple contents: ", stderr);
 		dtuple_print(stderr, entry);
 		putc('\n', stderr);
diff --git a/storage/innobase/fsp/fsp0file.cc b/storage/innobase/fsp/fsp0file.cc
index 95eb9007944..030e030d474 100644
--- a/storage/innobase/fsp/fsp0file.cc
+++ b/storage/innobase/fsp/fsp0file.cc
@@ -794,7 +794,7 @@ Datafile::restore_from_doublewrite()
 	ib::info() << "Restoring page " << page_id
 		<< " of datafile '" << m_filepath
 		<< "' from the doublewrite buffer. Writing "
-		<< physical_size << " bytes into file '"
+		<< ib::bytes_iec{physical_size} << " into file '"
 		<< m_filepath << "'";
 
 	return(os_file_write(
diff --git a/storage/innobase/fsp/fsp0sysspace.cc b/storage/innobase/fsp/fsp0sysspace.cc
index 56ef4959690..4c3507538c7 100644
--- a/storage/innobase/fsp/fsp0sysspace.cc
+++ b/storage/innobase/fsp/fsp0sysspace.cc
@@ -396,8 +396,8 @@ SysTablespace::set_size(
 
 	/* We created the data file and now write it full of zeros */
 	ib::info() << "Setting file '" << file.filepath() << "' size to "
-		<< (file.m_size >> (20U - srv_page_size_shift)) << " MB."
-		" Physically writing the file full; Please wait ...";
+		<< ib::bytes_iec{file.m_size << srv_page_size_shift} <<
+		". Physically writing the file full; Please wait ...";
 
 	bool	success = os_file_set_size(
 		file.m_filepath, file.m_handle,
@@ -405,8 +405,8 @@ SysTablespace::set_size(
 
 	if (success) {
 		ib::info() << "File '" << file.filepath() << "' size is now "
-			<< (file.m_size >> (20U - srv_page_size_shift))
-			<< " MB.";
+			<< ib::bytes_iec{file.m_size << srv_page_size_shift}
+			<< ".";
 	} else {
 		ib::error() << "Could not set the file size of '"
 			<< file.filepath() << "'. Probably out of disk space";
diff --git a/storage/innobase/fts/fts0fts.cc b/storage/innobase/fts/fts0fts.cc
index 2a3a780228d..42beefeb4d5 100644
--- a/storage/innobase/fts/fts0fts.cc
+++ b/storage/innobase/fts/fts0fts.cc
@@ -3942,7 +3942,7 @@ fts_sync_begin(
 		ib::info() << "FTS SYNC for table " << sync->table->name
 			<< ", deleted count: "
 			<< ib_vector_size(cache->deleted_doc_ids)
-			<< " size: " << cache->total_size << " bytes";
+			<< " size: " << ib::bytes_iec{cache->total_size};
 	}
 }
 
diff --git a/storage/innobase/include/ut0ut.h b/storage/innobase/include/ut0ut.h
index 69abd932375..166d8132a3e 100644
--- a/storage/innobase/include/ut0ut.h
+++ b/storage/innobase/include/ut0ut.h
@@ -305,6 +305,16 @@ operator<<(
 	return(lhs);
 }
 
+/** This is a wrapper class, used to print any number in IEC style */
+struct bytes_iec {
+  explicit bytes_iec(unsigned long long t): m_val(t) {}
+  double get_double() const { return static_cast<double>(m_val); }
+  const unsigned long long m_val;
+};
+
+/** Like hex operator above, except for bytes_iec */
+std::ostream &operator<<(std::ostream &lhs, const bytes_iec &rhs);
+
 /** The class logger is the base class of all the error log related classes.
 It contains a std::ostringstream object.  The main purpose of this class is
 to forward operator<< to the underlying std::ostringstream object.  Do not
diff --git a/storage/innobase/srv/srv0start.cc b/storage/innobase/srv/srv0start.cc
index 52eee800dae..58cdfda9574 100644
--- a/storage/innobase/srv/srv0start.cc
+++ b/storage/innobase/srv/srv0start.cc
@@ -269,13 +269,13 @@ static dberr_t create_log_file(bool create_new_db, lsn_t lsn,
 	}
 
 	ib::info() << "Setting log file " << logfile0 << " size to "
-		   << srv_log_file_size << " bytes";
+		   << ib::bytes_iec{srv_log_file_size};
 
 	ret = os_file_set_size(logfile0.c_str(), file, srv_log_file_size);
 	if (!ret) {
 		os_file_close(file);
 		ib::error() << "Cannot set log file " << logfile0
-			    << " size to " << srv_log_file_size << " bytes";
+			    << " size to " << ib::bytes_iec{srv_log_file_size};
 		return DB_ERROR;
 	}
 
@@ -406,7 +406,8 @@ static dberr_t srv_undo_tablespace_create(const char* name)
 			" be created";
 
 		ib::info() << "Setting file " << name << " size to "
-			<< (SRV_UNDO_TABLESPACE_SIZE_IN_PAGES >> (20 - srv_page_size_shift)) << " MB";
+			<< ib::bytes_iec{SRV_UNDO_TABLESPACE_SIZE_IN_PAGES
+					 << srv_page_size_shift};
 
 		ib::info() << "Database physically writes the file full: "
 			<< "wait...";
@@ -922,7 +923,8 @@ static lsn_t srv_prepare_to_delete_redo_log_file(bool old_exists)
 						" and resizing";
 				}
 
-				info << " redo log from " << srv_log_file_size
+				info << " redo log from "
+				     << ib::bytes_iec{srv_log_file_size}
 				     << " to ";
 			} else if (srv_encrypt_log) {
 				info << "Encrypting redo log: ";
@@ -930,8 +932,8 @@ static lsn_t srv_prepare_to_delete_redo_log_file(bool old_exists)
 				info << "Removing redo log encryption: ";
 			}
 
-			info << srv_log_file_size_requested
-			     << " bytes; LSN=" << flushed_lsn;
+			info << ib::bytes_iec{srv_log_file_size_requested}
+			     << "; LSN=" << flushed_lsn;
 		}
 
 		mysql_mutex_unlock(&log_sys.mutex);
@@ -1207,8 +1209,8 @@ dberr_t srv_start(bool create_new_db)
 	fil_system.create(srv_file_per_table ? 50000 : 5000);
 
 	ib::info() << "Initializing buffer pool, total size = "
-		<< srv_buf_pool_size
-		<< ", chunk size = " << srv_buf_pool_chunk_unit;
+		<< ib::bytes_iec{srv_buf_pool_size}
+		<< ", chunk size = " << ib::bytes_iec{srv_buf_pool_chunk_unit};
 
 	if (buf_pool.create()) {
 		ib::error() << "Cannot allocate memory for the buffer pool";
@@ -1225,8 +1227,8 @@ dberr_t srv_start(bool create_new_db)
 	if (srv_buf_pool_size <= 5 * 1024 * 1024) {
 
 		ib::info() << "Small buffer pool size ("
-			<< srv_buf_pool_size / 1024 / 1024
-			<< "M), the flst_validate() debug function can cause a"
+			<< ib::bytes_iec{srv_buf_pool_size}
+			<< "), the flst_validate() debug function can cause a"
 			<< " deadlock if the buffer pool fills up.";
 	}
 #endif /* UNIV_DEBUG */
diff --git a/storage/innobase/ut/ut0ut.cc b/storage/innobase/ut/ut0ut.cc
index d127f2138c9..cc128a494ea 100644
--- a/storage/innobase/ut/ut0ut.cc
+++ b/storage/innobase/ut/ut0ut.cc
@@ -478,6 +478,18 @@ ut_strerr(
 
 namespace ib {
 
+std::ostream &operator<<(std::ostream &lhs, const bytes_iec &rhs)
+{
+  static const char *sizes[]= {"B", "KiB", "MiB", "GiB", "TiB", "PiB",
+                              "EiB", "ZiB", "YiB"};
+  size_t i= 0;
+  double d= rhs.get_double();
+  for (; d > 512.0 && i < array_elements(sizes); i++, d/= 1024.0);
+  lhs.precision(3);
+  lhs << std::fixed << d << sizes[i];
+  return lhs;
+}
+
 ATTRIBUTE_COLD logger& logger::operator<<(dberr_t err)
 {
   m_oss << ut_strerr(err);