Simplify output handling in unit tests by rosenhouse · Pull Request #494 · vmware/splinterdb

rosenhouse · 2022-12-02T18:43:01Z

Unit tests respect a new 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 (see Enable application to silence info logs #487)
Cleans up some tests to avoid a direct dependency on platform.h:
- Removes some references to Platform_*_log_handle globals and instead calls new 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

Fixes #288

Here's a side-by-side comparison, running in quiet mode (default) on the left, and with VERBOSE=1 on the right.

and here's what it looks like when a test fails and you haven't set VERBOSE yet:

netlify · 2022-12-02T18:43:10Z

✅ Deploy Preview for splinterdb canceled.

Name	Link
🔨 Latest commit	`5d3e224`
🔍 Latest deploy log	https://app.netlify.com/sites/splinterdb/deploys/638faf8d2fd2270008975134

rtjohnso

I generally prefer command-line args over environment variables, but env vars are fine if there's a technical challenge to implementing this as a command-line arg.

rtjohnso · 2022-12-02T19:35:14Z

ci/steps.lib.yml

    INCLUDE_SLOW_TESTS: #@ str(not quick).lower()
    RUN_NIGHTLY_TESTS: #@ str(test_nightly).lower()
    BUILD_VERBOSE: "1"
+    VERBOSE: "1"


Any reason to make this an environment variable instead of a command-line option?

Yeah, a flag would be preferable for ease of typing and for discoverability. I just couldn't figure out how to make it work: the interactions between unit/main.c, config.h, unit/config_parse_test.c, and unit/splinter_test.c were just too messy for me to untangle in the couple hours that I spent on this. I'd welcome some help on that from @gapisback or anyone else.

+1, that would be ideal, but I can see why that would be tricky. Future work.

@rosenhouse -- I'll need to think this through with you. Am looking at the diffs now and pondered over how to achieve what you want.

Some time ago, I had added this --verbose-progress option that was used initially in functional/splinter_test.c to do some verbose progress reporting while large test workloads run. This arg is parsed and tracked as a bool in test_exec_config->verbose_progress.

With some work we could co-opt this flag to also mean what this VERBOSE=1 env-var wants to do. This boolean field may be the replacement for your newly-added Ctest_verbosity flag.

I'm not entirely sure that this scheme will work to meet all the requirements this change-set is bringing-in. (For instance, the functional tests still seem to spit out messages to stdout even when VERBOSE is not set. I'm a bit confused as to what the expected design is with regards to outputs from tests with this and your previous commit at SHA d2e9e86.)

If there is not a great hurry to replace the new env-var with a command line arg, my suggestion is to let this change set go in as-is. And you & I can talk off-line to see how to smooth things over in future editions.

Yes, we'll return to this in future work

rtjohnso · 2022-12-02T19:35:39Z

include/splinterdb/platform_linux/public_platform.h

-// and platform_error_log() messages go to stderr.
-//
-// Use platform_set_log_streams() to send the log messages elsewhere.
-typedef FILE                platform_log_handle;


Excellent idea to remove these from the public api.

ajhconway

LGTM

ajhconway · 2022-12-04T18:57:46Z

ci/steps.lib.yml

    INCLUDE_SLOW_TESTS: #@ str(not quick).lower()
    RUN_NIGHTLY_TESTS: #@ str(test_nightly).lower()
    BUILD_VERBOSE: "1"
+    VERBOSE: "1"


+1, that would be ideal, but I can see why that would be tricky. Future work.

ajhconway · 2022-12-04T18:58:00Z

include/splinterdb/platform_linux/public_platform.h

-// and platform_error_log() messages go to stderr.
-//
-// Use platform_set_log_streams() to send the log messages elsewhere.
-typedef FILE                platform_log_handle;


tests/unit/limitations_test.c

tests/unit/misc_test.c

gapisback · 2022-12-06T18:00:40Z

tests/unit/btree_stress_test.c

+      CTEST_ERR("invalid ranges in original tree\n");
   }

-   /* platform_default_log("\n\n\n"); */


I'm not so sure about deleting this dead code and the old lines on L249 onwards below.

Seems like the code author had felt a need that this kind of debugging would be handy if ever this one had to troubleshoot failures in this test's execution.

I'm generally tolerant about such code being left behind, as it does help some future engineer who might have to debug this stuff. (Rob didn't complain, surprisingly ... as he's the author.)

What if we (a) either retain this dead-code in comments or (b) enclose it under if (FALSE) { }? The code is there for troubleshooting and doesn't get in anyone's way.

I strongly dislike dead code. I'm going to delete it. No one is speaking up to claim this code as theirs, and I'm guessing it could be added back by someone who's making changes.

gapisback · 2022-12-06T18:19:11Z

tests/unit/ctest.h

+         fprintf(stdout, __VA_ARGS__);                                         \
+         fflush(stdout);                                                       \
+      }                                                                        \
+   } while (0)


Minor suggestion. It is sufficient if you code this multi-line macro simply as:

if (Ctest_verbosity) { ...} else

Missing ; at end of else will take care of correct usage.

That seems dangerous to me.

Suppose someone forgets the ; and writes

CTEST_LOG_INFO("foo") something_important();

With the do/while implementation of the macro, the compiler will error:

tests/unit/splinterdb_quick_test.c:862:25: fatal error: expected ';' after do/while statement CTEST_LOG_INFO("foo") ^ ;

But with your proposed if/else implementation, it compiles cleanly, and then something_important() only gets called when VERBOSE is unset.

gapisback · 2022-12-06T18:53:46Z

tests/unit/main.c

 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;


Any reason why this is declared as int rather than as bool ? (I think I dimly recall some issue with using bool as a type in ctests' main.c ... Maybe that's why this is an int ?)

You may want to doc that this is really being treated as a boolean variable.

It would be good to be consistent elsewhere where this variable is checked. In some places code does if (Ctest_verbosity) and in others it does if (Ctest_verbosity > 0).

Examples:

tests/unit/limitations_test.c-73- if (Ctest_verbosity) {

v/s

tests/unit/splinterdb_quick_test.c-101- if (Ctest_verbosity > 0) { tests/unit/splinterdb_stress_test.c-51- if (Ctest_verbosity > 0) {

Good point. Changed to _Bool on latest.

gapisback · 2022-12-06T19:11:34Z

tests/unit/splinterdb_stress_test.c

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


My comment is not specifically tied to this diff, or the diff below on L164.

I just wondered ... how would a new test author know which interface to use for printing messages.

Unit-tests: I noticed that in splinter_test.c, we are still using platform_default_log(), while in other files we are using CTEST_LOG_INFO().

Functional-tests: are all using platform_default_log().

I am wondering ... how can we provide guidelines on what to use where. May be a README in tests/ sub-dir with some general guidelines on what to use where (platform_default_log(), CTEST_LOG_INFO() and CTEST_ERR()) will be helpful. I will certainly forget these details and will benefit from archived how-to instructions for future reference.

Yes, that was a problem before this PR (multiple ways to print between tests). I think splinter_test.c is a special case, because it is testing private APIs. That said, based on this feedback, I've made the following updates to this file in the most recent commit:

updated this file to use the CTEST_LOG_INFO() macro as much as I could easily... though there are other places where it uses private APIs to print to the Platform_default_log_stream and I'm not going to touch that in this PR.

Made it respect the verbose flag by calling platform_set_log_streams() the right way

added a note to the top of this file to warn folks not to follow patterns here.

gapisback · 2022-12-06T19:12:09Z

tests/unit/splinterdb_stress_test.c

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


This and the diff on L179 is a good catch. Thanks!

gapisback

Hi, @rosenhouse - Thanks for taking an issue off my plate and improving the usage landscape somewhat!

I have marked-up minor comments and suggestions; nothing major, so assume that you will be able to address them accordingly.

A general comment is that it will be a bit confusing for a new test-code author to figure out which interface to use where, functional and unit tests code. (I myself will forget and will end up searching what we did in other tests and copy from there.)

I suspect there will be a bit more churn in this area, especially relating to interface and handling of (current) env-var VERBOSE and / or --verbose-progress argument.

I think it will be helpful to having coding-level guidelines perhaps, in testing.md or in unit_testing.md.

We can develop this off-line once the dust settles on this area.

- 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

rosenhouse · 2022-12-06T21:16:34Z

@gapisback Thanks for the review. I've tried to improve the "new test author experience" part by updating splinter_test as much as was practical in a short-time, and leaving a note up top to caution against following patterns there. And then there's at least a clearer distinction between "unit" versus "functional".

And yes, let's merge this as-is, and we'll defer the flag thing to later.

rosenhouse requested review from ajhconway, gapisback and rtjohnso December 2, 2022 18:43

vmwclabot added the cla-not-required label Dec 2, 2022

rosenhouse force-pushed the gabe/unit-tests-stdout-stderr branch from 218ce4c to 85fdae2 Compare December 2, 2022 18:57

rtjohnso approved these changes Dec 2, 2022

View reviewed changes

ajhconway approved these changes Dec 4, 2022

View reviewed changes

rosenhouse force-pushed the gabe/unit-tests-stdout-stderr branch from 85fdae2 to 520edca Compare December 4, 2022 23:16

gapisback reviewed Dec 6, 2022

View reviewed changes

gapisback approved these changes Dec 6, 2022

View reviewed changes

rosenhouse added 4 commits December 6, 2022 20:12

fixup: move file_error_returns test to limitations test file

b49ec54

code review fix: change verbose global to be a _Bool

0a635e8

fixup: unit/splinter_test.c uses new logging apis

5d3e224

rosenhouse force-pushed the gabe/unit-tests-stdout-stderr branch from 520edca to 5d3e224 Compare December 6, 2022 21:09

rosenhouse merged commit 83de5e0 into main Dec 6, 2022

rosenhouse deleted the gabe/unit-tests-stdout-stderr branch December 6, 2022 22:03

rosenhouse mentioned this pull request Dec 7, 2022

Enable use of background threads in Splinter. Engage tests to verify basic stability of this existing feature. #469

Merged

gapisback mentioned this pull request Dec 23, 2022

Refactor code that manages stdout / stderr file handles in unit tests to a common routine. #513

Closed

gapisback mentioned this pull request Jan 18, 2023

Rework env-var interface to set log streams from unit-tests that exercise print diagnostics code. #534

Open

Conversation

rosenhouse commented Dec 2, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

netlify bot commented Dec 2, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

✅ Deploy Preview for splinterdb canceled.

Uh oh!

rtjohnso left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ajhconway left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rosenhouse Dec 6, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

gapisback left a comment

Choose a reason for hiding this comment

Uh oh!

rosenhouse commented Dec 6, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

rosenhouse commented Dec 2, 2022 •

edited

Loading

netlify bot commented Dec 2, 2022 •

edited

Loading

rosenhouse Dec 6, 2022 •

edited

Loading

rosenhouse commented Dec 6, 2022 •

edited

Loading