From 7e85a29a8d6ec2bc548c2f66669d41e8c91fb99b Mon Sep 17 00:00:00 2001 From: Aditya Gurajada Date: Thu, 22 Dec 2022 10:44:04 -0800 Subject: [PATCH] (#511) Add fns to print 'size' as human-readable string w/ unit-specifiers This commit adds couple of utility functions to snprintf(), in an output buffer, the 'size' unit to a human-readable string with unit-specifiers. - size_to_str() - Convert 'size' to a string in an output buffer - size_to_fmtstr() - Same as above, using user-specified format-string. Useful to generate output enclosed in, e.g., '(%s)'. - Add size_str(), size_fmstr() caller-macros to simplify calling these formatting functions. These macros declare on-stack buffers used to format the output string. size_str() provided by Rob Johnson, to greatly simplify the usage. Add utility bytes-to-Units conversion macros. Add unit tests to exercise these interfaces. Apply these utility fns in couple of stats-printing and BTree print-methods, to display size values as human-friendly unit specifiers. --- src/btree.c | 13 +++- src/platform_linux/platform.h | 17 ++++- src/rc_allocator.c | 73 +++++++++++--------- src/rc_allocator.h | 4 +- src/trunk.c | 11 +-- src/util.c | 61 +++++++++++++++++ src/util.h | 36 ++++++++++ tests/unit/btree_stress_test.c | 16 +++++ tests/unit/misc_test.c | 121 +++++++++++++++++++++++++++++++-- 9 files changed, 302 insertions(+), 50 deletions(-) diff --git a/src/btree.c b/src/btree.c index 860434566..76a67c2cf 100644 --- a/src/btree.c +++ b/src/btree.c @@ -3083,6 +3083,10 @@ btree_print_offset_table(platform_log_handle *log_handle, btree_hdr *hdr) platform_log(log_handle, "\n"); } +// Macro to deal with printing Pivot stats 'sz' bytes as uninitialized +#define PIVOT_STATS_BYTES_AS_STR(sz) \ + (((sz) == BTREE_UNKNOWN_COUNTER) ? "BTREE_UNKNOWN_COUNTER" : size_str((sz))) + static void btree_print_btree_pivot_stats(platform_log_handle *log_handle, btree_pivot_stats *pivot_stats) @@ -3099,11 +3103,13 @@ btree_print_btree_pivot_stats(platform_log_handle *log_handle, // Indentation is dictated by outer caller platform_log(log_handle, " (num_kvs=%u\n" - " key_bytes=%u\n" - " message_bytes=%u)\n", + " key_bytes=%u (%s)\n" + " message_bytes=%u (%s))\n", pivot_stats->num_kvs, pivot_stats->key_bytes, - pivot_stats->message_bytes); + PIVOT_STATS_BYTES_AS_STR(pivot_stats->key_bytes), + pivot_stats->message_bytes, + PIVOT_STATS_BYTES_AS_STR(pivot_stats->message_bytes)); } static void @@ -3255,6 +3261,7 @@ btree_print_subtree(platform_log_handle *log_handle, node.addr = addr; btree_print_node(log_handle, cc, cfg, &node); if (!allocator_page_valid(cache_get_allocator(cc), node.addr)) { + platform_log(log_handle, "Unallocated BTree node addr=%lu\n", addr); return; } btree_node_get(cc, cfg, &node, PAGE_TYPE_BRANCH); diff --git a/src/platform_linux/platform.h b/src/platform_linux/platform.h index 54950caed..18b3fb81f 100644 --- a/src/platform_linux/platform.h +++ b/src/platform_linux/platform.h @@ -88,14 +88,27 @@ // Data unit constants #define KiB (1024UL) -#define MiB (KiB * KiB) -#define GiB (MiB * KiB) +#define MiB (KiB * 1024) +#define GiB (MiB * 1024) +#define TiB (GiB * 1024) +// Convert 'x' in unit-specifiers to bytes #define KiB_TO_B(x) ((x)*KiB) #define MiB_TO_B(x) ((x)*MiB) #define GiB_TO_B(x) ((x)*GiB) +#define TiB_TO_B(x) ((x)*TiB) + +// Convert 'x' in bytes to 'int'-value with unit-specifiers +#define B_TO_KiB(x) ((x) / KiB) #define B_TO_MiB(x) ((x) / MiB) #define B_TO_GiB(x) ((x) / GiB) +#define B_TO_TiB(x) ((x) / TiB) + +// For x bytes, returns as int the fractional portion modulo a unit-specifier +#define B_TO_KiB_FRACT(x) ((100 * ((x) % KiB)) / KiB) +#define B_TO_MiB_FRACT(x) ((100 * ((x) % MiB)) / MiB) +#define B_TO_GiB_FRACT(x) ((100 * ((x) % GiB)) / GiB) +#define B_TO_TiB_FRACT(x) ((100 * ((x) % TiB)) / TiB) // Time unit constants #define THOUSAND (1000UL) diff --git a/src/rc_allocator.c b/src/rc_allocator.c index 88cc5a1fc..8217f79a1 100644 --- a/src/rc_allocator.c +++ b/src/rc_allocator.c @@ -777,50 +777,52 @@ rc_allocator_assert_noleaks(rc_allocator *al) void rc_allocator_print_stats(rc_allocator *al) { - int64 divider = GiB / al->cfg->io_cfg->extent_size; + // clang-format off + const char *dashes = "-------------------------------------------------------------------"; + platform_default_log("|%s|\n", dashes); + platform_default_log("| Allocator Stats |\n"); + platform_default_log("|%s|\n", dashes); + // clang-format on + + uint64 extent_size = al->cfg->io_cfg->extent_size; // bytes platform_default_log( - "----------------------------------------------------------------\n"); - platform_default_log( - "| Allocator Stats |\n"); - platform_default_log( - "|--------------------------------------------------------------|\n"); - uint64 curr_gib = al->stats.curr_allocated / divider; - platform_default_log( - "| Currently Allocated: %12lu extents (%4luGiB) |\n", + "| Currently Allocated: %12lu extents %-14s |\n", al->stats.curr_allocated, - curr_gib); - uint64 max_gib = al->stats.max_allocated / divider; + size_fmtstr("(%s)", (al->stats.curr_allocated * extent_size))); + platform_default_log( - "| Max Allocated: %12lu extents (%4luGiB) |\n", + "| Max Allocated: %12lu extents %-14s |\n", al->stats.max_allocated, - max_gib); - platform_default_log( - "|--------------------------------------------------------------|\n"); - platform_default_log( - "| Page Type | Allocations | Deallocations | Footprint (bytes) |\n"); - platform_default_log( - "|--------------------------------------------------------------|\n"); + size_fmtstr("(%s)", (al->stats.max_allocated * extent_size))); + + // clang-format off + platform_default_log("|%s|\n", dashes); + platform_default_log("| Page Type | Allocations | Deallocations | Footprint |\n"); + platform_default_log("| | (Number of extents) | # extents (bytes) |\n"); + platform_default_log("|%s|\n", dashes); + // clang-format on + int64 exp_allocated_count = 0; for (page_type type = PAGE_TYPE_FIRST; type < NUM_PAGE_TYPES; type++) { - const char *str = page_type_str[type]; - int64 allocs = al->stats.extent_allocs[type]; - int64 deallocs = al->stats.extent_deallocs[type]; - int64 footprint = allocs - deallocs; - int64 footprint_gib = footprint / divider; + const char *str = page_type_str[type]; + int64 allocs = al->stats.extent_allocs[type]; + int64 deallocs = al->stats.extent_deallocs[type]; + int64 footprint = allocs - deallocs; exp_allocated_count += footprint; - platform_default_log("| %-10s | %11ld | %13ld | %8ld (%4ldGiB) |\n", + platform_default_log("| %-10s | %11ld | %13ld | %8ld %14s|\n", str, allocs, deallocs, footprint, - footprint_gib); + size_fmtstr("(%s)", (footprint * extent_size))); } + platform_default_log("|%s|\n", dashes); platform_default_log( - "----------------------------------------------------------------\n"); - platform_default_log("Expected allocation count from footprint = %ld\n", - exp_allocated_count); + "Expected count of extents in-use from footprint = %ld extents (%s)\n", + exp_allocated_count, + size_str(exp_allocated_count * extent_size)); } /* @@ -846,17 +848,20 @@ rc_allocator_print_allocated(rc_allocator *al) platform_default_log(" Index ExtentAddr Count\n"); // # of extents with non-zero referenced page-count found - uint64 found = 0; + uint64 nextents_found = 0; + uint64 extent_size = al->cfg->io_cfg->extent_size; for (i = 0; i < al->cfg->extent_capacity; i++) { ref = al->ref_count[i]; if (ref != 0) { - found++; - uint64 ext_addr = (i * al->cfg->io_cfg->extent_size); + nextents_found++; + uint64 ext_addr = (i * extent_size); platform_default_log("%8lu %12lu %u\n", i, ext_addr, ref); } } - platform_default_log("%sFound %lu extents with allocated pages.\n", + + platform_default_log("%sFound %lu extents (%s) with allocated pages.\n", (print_curly ? "}\n" : ""), - found); + nextents_found, + size_str(nextents_found * extent_size)); } diff --git a/src/rc_allocator.h b/src/rc_allocator.h index 87e0959ef..54ed22eb8 100644 --- a/src/rc_allocator.h +++ b/src/rc_allocator.h @@ -44,8 +44,8 @@ _Static_assert(offsetof(rc_allocator_meta_page, splinters) == 0, *---------------------------------------------------------------------- */ typedef struct rc_allocator_stats { - int64 curr_allocated; - int64 max_allocated; + int64 curr_allocated; // # of extents allocated + int64 max_allocated; // # of extents allocated high-water mark int64 extent_allocs[NUM_PAGE_TYPES]; int64 extent_deallocs[NUM_PAGE_TYPES]; } rc_allocator_stats; diff --git a/src/trunk.c b/src/trunk.c index a4acf7ea8..233e48045 100644 --- a/src/trunk.c +++ b/src/trunk.c @@ -7905,8 +7905,11 @@ trunk_print_space_use(platform_log_handle *log_handle, trunk_handle *spl) "Space used by level: trunk_tree_height=%d\n", trunk_tree_height(spl)); for (uint16 i = 0; i <= trunk_tree_height(spl); i++) { - platform_log( - log_handle, "%u: %8lu MiB\n", i, B_TO_MiB(bytes_used_by_level[i])); + platform_log(log_handle, + "%u: %lu bytes (%s)\n", + i, + bytes_used_by_level[i], + size_str(bytes_used_by_level[i])); } platform_log(log_handle, "\n"); } @@ -8851,7 +8854,7 @@ trunk_node_print_branches(trunk_handle *spl, uint64 addr, void *arg) spl, &node, branch_no, &num_tuples_in_branch, &kv_bytes_in_branch); uint64 kib_in_branch = 0; // trunk_branch_extent_count(spl, &node, branch_no); - kib_in_branch *= trunk_extent_size(&spl->cfg) / 1024; + kib_in_branch *= B_TO_KiB(trunk_extent_size(&spl->cfg)); fraction space_amp = init_fraction(kib_in_branch * 1024, kv_bytes_in_branch); platform_log( @@ -8861,7 +8864,7 @@ trunk_node_print_branches(trunk_handle *spl, uint64 addr, void *arg) branch_no, addr, num_tuples_in_branch, - kv_bytes_in_branch / 1024, + B_TO_KiB(kv_bytes_in_branch), kib_in_branch, FRACTION_ARGS(space_amp)); } diff --git a/src/util.c b/src/util.c index 71ea5d2f4..99ff8cf9c 100644 --- a/src/util.c +++ b/src/util.c @@ -364,3 +364,64 @@ debug_hex_dump_slice(platform_log_handle *plh, uint64 grouping, slice data) { debug_hex_dump(plh, grouping, slice_length(data), slice_data(data)); } + +/* + * Format a size value with unit-specifiers, in an output buffer. + * Returns 'outbuf', as ptr to size-value snprintf()'ed as a string. + */ +char * +size_to_str(char *outbuf, size_t outbuflen, size_t size) +{ + debug_assert(outbuflen >= SIZE_TO_STR_LEN, "outbuflen=%lu.\n", outbuflen); + size_t unit_val = 0; + size_t frac_val = 0; + bool is_approx = FALSE; + + char *units = NULL; + if (size >= TiB) { + unit_val = B_TO_TiB(size); + frac_val = B_TO_TiB_FRACT(size); + is_approx = (size > TiB_TO_B(unit_val)); + units = "TiB"; + + } else if (size >= GiB) { + unit_val = B_TO_GiB(size); + frac_val = B_TO_GiB_FRACT(size); + is_approx = (size > GiB_TO_B(unit_val)); + units = "GiB"; + + } else if (size >= MiB) { + unit_val = B_TO_MiB(size); + frac_val = B_TO_MiB_FRACT(size); + is_approx = (size > MiB_TO_B(unit_val)); + units = "MiB"; + + } else if (size >= KiB) { + unit_val = B_TO_KiB(size); + frac_val = B_TO_KiB_FRACT(size); + is_approx = (size > KiB_TO_B(unit_val)); + units = "KiB"; + } else { + unit_val = size; + units = "bytes"; + } + + if (frac_val || is_approx) { + snprintf(outbuf, outbuflen, "~%ld.%ld %s", unit_val, frac_val, units); + } else { + snprintf(outbuf, outbuflen, "%ld %s", unit_val, units); + } + return outbuf; +} + +/* + * Sibling of size_to_str(), but uses user-provided print format specifier. + * 'fmtstr' is expected to have just one '%s', and whatever other text user + * wishes to print with the output string. + */ +char * +size_to_fmtstr(char *outbuf, size_t outbuflen, const char *fmtstr, size_t size) +{ + snprintf(outbuf, outbuflen, fmtstr, size_str(size)); + return outbuf; +} diff --git a/src/util.h b/src/util.h index 603f5f756..550eb02d6 100644 --- a/src/util.h +++ b/src/util.h @@ -382,4 +382,40 @@ debug_hex_dump_slice(platform_log_handle *, uint64 grouping, slice data); : ((intval) < 1000) ? "3d" \ : "4d") +// Length of output buffer to snprintf()-into size as string w/ unit specifier +#define SIZE_TO_STR_LEN 20 + +// Format a size value with unit-specifiers, in an output buffer. +char * +size_to_str(char *outbuf, size_t outbuflen, size_t size); + +char * +size_to_fmtstr(char *outbuf, size_t outbuflen, const char *fmtstr, size_t size); + +/* + * Convenience caller macros to convert 'sz' bytes to return a string, + * formatting the input size as human-readable value with unit-specifiers. + */ +// char *size_str(size_t sz) +#define size_str(sz) \ + (({ \ + struct { \ + char buffer[SIZE_TO_STR_LEN]; \ + } onstack_chartmp; \ + size_to_str( \ + onstack_chartmp.buffer, sizeof(onstack_chartmp.buffer), sz); \ + onstack_chartmp; \ + }).buffer) + +// char *size_fmtstr(const char *fmtstr, size_t sz) +#define size_fmtstr(fmtstr, sz) \ + (({ \ + struct { \ + char buffer[SIZE_TO_STR_LEN]; \ + } onstack_chartmp; \ + size_to_fmtstr( \ + onstack_chartmp.buffer, sizeof(onstack_chartmp.buffer), fmtstr, sz); \ + onstack_chartmp; \ + }).buffer) + #endif // _SPLINTER_UTIL_H_ diff --git a/tests/unit/btree_stress_test.c b/tests/unit/btree_stress_test.c index 0408923a6..cb4289412 100644 --- a/tests/unit/btree_stress_test.c +++ b/tests/unit/btree_stress_test.c @@ -113,6 +113,16 @@ CTEST_DATA(btree_stress) // Setup function for suite, called before every test in suite CTEST_SETUP(btree_stress) { + if (Ctest_verbose) { + platform_set_log_streams(stdout, stderr); + CTEST_LOG_INFO("\nVerbose mode on. This test exercises an error case, " + "so on sucess it " + "will print a message that appears to be an error.\n"); + } else { + FILE *dev_null = fopen("/dev/null", "w"); + ASSERT_NOT_NULL(dev_null); + platform_set_log_streams(dev_null, dev_null); + } config_set_defaults(&data->master_cfg); data->master_cfg.cache_capacity = GiB_TO_B(5); data->data_cfg = test_data_config; @@ -256,6 +266,12 @@ CTEST2(btree_stress, test_random_inserts_concurrent) (cache *)&data->cc, &data->dbtree_cfg, packed_root_addr, nkvs, data->hid); ASSERT_NOT_EQUAL(0, rc, "Invalid ranges in packed tree\n"); + // Exercise print method to verify that it basically continues to work. + btree_print_tree(Platform_default_log_handle, + (cache *)&data->cc, + &data->dbtree_cfg, + packed_root_addr); + // Release memory allocated in this test case for (uint64 i = 0; i < nthreads; i++) { platform_free(data->hid, params[i].scratch); diff --git a/tests/unit/misc_test.c b/tests/unit/misc_test.c index 357e82414..18296e1f8 100644 --- a/tests/unit/misc_test.c +++ b/tests/unit/misc_test.c @@ -12,6 +12,8 @@ #include "platform.h" #include "unit_tests.h" #include "ctest.h" // This is required for all test-case files. +#include "util.h" +#include "platform.h" #define ASSERT_OUTBUF_LEN 200 @@ -21,7 +23,7 @@ "Test assertion msg with arguments id = %d, name = '%s'." /* Function prototypes and caller-macros to invoke testing interfaces */ -void +static void test_platform_assert_msg(platform_log_handle *log_handle, const char *filename, int linenumber, @@ -39,7 +41,7 @@ test_platform_assert_msg(platform_log_handle *log_handle, test_platform_assert_msg( \ log_handle, __FILE__, __LINE__, __FUNCTION__, #expr, "" __VA_ARGS__) -void +static void test_vfprintf_usermsg(platform_log_handle *log_handle, const char *message, ...); @@ -53,6 +55,9 @@ test_vfprintf_usermsg(platform_log_handle *log_handle, #define test_assert_usermsg(log_handle, ...) \ test_vfprintf_usermsg(log_handle, "" __VA_ARGS__) +static void +test_streqn(char *expstr, char *actstr, int caseno); + /* * Global data declaration macro: */ @@ -67,12 +72,14 @@ CTEST_SETUP(misc) // So lets send those messages to /dev/null unless VERBOSE=1. if (Ctest_verbose) { data->log_output = stdout; + platform_set_log_streams(stdout, stderr); CTEST_LOG_INFO("\nVerbose mode on. This test exercises error-reporting " "logic, so on success it will print a message " "that appears to be an error.\n"); } else { - data->log_output = fopen("/dev/null", "w"); + FILE *dev_null = data->log_output = fopen("/dev/null", "w"); ASSERT_NOT_NULL(data->log_output); + platform_set_log_streams(dev_null, dev_null); } } @@ -183,13 +190,101 @@ CTEST2(misc, test_ctest_assert_prints_user_msg_with_params) platform_close_log_stream(&stream, data->log_output); } +/* + * Simple test to verify lower-level conversion macros used by size_to_str() + */ +CTEST2(misc, test_bytes_to_fractional_value_macros) +{ + // Run through a few typical cases to check lower-level macros + size_t size = (KiB + ((25 * KiB) / 100)); // 1.25 KiB + ASSERT_EQUAL(25, B_TO_KiB_FRACT(size)); + + size = (MiB + ((5 * MiB) / 10)); // 1.5 MiB + ASSERT_EQUAL(50, B_TO_MiB_FRACT(size)); + + size = (GiB + ((75 * GiB) / 100)); // 1.75 GiB + ASSERT_EQUAL(75, B_TO_GiB_FRACT(size)); + + size = (TiB + ((5 * TiB) / 10)); // 1.5 TiB + ASSERT_EQUAL(50, B_TO_TiB_FRACT(size)); +} + +/* + * Test case to verify conversion of size value to a string with + * unit-specifiers. Do quick cross-check of the lower-level conversion macros + * involved. + */ +CTEST2(misc, test_size_to_str) +{ + char size_str[SIZE_TO_STR_LEN]; + char size_str2[SIZE_TO_STR_LEN + 2]; // size-as-string enclosed in () + typedef struct size_to_expstr { + size_t size; + char *expstr; + } size_to_expstr; + + // Verify base-case, and validate ptr returned to output string buffer. + size_t size = 0; + char *expstr = "0 bytes"; + char *outstr = size_to_str(size_str, sizeof(size_str), size); + // Conversion fn should return input-buffer's start addr as outstr. + ASSERT_TRUE(outstr == size_str); + test_streqn(expstr, outstr, 0); + + // Built expected string enclosed in () + snprintf(size_str2, sizeof(size_str2), "(%s)", size_str); + + // Size as string enclosed in () will be generated in this buffer + char *expstr2 = size_str2; + outstr = size_to_fmtstr(size_str2, sizeof(size_str2), "(%s)", size); + + // Conversion fn should return input-str's start addr as outstr. + ASSERT_TRUE(outstr == size_str2); + test_streqn(expstr2, size_str2, 0); + + // Exercise the string formatter with typical data values. + // clang-format off + size_to_expstr size_to_str_cases[] = + { + { 129 , "129 bytes" } + + , { KiB , "1 KiB" } + , { MiB , "1 MiB" } + , { GiB , "1 GiB" } + , { TiB , "1 TiB" } + + , { KiB + 128 , "~1.12 KiB" } + , { KiB + ((25 * KiB) / 100) , "~1.25 KiB" } + , { MiB + 128 , "~1.0 MiB" } + , { MiB + ((5 * MiB) / 10) , "~1.50 MiB" } + , { GiB + 128 , "~1.0 GiB" } + , { GiB + ((75 * GiB) / 100) , "~1.75 GiB" } + , { (3 * GiB) + ((5 * GiB) / 10) , "~3.50 GiB" } + , { TiB + 128 , "~1.0 TiB" } + , { (2 * TiB) + ((25 * TiB) / 100) , "~2.25 TiB" } + }; + // clang-format on + + for (int cctr = 0; cctr < ARRAY_SIZE(size_to_str_cases); cctr++) { + size = size_to_str_cases[cctr].size; + expstr = size_to_str_cases[cctr].expstr; + char *outstr = size_to_str(size_str, sizeof(size_str), size); + test_streqn(expstr, outstr, cctr); + + // Build expected string enclosed in () + snprintf(size_str2, sizeof(size_str2), "(%s)", size_str); + size_to_fmtstr(size_str, sizeof(size_str), "(%s)", size); + test_streqn(expstr2, size_str, cctr); + } +} + /* Helper functions follow all test case methods */ /* * Wrapper function to exercise platform_assert_msg() into an output * buffer. Used to test that the message is generated as expected. */ -void +static void test_platform_assert_msg(platform_log_handle *log_handle, const char *filename, int linenumber, @@ -210,8 +305,24 @@ test_platform_assert_msg(platform_log_handle *log_handle, * into an output buffer. Used to test that the message is generated as * expected. */ -void +static void test_vfprintf_usermsg(platform_log_handle *log_handle, const char *message, ...) { VFPRINTF_USERMSG(log_handle, message); } + +/* Helper fn to check that expected / actual null-terminated strings match */ +static void +test_streqn(char *expstr, char *actstr, int caseno) +{ + ASSERT_STREQN(expstr, + actstr, + strlen(expstr), + "Test case=%d failed, Expected: '%.*s', " + "Received: '%.*s'\n", + caseno, + strlen(expstr), + expstr, + strlen(expstr), + actstr); +}