From 5c16be46877e82fe555f0c344ca3478d6b4b6172 Mon Sep 17 00:00:00 2001 From: Gabriel Rosenhouse Date: Fri, 2 Dec 2022 06:41:01 +0000 Subject: [PATCH 1/4] Simplify output handling in unit tests - Unit tests respect VERBOSE environment variable, which ensures output goes to stdout/stderr. - When VERBOSE is unset, or set to "0" or "false", then: - stdout will show only 1 status line per test - stderr will be silent, except for error messages - When VERBOSE is set to any other value, then library and unit test info messages go to stdout. - When a unit test fails, the user will see a suggestion to set VERBOSE=1 to see all the detailed output. (TODO: the suggestion doesn't appear on a crash, but that'd be nice) - Library log lines from unit tests no longer go to /tmp/unit_test.std[out,err] - Platform_default_log_handle and Platform_error_log_handle are no longer part of the public API surface. Applications (and tests that mimic apps) must use platform_set_log_streams() instead. - Cleans up some tests to avoid a direct dependency on platform.h: - Removes some references to Platform_*_log_handle globals and instead calls platform_set_log_streams() - Removes some calls to platform_default_log() and instead use a dedicated CTEST_LOG_INFO() macro. - This isn't complete, but is a start - Enable VERBOSE mode when running tests in CI --- ci/jobs.lib.yml | 1 - ci/steps.lib.yml | 1 + .../platform_linux/public_platform.h | 13 +++---- src/platform_linux/platform.h | 3 ++ tests/unit/btree_stress_test.c | 12 ++----- tests/unit/config_parse_test.c | 3 -- tests/unit/ctest.h | 13 +++++++ tests/unit/limitations_test.c | 26 +++++++++----- tests/unit/main.c | 35 +++++++++++++++++++ tests/unit/misc_test.c | 26 +++++++++++--- tests/unit/splinter_test.c | 3 -- tests/unit/splinterdb_quick_test.c | 6 ++-- tests/unit/splinterdb_stress_test.c | 33 ++++++++--------- tests/unit/task_system_test.c | 3 -- tests/unit/util_test.c | 12 +++---- 15 files changed, 120 insertions(+), 70 deletions(-) diff --git a/ci/jobs.lib.yml b/ci/jobs.lib.yml index 2f7614c23..b36cdc6d5 100644 --- a/ci/jobs.lib.yml +++ b/ci/jobs.lib.yml @@ -15,7 +15,6 @@ #@ load("sequences.lib.yml", -#@ "sequence_pr_build_test", #@ "sequence_pr_debug_build_test", #@ "sequence_pr_clang_format", #@ "sequence_pr_shell_scripts", diff --git a/ci/steps.lib.yml b/ci/steps.lib.yml index 27bb35038..70e02d2c0 100644 --- a/ci/steps.lib.yml +++ b/ci/steps.lib.yml @@ -105,6 +105,7 @@ config: INCLUDE_SLOW_TESTS: #@ str(not quick).lower() RUN_NIGHTLY_TESTS: #@ str(test_nightly).lower() BUILD_VERBOSE: "1" + VERBOSE: "1" #! Exercise 'make help' in quick tests mode, to ensure 'help' still works. #@ if quick: diff --git a/include/splinterdb/platform_linux/public_platform.h b/include/splinterdb/platform_linux/public_platform.h index 3d773e236..a4bf3d064 100644 --- a/include/splinterdb/platform_linux/public_platform.h +++ b/include/splinterdb/platform_linux/public_platform.h @@ -67,17 +67,12 @@ typedef int32 bool; #endif typedef uint8 bool8; -// By default, platform_default_log() messages are sent to /dev/null -// and platform_error_log() messages go to stderr. -// -// Use platform_set_log_streams() to send the log messages elsewhere. -typedef FILE platform_log_handle; -extern platform_log_handle *Platform_default_log_handle; -extern platform_log_handle *Platform_error_log_handle; +typedef FILE platform_log_handle; -// Set the streams where informational and error messages will be printed. +// By default, info messages sent from platform_default_log() go to /dev/null +// and error messages sent from platform_error_log() go to stderr. // -// These default to /dev/null and stderr, respectively. +// Use platform_set_log_streams() to send those log messages elsewhere. // // For example, to send info messages to stdout and errors to stderr, run: // platform_set_log_streams(stdout, stderr); diff --git a/src/platform_linux/platform.h b/src/platform_linux/platform.h index 228dbe447..f148629a6 100644 --- a/src/platform_linux/platform.h +++ b/src/platform_linux/platform.h @@ -170,12 +170,15 @@ typedef struct { extern bool platform_use_hugetlb; extern bool platform_use_mlock; + /* * Section 3: * Shared types/typedefs that rely on platform-specific types/typedefs * There should not be any generic #includes here, but potentially #includes * of headers defined in splinterdb cannot be included until now. */ +extern platform_log_handle *Platform_default_log_handle; +extern platform_log_handle *Platform_error_log_handle; /* diff --git a/tests/unit/btree_stress_test.c b/tests/unit/btree_stress_test.c index 92ca6414b..e9d10ce6b 100644 --- a/tests/unit/btree_stress_test.c +++ b/tests/unit/btree_stress_test.c @@ -234,23 +234,15 @@ CTEST2(btree_stress, test_random_inserts_concurrent) if (!iterator_tests( (cache *)&data->cc, &data->dbtree_cfg, root_addr, nkvs, data->hid)) { - platform_default_log("invalid ranges in original tree\n"); + CTEST_ERR("invalid ranges in original tree\n"); } - /* platform_default_log("\n\n\n"); */ - /* btree_print_tree((cache *)&cc, &dbtree_cfg, root_addr); */ - uint64 packed_root_addr = pack_tests( (cache *)&data->cc, &data->dbtree_cfg, data->hid, root_addr, nkvs); if (0 < nkvs && !packed_root_addr) { ASSERT_TRUE(FALSE, "Pack failed.\n"); } - /* platform_default_log("\n\n\n"); */ - /* btree_print_tree((cache *)&cc, &dbtree_cfg, - * packed_root_addr); */ - /* platform_default_log("\n\n\n"); */ - rc = query_tests((cache *)&data->cc, &data->dbtree_cfg, data->hid, @@ -493,7 +485,7 @@ pack_tests(cache *cc, if (!SUCCESS(btree_pack(&req))) { ASSERT_TRUE(FALSE, "Pack failed! req.num_tuples = %d\n", req.num_tuples); } else { - platform_default_log("Packed %lu items ", req.num_tuples); + CTEST_LOG_INFO("Packed %lu items ", req.num_tuples); } btree_pack_req_deinit(&req, hid); diff --git a/tests/unit/config_parse_test.c b/tests/unit/config_parse_test.c index 11393d091..31b8d8e21 100644 --- a/tests/unit/config_parse_test.c +++ b/tests/unit/config_parse_test.c @@ -41,9 +41,6 @@ CTEST_DATA(config_parse) // Optional setup function for suite, called before every test in suite CTEST_SETUP(config_parse) { - Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+"); - Platform_error_log_handle = fopen("/tmp/unit_test.stderr", "a+"); - uint64 heap_capacity = (1024 * MiB); // Create a heap for io, allocator, cache and splinter platform_status rc = platform_heap_create( diff --git a/tests/unit/ctest.h b/tests/unit/ctest.h index d6242b775..4b9f6dada 100644 --- a/tests/unit/ctest.h +++ b/tests/unit/ctest.h @@ -79,6 +79,19 @@ struct ctest { unsigned int magic; }; +// If 0, then CTEST_LOG_INFO() and CTEST_LOG() will no-op. Defaults to 0. +extern int Ctest_verbosity; + +// For immedate logging to stdout +// (contrast with CTEST_LOG which does buffered/delayed logging to stderr) +#define CTEST_LOG_INFO(...) \ + do { \ + if (Ctest_verbosity) { \ + fprintf(stdout, __VA_ARGS__); \ + fflush(stdout); \ + } \ + } while (0) + /* * Global handles to command-line args are provided so that we can access * argc/argv indirectly thru these global variables inside setup methods. diff --git a/tests/unit/limitations_test.c b/tests/unit/limitations_test.c index e23f74898..66b907c9a 100644 --- a/tests/unit/limitations_test.c +++ b/tests/unit/limitations_test.c @@ -63,24 +63,32 @@ CTEST_DATA(limitations) * Setup heap memory to be used later to test Splinter configuration. * splinter_test(). */ -// clang-format off CTEST_SETUP(limitations) { - Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+"); - Platform_error_log_handle = fopen("/tmp/unit_test.stderr", "a+"); + // This test exercises error cases, so even when everthing succeeds + // it generates lots of "error" messages. + // By default, that would go to stderr, which would pollute test output. + // Here we ensure those expected error messages are only printed + // when the caller sets the VERBOSE env var to opt-in. + if (Ctest_verbosity) { + 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); + } uint64 heap_capacity = (1 * GiB); // Create a heap for io, allocator, cache and splinter - platform_status rc = platform_heap_create(platform_get_module_id(), - heap_capacity, - &data->hh, - &data->hid); + platform_status rc = platform_heap_create( + platform_get_module_id(), heap_capacity, &data->hh, &data->hid); platform_assert_status_ok(rc); } -// clang-format on - /* * Tear down memory allocated for various sub-systems. Shutdown Splinter. */ diff --git a/tests/unit/main.c b/tests/unit/main.c index 19e6141dd..ca1175fb0 100644 --- a/tests/unit/main.c +++ b/tests/unit/main.c @@ -35,6 +35,9 @@ static const char *testcase_name = NULL; typedef int (*ctest_filter_func)(struct ctest *); +// If 0, then CTEST_LOG_INFO() and CTEST_LOG() will no-op. Defaults to 0. +int Ctest_verbosity = 0; + /* * Global handles to command-line args are provided so that we can access * argc/argv indirectly thru these global variables inside setup methods. @@ -88,6 +91,9 @@ ctest_process_args(const int argc, int ctest_is_unit_test(const char *argv0); +static int +ctest_get_verbosity(); + static int suite_all(struct ctest *t); @@ -170,6 +176,8 @@ ctest_main(int argc, const char *argv[]) signal(SIGSEGV, sighandler); #endif + Ctest_verbosity = ctest_get_verbosity(); + int program_is_unit_test = ctest_is_unit_test(argv[0]); int print_list = 0; // Are we processing --list arg? @@ -340,6 +348,13 @@ ctest_main(int argc, const char *argv[]) num_skip, (t2 - t1) / 1000); color_print(color, results); + + if (num_fail > 0 && Ctest_verbosity == 0) { + snprintf(results, + sizeof(results), + "(Rerun with env var VERBOSE=1 to see more log messages)"); + color_print(color, results); + } return num_fail; } @@ -384,6 +399,22 @@ ctest_is_unit_test(const char *argv0) return 0; } +// Determine the log message verbosity to use for this test run. +// If env var VERBOSE is unset, or is set to "0" or "false", the be quiet. +// Otherwise, be verbose. +static int +ctest_get_verbosity() +{ + char *val = getenv("VERBOSE"); + if (val == NULL) { + return 0; + } + if ((strcmp(val, "0") == 0) || (strcmp(val, "false") == 0)) { + return 0; + } + return 1; +} + /* * --------------------------------------------------------------------------- * Process the command-line arguments. The main job of this function is to @@ -718,6 +749,10 @@ msg_end(void) void CTEST_LOG(const char *fmt, ...) { + if (Ctest_verbosity == 0) { + return; + } + va_list argp; msg_start(ANSI_BLUE, "LOG"); diff --git a/tests/unit/misc_test.c b/tests/unit/misc_test.c index ab41c89a6..5218d3a02 100644 --- a/tests/unit/misc_test.c +++ b/tests/unit/misc_test.c @@ -56,9 +56,25 @@ test_vfprintf_usermsg(platform_log_handle *log_handle, /* * Global data declaration macro: */ -CTEST_DATA(misc){}; +CTEST_DATA(misc) +{ + FILE *log_output; +}; -CTEST_SETUP(misc) {} +CTEST_SETUP(misc) +{ + // It can be surprising to see errors printed from a successful test run. + // So lets send those messages to /dev/null unless VERBOSE=1. + if (Ctest_verbosity) { + data->log_output = stdout; + 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"); + ASSERT_NOT_NULL(data->log_output); + } +} // Optional teardown function for suite, called after every test in suite CTEST_TEARDOWN(misc) {} @@ -90,7 +106,7 @@ CTEST2(misc, test_assert_basic_msg) MISC_MSG_WITH_NO_ARGS); ASSERT_STREQN(expmsg, assert_str, strlen(expmsg)); - platform_close_log_stream(&stream, Platform_error_log_handle); + platform_close_log_stream(&stream, data->log_output); } /* @@ -127,7 +143,7 @@ CTEST2(misc, test_assert_msg_with_args) arg_name); ASSERT_STREQN(expmsg, assert_str, strlen(expmsg)); - platform_close_log_stream(&stream, Platform_error_log_handle); + platform_close_log_stream(&stream, data->log_output); } /* @@ -164,7 +180,7 @@ CTEST2(misc, test_ctest_assert_prints_user_msg_with_params) expmsg, expmsg_len, assert_str); - platform_close_log_stream(&stream, Platform_error_log_handle); + platform_close_log_stream(&stream, data->log_output); } /* Helper functions follow all test case methods */ diff --git a/tests/unit/splinter_test.c b/tests/unit/splinter_test.c index 7e8cbff7e..fea44d59d 100644 --- a/tests/unit/splinter_test.c +++ b/tests/unit/splinter_test.c @@ -112,9 +112,6 @@ CTEST_DATA(splinter) // clang-format off CTEST_SETUP(splinter) { - Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+"); - Platform_error_log_handle = fopen("/tmp/unit_test.stderr", "a+"); - // Defaults: For basic unit-tests, use single threads data->num_insert_threads = 1; data->num_lookup_threads = 1; diff --git a/tests/unit/splinterdb_quick_test.c b/tests/unit/splinterdb_quick_test.c index 899cd656e..8cbab9cb1 100644 --- a/tests/unit/splinterdb_quick_test.c +++ b/tests/unit/splinterdb_quick_test.c @@ -94,11 +94,13 @@ CTEST_DATA(splinterdb_quick) comparison_counting_data_config default_data_cfg; }; + // Optional setup function for suite, called before every test in suite CTEST_SETUP(splinterdb_quick) { - Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+"); - Platform_error_log_handle = fopen("/tmp/unit_test.stderr", "a+"); + if (Ctest_verbosity > 0) { + platform_set_log_streams(stdout, stderr); + } default_data_config_init(TEST_MAX_KEY_SIZE, &data->default_data_cfg.super); create_default_cfg(&data->cfg, &data->default_data_cfg.super); diff --git a/tests/unit/splinterdb_stress_test.c b/tests/unit/splinterdb_stress_test.c index 402892c68..feb843a42 100644 --- a/tests/unit/splinterdb_stress_test.c +++ b/tests/unit/splinterdb_stress_test.c @@ -48,8 +48,9 @@ CTEST_DATA(splinterdb_stress) // Setup function for suite, called before every test in suite CTEST_SETUP(splinterdb_stress) { - Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+"); - Platform_error_log_handle = fopen("/tmp/unit_test.stderr", "a+"); + if (Ctest_verbosity > 0) { + platform_set_log_streams(stdout, stderr); + } data->cfg = (splinterdb_config){.filename = TEST_DB_NAME, .cache_size = 1000 * Mega, @@ -88,9 +89,9 @@ CTEST2(splinterdb_stress, test_random_inserts_concurrent) ASSERT_EQUAL(0, rc); } - fprintf(stderr, "Waiting for %d worker threads ...\n", num_threads); + CTEST_LOG_INFO("Waiting for %d worker threads ...\n", num_threads); for (int i = 0; i < num_threads; i++) { - fprintf(stderr, " Thread[%d] ID=%lu\n", i, thread_ids[i]); + CTEST_LOG_INFO(" Thread[%d] ID=%lu\n", i, thread_ids[i]); } for (int i = 0; i < num_threads; i++) { @@ -98,12 +99,8 @@ CTEST2(splinterdb_stress, test_random_inserts_concurrent) int rc = pthread_join(thread_ids[i], &thread_rc); ASSERT_EQUAL(0, rc); if (thread_rc != 0) { - fprintf(stderr, - "Thread %d [ID=%lu] had error: %p\n", - i, - thread_ids[i], - thread_rc); - ASSERT_TRUE(FALSE); + CTEST_ERR( + "Thread %d [ID=%lu] had error: %p\n", i, thread_ids[i], thread_rc); } } } @@ -120,7 +117,7 @@ CTEST2(splinterdb_stress, test_naive_range_delete) const uint32 num_inserts = 2 * 1000 * 1000; - platform_default_log("loading data..."); + CTEST_LOG_INFO("loading data..."); for (uint32 i = 0; i < num_inserts; i++) { char key_buffer[TEST_KEY_SIZE] = {0}; char value_buffer[TEST_VALUE_SIZE] = {0}; @@ -132,11 +129,11 @@ CTEST2(splinterdb_stress, test_naive_range_delete) ASSERT_EQUAL(0, rc); } - platform_default_log("loaded %u k/v pairs\n", num_inserts); + CTEST_LOG_INFO("loaded %u k/v pairs\n", num_inserts); uint32 num_rounds = 5; for (uint32 round = 0; round < num_rounds; round++) { - platform_default_log("range delete round %d...\n", round); + CTEST_LOG_INFO("range delete round %d...\n", round); char start_key_data[4]; random_bytes(&rand_state, start_key_data, sizeof(start_key_data)); const uint32 num_to_delete = num_inserts / num_rounds; @@ -164,7 +161,7 @@ exec_worker_thread(void *w) pthread_t thread_id = pthread_self(); - fprintf(stderr, "Writing lots of data from thread %lu\n", thread_id); + CTEST_LOG_INFO("Writing lots of data from thread %lu\n", thread_id); int rc = 0; for (uint32_t i = 0; i < num_inserts; i++) { size_t result = read(random_data, key_buf, sizeof key_buf); @@ -179,7 +176,7 @@ exec_worker_thread(void *w) ASSERT_EQUAL(0, rc); if (i && (i % 100000 == 0)) { - fprintf(stderr, "Thread %lu has completed %u inserts\n", thread_id, i); + CTEST_LOG_INFO("Thread %lu has completed %u inserts\n", thread_id, i); } } @@ -192,7 +189,7 @@ exec_worker_thread(void *w) static void naive_range_delete(const splinterdb *kvsb, slice start_key, uint32 count) { - platform_default_log("\tcollecting keys to delete...\n"); + CTEST_LOG_INFO("\tcollecting keys to delete...\n"); char *keys_to_delete = calloc(count, TEST_KEY_SIZE); splinterdb_iterator *it; @@ -218,7 +215,7 @@ naive_range_delete(const splinterdb *kvsb, slice start_key, uint32 count) ASSERT_EQUAL(0, rc); splinterdb_iterator_deinit(it); - platform_default_log("\tdeleting collected keys...\n"); + CTEST_LOG_INFO("\tdeleting collected keys...\n"); for (uint32 i = 0; i < num_found; i++) { slice key_to_delete = slice_create(TEST_KEY_SIZE, keys_to_delete + i * TEST_KEY_SIZE); @@ -226,5 +223,5 @@ naive_range_delete(const splinterdb *kvsb, slice start_key, uint32 count) } free(keys_to_delete); - platform_default_log("\tdeleted %u k/v pairs\n", num_found); + CTEST_LOG_INFO("\tdeleted %u k/v pairs\n", num_found); } diff --git a/tests/unit/task_system_test.c b/tests/unit/task_system_test.c index 00e707d6c..3423e00d9 100644 --- a/tests/unit/task_system_test.c +++ b/tests/unit/task_system_test.c @@ -79,9 +79,6 @@ CTEST_DATA(task_system) */ CTEST_SETUP(task_system) { - Platform_default_log_handle = fopen("/tmp/unit_test.stdout", "a+"); - Platform_error_log_handle = fopen("/tmp/unit_test.stderr", "a+"); - uint64 heap_capacity = (256 * MiB); // small heap is sufficient. platform_status rc = STATUS_OK; diff --git a/tests/unit/util_test.c b/tests/unit/util_test.c index 2a86db39e..95927f18e 100644 --- a/tests/unit/util_test.c +++ b/tests/unit/util_test.c @@ -106,13 +106,11 @@ check_one_debug_hex_encode(size_t dst_len, // Indentation is intentional, so both outputs line up for easier // visual comparison in case of failures. - fprintf(stderr, - "unexpected output: '%.*s',\n" - " expected output: '%s'\n", - dst_full_size, - dst, - expected); - return -1; + CTEST_ERR("unexpected output: '%.*s',\n" + " expected output: '%s'\n", + dst_full_size, + dst, + expected); } return 0; } From b49ec5495a007baaa012848ccd59bdae48aebc45 Mon Sep 17 00:00:00 2001 From: Gabriel Rosenhouse Date: Tue, 6 Dec 2022 20:26:44 +0000 Subject: [PATCH 2/4] fixup: move file_error_returns test to limitations test file --- tests/unit/limitations_test.c | 22 ++++++++++++++++++++++ tests/unit/splinterdb_quick_test.c | 23 ----------------------- 2 files changed, 22 insertions(+), 23 deletions(-) diff --git a/tests/unit/limitations_test.c b/tests/unit/limitations_test.c index 66b907c9a..3002b404e 100644 --- a/tests/unit/limitations_test.c +++ b/tests/unit/limitations_test.c @@ -384,6 +384,28 @@ CTEST2(limitations, test_zero_cache_size) int rc = splinterdb_create(&cfg, &kvsb); ASSERT_NOT_EQUAL(0, rc); } +/* + * Check that errors on file-opening are returned, not asserted. + * Previously, a user error, e.g. bad file permissions, would + * just crash the program. + */ +CTEST2(limitations, test_file_error_returns) +{ + splinterdb *kvsb; + splinterdb_config cfg; + data_config default_data_cfg; + + default_data_config_init(TEST_MAX_KEY_SIZE, &default_data_cfg); + create_default_cfg(&cfg, &default_data_cfg); + + cfg.filename = "/dev/null/this-file-cannot-possibly-be-opened"; + + // this will fail, but shouldn't crash! + int rc = splinterdb_create(&cfg, &kvsb); + ASSERT_NOT_EQUAL(0, rc); + // if we've made it this far, at least the application can report + // the error and recover! +} /* * Helper routine to create a valid Splinter configuration using default diff --git a/tests/unit/splinterdb_quick_test.c b/tests/unit/splinterdb_quick_test.c index 8cbab9cb1..9621719ae 100644 --- a/tests/unit/splinterdb_quick_test.c +++ b/tests/unit/splinterdb_quick_test.c @@ -857,29 +857,6 @@ CTEST2(splinterdb_quick, test_iterator_init_bug) splinterdb_iterator_deinit(it); } -/* - * Check that errors on file-opening are returned, not asserted. - * Previously, a user error, e.g. bad file permissions, would - * just crash the program. - */ -CTEST2(splinterdb_quick, test_file_error_returns) -{ - // Tear down default instance, so we can try to create a new one. - splinterdb_close(&data->kvsb); - - data->cfg.filename = "/dev/null/this-file-cannot-possibly-be-opened"; - - fprintf(Platform_error_log_handle, - "=== Testing an error condition, expect to see error messages " - "following this\n"); - // this will fail, but shouldn't crash! - int rc = splinterdb_create(&data->cfg, &data->kvsb); - ASSERT_TRUE(0 != rc); - fprintf(Platform_error_log_handle, "^^^ Done testing an error condition\n"); - // if we've made it this far, at least the application can report - // the error and recover! -} - /* * ******************************************************************************** * Define minions and helper functions here, after all test cases are From 0a635e8ed2aec661de5a88864bf8789a0bb906e4 Mon Sep 17 00:00:00 2001 From: Gabriel Rosenhouse Date: Tue, 6 Dec 2022 20:46:44 +0000 Subject: [PATCH 3/4] code review fix: change verbose global to be a _Bool --- tests/unit/ctest.h | 6 +++--- tests/unit/limitations_test.c | 2 +- tests/unit/main.c | 14 +++++++------- tests/unit/misc_test.c | 2 +- tests/unit/splinterdb_quick_test.c | 2 +- tests/unit/splinterdb_stress_test.c | 2 +- 6 files changed, 14 insertions(+), 14 deletions(-) diff --git a/tests/unit/ctest.h b/tests/unit/ctest.h index 4b9f6dada..4411275e9 100644 --- a/tests/unit/ctest.h +++ b/tests/unit/ctest.h @@ -79,14 +79,14 @@ struct ctest { unsigned int magic; }; -// If 0, then CTEST_LOG_INFO() and CTEST_LOG() will no-op. Defaults to 0. -extern int Ctest_verbosity; +// If FALSE (default), then CTEST_LOG_INFO() and CTEST_LOG() will no-op. +extern _Bool Ctest_verbose; // For immedate logging to stdout // (contrast with CTEST_LOG which does buffered/delayed logging to stderr) #define CTEST_LOG_INFO(...) \ do { \ - if (Ctest_verbosity) { \ + if (Ctest_verbose) { \ fprintf(stdout, __VA_ARGS__); \ fflush(stdout); \ } \ diff --git a/tests/unit/limitations_test.c b/tests/unit/limitations_test.c index 3002b404e..914f69dbd 100644 --- a/tests/unit/limitations_test.c +++ b/tests/unit/limitations_test.c @@ -70,7 +70,7 @@ CTEST_SETUP(limitations) // By default, that would go to stderr, which would pollute test output. // Here we ensure those expected error messages are only printed // when the caller sets the VERBOSE env var to opt-in. - if (Ctest_verbosity) { + 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 " diff --git a/tests/unit/main.c b/tests/unit/main.c index ca1175fb0..7e78d3895 100644 --- a/tests/unit/main.c +++ b/tests/unit/main.c @@ -35,8 +35,8 @@ static const char *testcase_name = NULL; typedef int (*ctest_filter_func)(struct ctest *); -// If 0, then CTEST_LOG_INFO() and CTEST_LOG() will no-op. Defaults to 0. -int Ctest_verbosity = 0; +// If false, then CTEST_LOG_INFO() and CTEST_LOG() will no-op. +_Bool Ctest_verbose = FALSE; /* * Global handles to command-line args are provided so that we can access @@ -91,7 +91,7 @@ ctest_process_args(const int argc, int ctest_is_unit_test(const char *argv0); -static int +static bool ctest_get_verbosity(); static int @@ -176,7 +176,7 @@ ctest_main(int argc, const char *argv[]) signal(SIGSEGV, sighandler); #endif - Ctest_verbosity = ctest_get_verbosity(); + Ctest_verbose = ctest_get_verbosity(); int program_is_unit_test = ctest_is_unit_test(argv[0]); @@ -349,7 +349,7 @@ ctest_main(int argc, const char *argv[]) (t2 - t1) / 1000); color_print(color, results); - if (num_fail > 0 && Ctest_verbosity == 0) { + if (num_fail > 0 && !Ctest_verbose) { snprintf(results, sizeof(results), "(Rerun with env var VERBOSE=1 to see more log messages)"); @@ -402,7 +402,7 @@ ctest_is_unit_test(const char *argv0) // Determine the log message verbosity to use for this test run. // If env var VERBOSE is unset, or is set to "0" or "false", the be quiet. // Otherwise, be verbose. -static int +static bool ctest_get_verbosity() { char *val = getenv("VERBOSE"); @@ -749,7 +749,7 @@ msg_end(void) void CTEST_LOG(const char *fmt, ...) { - if (Ctest_verbosity == 0) { + if (!Ctest_verbose) { return; } diff --git a/tests/unit/misc_test.c b/tests/unit/misc_test.c index 5218d3a02..357e82414 100644 --- a/tests/unit/misc_test.c +++ b/tests/unit/misc_test.c @@ -65,7 +65,7 @@ CTEST_SETUP(misc) { // It can be surprising to see errors printed from a successful test run. // So lets send those messages to /dev/null unless VERBOSE=1. - if (Ctest_verbosity) { + if (Ctest_verbose) { data->log_output = stdout; CTEST_LOG_INFO("\nVerbose mode on. This test exercises error-reporting " "logic, so on success it will print a message " diff --git a/tests/unit/splinterdb_quick_test.c b/tests/unit/splinterdb_quick_test.c index 9621719ae..1bea53522 100644 --- a/tests/unit/splinterdb_quick_test.c +++ b/tests/unit/splinterdb_quick_test.c @@ -98,7 +98,7 @@ CTEST_DATA(splinterdb_quick) // Optional setup function for suite, called before every test in suite CTEST_SETUP(splinterdb_quick) { - if (Ctest_verbosity > 0) { + if (Ctest_verbose) { platform_set_log_streams(stdout, stderr); } diff --git a/tests/unit/splinterdb_stress_test.c b/tests/unit/splinterdb_stress_test.c index feb843a42..7a23c4fc4 100644 --- a/tests/unit/splinterdb_stress_test.c +++ b/tests/unit/splinterdb_stress_test.c @@ -48,7 +48,7 @@ CTEST_DATA(splinterdb_stress) // Setup function for suite, called before every test in suite CTEST_SETUP(splinterdb_stress) { - if (Ctest_verbosity > 0) { + if (Ctest_verbose) { platform_set_log_streams(stdout, stderr); } From 5d3e22407871dc98cb705e78a03af5110ecf0211 Mon Sep 17 00:00:00 2001 From: Gabriel Rosenhouse Date: Tue, 6 Dec 2022 21:06:06 +0000 Subject: [PATCH 4/4] fixup: unit/splinter_test.c uses new logging apis --- tests/unit/splinter_test.c | 77 ++++++++++++++++++++------------------ 1 file changed, 41 insertions(+), 36 deletions(-) diff --git a/tests/unit/splinter_test.c b/tests/unit/splinter_test.c index fea44d59d..1616e982c 100644 --- a/tests/unit/splinter_test.c +++ b/tests/unit/splinter_test.c @@ -5,7 +5,10 @@ * ----------------------------------------------------------------------------- * splinter_test.c -- * - * Exercises the basic SplinterDB interfaces. + * Exercises internal interfaces, using private APIs. + * + * If you're writing new unit tests of the public API, please do not use this + * file as a template or example. * * NOTE: There is some duplication of the splinter_do_inserts() in the test * cases which adds considerable execution times. The test_inserts() test case @@ -112,6 +115,9 @@ CTEST_DATA(splinter) // clang-format off CTEST_SETUP(splinter) { + if (Ctest_verbose) { + platform_set_log_streams(stdout, stderr); + } // Defaults: For basic unit-tests, use single threads data->num_insert_threads = 1; data->num_lookup_threads = 1; @@ -163,12 +169,12 @@ CTEST_SETUP(splinter) io_config * io_cfgp = &data->io_cfg; if (io_cfgp->async_queue_size < total_threads * data->max_async_inflight) { io_cfgp->async_queue_size = ROUNDUP(total_threads * data->max_async_inflight, 32); - platform_default_log("Bumped up IO queue size to %lu\n", io_cfgp->async_queue_size); + CTEST_LOG_INFO("Bumped up IO queue size to %lu\n", io_cfgp->async_queue_size); } if (io_cfgp->kernel_queue_size < total_threads * data->max_async_inflight) { io_cfgp->kernel_queue_size = ROUNDUP(total_threads * data->max_async_inflight, 32); - platform_default_log("Bumped up IO queue size to %lu\n", + CTEST_LOG_INFO("Bumped up IO queue size to %lu\n", io_cfgp->kernel_queue_size); } @@ -451,7 +457,7 @@ CTEST2(splinter, test_lookups) // ************************************************************************** uint64 start_time = platform_get_timestamp(); - platform_default_log("\n"); + CTEST_LOG_INFO("\n"); for (uint64 insert_num = 0; insert_num < num_inserts; insert_num++) { // Show progress message in %age-completed to stdout @@ -476,7 +482,7 @@ CTEST2(splinter, test_lookups) } uint64 elapsed_ns = platform_timestamp_elapsed(start_time); - platform_default_log( + CTEST_LOG_INFO( " ... splinter positive lookup time %lu s, per tuple %lu ns\n", NSEC_TO_SEC(elapsed_ns), (elapsed_ns / num_inserts)); @@ -513,7 +519,7 @@ CTEST2(splinter, test_lookups) } elapsed_ns = platform_timestamp_elapsed(start_time); - platform_default_log( + CTEST_LOG_INFO( " ... splinter negative lookup time %lu s, per tuple %lu ns\n", NSEC_TO_SEC(elapsed_ns), (elapsed_ns / num_inserts)); @@ -524,8 +530,8 @@ CTEST2(splinter, test_lookups) // ************************************************************************** int niters = 3; - platform_default_log( - "Perform test_lookup_by_range() for %d iterations ...\n", niters); + CTEST_LOG_INFO("Perform test_lookup_by_range() for %d iterations ...\n", + niters); // Iterate thru small set of num_ranges for additional coverage. trunk_shadow_sort(&shadow); for (int ictr = 1; ictr <= 3; ictr++) { @@ -579,7 +585,7 @@ CTEST2(splinter, test_lookups) test_wait_for_inflight(spl, async_lookup, &vtarg_true); elapsed_ns = platform_timestamp_elapsed(start_time); - platform_default_log( + CTEST_LOG_INFO( " ... splinter positive async lookup time %lu s, per tuple %lu ns\n", NSEC_TO_SEC(elapsed_ns), (elapsed_ns / num_inserts)); @@ -610,7 +616,7 @@ CTEST2(splinter, test_lookups) test_wait_for_inflight(spl, async_lookup, &vtarg_false); elapsed_ns = platform_timestamp_elapsed(start_time); - platform_default_log( + CTEST_LOG_INFO( " ... splinter negative async lookup time %lu s, per tuple %lu ns\n", NSEC_TO_SEC(elapsed_ns), (elapsed_ns / num_inserts)); @@ -651,20 +657,20 @@ CTEST2(splinter, test_splinter_print_diags) "Expected to have inserted non-zero rows, num_inserts=%lu", num_inserts); - platform_default_log("**** Splinter Diagnostics ****\n" - "Generated by %s:%d:%s ****\n", - __FILE__, - __LINE__, - __FUNCTION__); + CTEST_LOG_INFO("**** Splinter Diagnostics ****\n" + "Generated by %s:%d:%s ****\n", + __FILE__, + __LINE__, + __FUNCTION__); trunk_print_super_block(Platform_default_log_handle, spl); trunk_print_space_use(Platform_default_log_handle, spl); - platform_default_log("\n** trunk_print() **\n"); + CTEST_LOG_INFO("\n** trunk_print() **\n"); trunk_print(Platform_default_log_handle, spl); - platform_default_log("\n** Allocator stats **\n"); + CTEST_LOG_INFO("\n** Allocator stats **\n"); allocator_print_stats(alp); allocator_print_allocated(alp); @@ -712,13 +718,13 @@ splinter_do_inserts(void *datap, / generator_average_message_size(&data->gen); } - platform_default_log("Splinter_cfg max_kv_bytes_per_node=%lu" - ", fanout=%lu" - ", max_extents_per_memtable=%lu, num_inserts=%d. ", - data->splinter_cfg[0].max_kv_bytes_per_node, - data->splinter_cfg[0].fanout, - data->splinter_cfg[0].mt_cfg.max_extents_per_memtable, - num_inserts); + CTEST_LOG_INFO("Splinter_cfg max_kv_bytes_per_node=%lu" + ", fanout=%lu" + ", max_extents_per_memtable=%lu, num_inserts=%d. ", + data->splinter_cfg[0].max_kv_bytes_per_node, + data->splinter_cfg[0].fanout, + data->splinter_cfg[0].mt_cfg.max_extents_per_memtable, + num_inserts); uint64 start_time = platform_get_timestamp(); uint64 insert_num; @@ -733,9 +739,9 @@ splinter_do_inserts(void *datap, platform_status rc; - platform_default_log("trunk_insert() test with %d inserts %s ...\n", - num_inserts, - (verify ? "and verify" : "")); + CTEST_LOG_INFO("trunk_insert() test with %d inserts %s ...\n", + num_inserts, + (verify ? "and verify" : "")); merge_accumulator msg; merge_accumulator_init(&msg, spl->heap_id); for (insert_num = 0; insert_num < num_inserts; insert_num++) { @@ -771,7 +777,7 @@ splinter_do_inserts(void *datap, uint64 elapsed_s = NSEC_TO_SEC(elapsed_ns); // For small # of inserts, elapsed sec will be 0. Deal with it. - platform_default_log( + CTEST_LOG_INFO( "... average tuple_size=%lu, splinter insert time %lu s, per " "tuple %lu ns, %s%lu rows/sec. ", key_size + generator_average_message_size(&data->gen), @@ -817,9 +823,8 @@ shadow_check_tuple_func(key returned_key, message value, void *varg) trunk_message_to_string(arg->spl, shadow_value, expected_value); trunk_message_to_string(arg->spl, value, actual_value); - platform_default_log( - "expected: '%s' | '%s'\n", expected_key, expected_value); - platform_default_log("actual : '%s' | '%s'\n", actual_key, actual_value); + CTEST_LOG_INFO("expected: '%s' | '%s'\n", expected_key, expected_value); + CTEST_LOG_INFO("actual : '%s' | '%s'\n", actual_key, actual_value); arg->errors++; } @@ -897,11 +902,11 @@ test_lookup_by_range(void *datap, } uint64 elapsed_ns = platform_timestamp_elapsed(start_time); - platform_default_log(" ... splinter range time %lu s, per operation %lu ns" - ", %lu ranges\n", - NSEC_TO_SEC(elapsed_ns), - (elapsed_ns / num_ranges), - num_ranges); + CTEST_LOG_INFO(" ... splinter range time %lu s, per operation %lu ns" + ", %lu ranges\n", + NSEC_TO_SEC(elapsed_ns), + (elapsed_ns / num_ranges), + num_ranges); return rc; }