MDEV-27158: humanize the bytes in innodb info/error messages

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

mysql-test/suite/innodb/r/log_file.result

@@ -289,7 +289,6 @@ 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
 # restart
 # Cleanup
 bak_ib_logfile0

mysql-test/suite/innodb/r/log_file_size.result

@@ -45,11 +45,11 @@ FOUND 1 /InnoDB: innodb_read_only prevents crash recovery/ in mysqld.1.err
 # restart: --debug=d,innodb_log_abort_4
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND 5 /redo log from [0-9]+ to [0-9]+ bytes/ in mysqld.1.err
+FOUND 5 /redo log from [1-9][0-9.]+[KMGT]iB to [1-9][0-9.]+[KMGT]iB/ in mysqld.1.err
 # restart: --debug=d,innodb_log_abort_5
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND 6 /redo log from [0-9]+ to [0-9]+ bytes/ in mysqld.1.err
+FOUND 6 /redo log from [1-9][0-9.]+[KMGT]iB to [1-9][0-9.]+[KMGT]iB/ in mysqld.1.err
 # restart: --innodb-read-only
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
@@ -57,7 +57,7 @@ FOUND 2 /InnoDB: innodb_read_only prevents crash recovery/ in mysqld.1.err
 # restart: --debug=d,innodb_log_abort_6
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'
-FOUND 7 /redo log from [0-9]+ to [0-9]+ bytes/ in mysqld.1.err
+FOUND 7 /redo log from [1-9][0-9.]+[KMGT]iB to [1-9][0-9.]+[KMGT]iB/ in mysqld.1.err
 # restart: --debug=d,innodb_log_abort_7
 SELECT * FROM t1;
 ERROR 42000: Unknown storage engine 'InnoDB'

mysql-test/suite/innodb/t/log_file.test

@@ -208,8 +208,6 @@ 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+
---source include/search_pattern_in_file.inc
 
 --let $restart_parameters=
 --source include/start_mysqld.inc

mysql-test/suite/innodb/t/log_file_size.test

@@ -112,14 +112,13 @@ let SEARCH_PATTERN= InnoDB: innodb_read_only prevents crash recovery;
 --source include/restart_mysqld.inc
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
-let SEARCH_PATTERN= redo log from [0-9]+ to [0-9]+ bytes;
+let SEARCH_PATTERN= redo log from [1-9][0-9.]+[KMGT]iB to [1-9][0-9.]+[KMGT]iB;
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --debug=d,innodb_log_abort_5
 --source include/restart_mysqld.inc
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
-let SEARCH_PATTERN= redo log from [0-9]+ to [0-9]+ bytes;
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --innodb-read-only
@@ -134,7 +133,7 @@ let SEARCH_PATTERN= InnoDB: innodb_read_only prevents crash recovery;
 --error ER_UNKNOWN_STORAGE_ENGINE
 SELECT * FROM t1;
 
-let SEARCH_PATTERN= redo log from [0-9]+ to [0-9]+ bytes;
+let SEARCH_PATTERN= redo log from [1-9][0-9.]+[KMGT]iB to [1-9][0-9.]+[KMGT]iB;
 --source include/search_pattern_in_file.inc
 
 --let $restart_parameters= --debug=d,innodb_log_abort_7

storage/innobase/buf/buf0buf.cc

@@ -1641,11 +1641,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 */

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;
 	}
 

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);

storage/innobase/fsp/fsp0file.cc

@@ -790,7 +790,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(

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";

storage/innobase/fts/fts0fts.cc

@@ -3994,7 +3994,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};
 	}
 }
 

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

storage/innobase/srv/srv0start.cc

@@ -3,7 +3,7 @@
 Copyright (c) 1996, 2017, Oracle and/or its affiliates. All rights reserved.
 Copyright (c) 2008, Google Inc.
 Copyright (c) 2009, Percona Inc.
-Copyright (c) 2013, 2021, MariaDB Corporation.
+Copyright (c) 2013, 2022, MariaDB Corporation.
 
 Portions of this file contain modifications contributed and copyrighted by
 Google, Inc. Those modifications are gratefully acknowledged and are described
@@ -273,13 +273,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;
 	}
 
@@ -414,7 +414,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...";
@@ -919,8 +920,8 @@ static lsn_t srv_prepare_to_delete_redo_log_file(bool old_exists)
     {
       msg= "Upgrading redo log: ";
 same_size:
-      ib::info() << msg << srv_log_file_size_requested << " bytes; LSN="
-                 << flushed_lsn;
+      ib::info() << msg << ib::bytes_iec(srv_log_file_size_requested)
+                 << "; LSN=" << flushed_lsn;
     }
     else if (old_exists && srv_log_file_size == srv_log_file_size_requested)
     {
@@ -937,9 +938,10 @@ static lsn_t srv_prepare_to_delete_redo_log_file(bool old_exists)
           ? "Encrypting and resizing"
           : "Removing encryption and resizing";
 
-      ib::info() << msg << " redo log from " << srv_log_file_size << " to "
-                 << srv_log_file_size_requested
-                 << " bytes; LSN=" << flushed_lsn;
+      ib::info() << msg << " redo log from "
+                 << ib::bytes_iec{srv_log_file_size} << " to "
+                 << ib::bytes_iec{srv_log_file_size_requested}
+                 << "; LSN=" << flushed_lsn;
     }
   }
 
@@ -1197,8 +1199,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";
@@ -1215,8 +1217,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 */

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);