1919#include " flow/log/simple_ostream_logger.hpp"
2020#include " flow/log/detail/component_cfg.hpp" // Yes, detail/ -- we do what we must.
2121#include " flow/test/test_logger.hpp"
22+ #include " flow/test/test_config.hpp"
2223#include " flow/perf/checkpt_timer.hpp"
2324#include " flow/util/string_view.hpp"
2425#include < gtest/gtest.h>
@@ -179,6 +180,8 @@ void dict_benchmark(size_t n_cfgs)
179180 FLOW_LOG_SET_CONTEXT (&logger, Flow_log_component::S_UNCAT);
180181 log::beautify_chrono_logger_this_thread (&logger); // Nice short-form duration printouts.
181182
183+ const bool do_not_fail_benchmarks = flow::test::Test_config::get_singleton ().m_do_not_fail_benchmarks ;
184+
182185 using Ti = const std::type_info*;
183186 using Type_idx = std::type_index;
184187 using std::string;
@@ -206,7 +209,18 @@ void dict_benchmark(size_t n_cfgs)
206209 std::mt19937 gen (rd ());
207210 std::uniform_int_distribution<size_t > dist_to_n_cfgs (0 , n_cfgs - 1 );
208211 perf::Clock_types_subset clocks;
209- constexpr auto CLK_TYPE = size_t (perf::Clock_type::S_CPU_THREAD_TOTAL_HI_RES);
212+ /* Important (in our benchmarking context) discussion -- what clock to measure? Normally I (ygoldfel) by far
213+ * prefer REAL_HI_RES. It is extremely accurate and itself very low-cost. When it's a local environment without
214+ * a real possibility of irrelevant stuff happening simultaneously, it's great. Here, though, we've got a brittle
215+ * situation: the thing being timed in is in the nanoseconds, so the slightest disruption throws various ratios
216+ * below out of whack and triggers failures and confusion. So in this case it seems best to count processor cycles;
217+ * and just in case multithreading (though there shouldn't be any in our context) becomes an issue, let's count
218+ * this thread's cycles.
219+ * Update: On 2nd thought, failing tests due to this benchmark appears too draconian, at least in automated
220+ * setups like GitHub Actions; so we allow for --do-not-fail-benchmarks flag to override that. Hence
221+ * let's use the (IMO) nicer experience of REAL_HI_RES, since we will basically run without --do-not-fail-benchmarks
222+ * only locally, where we can control our environment and not worry about spurious craziness that much. */
223+ constexpr auto CLK_TYPE = size_t (perf::Clock_type::S_REAL_HI_RES);
210224 clocks.set (CLK_TYPE);
211225
212226 /* Maps Dict_* type to total (findable lookup + unfindable lookup) benchmark result for that dictionary impl.
@@ -315,20 +329,37 @@ void dict_benchmark(size_t n_cfgs)
315329 {
316330 if (rec.m_type == Type_idx (typeid (FLOW_LOG_CONFIG_COMPONENT_PAYLOAD_TYPE_DICT_BY_PTR<cfg_t >)))
317331 {
318- EXPECT_LT (rec.m_time_multiple , SIGNIFICANT_MULTIPLE_THRESHOLD)
319- << " Dict type [by-ptr (fast)] impl [" << dict_type_printable (rec.m_type , true ) << " ] is the default "
320- " but benchmark finds it is not the fastest (of by-ptr/fast impls), AND it is over the safety "
321- " allowance. Perhaps reconsider the default?" ;
332+ #define MSG " Dict type [by-ptr (fast)] impl [" << dict_type_printable(rec.m_type, true ) << " ] is the default " \
333+ " but benchmark finds it is not the fastest (of by-ptr/fast impls), AND it is over the safety " \
334+ " allowance. Perhaps reconsider the default?"
335+ if (do_not_fail_benchmarks)
336+ {
337+ if (rec.m_time_multiple >= SIGNIFICANT_MULTIPLE_THRESHOLD) { FLOW_LOG_WARNING (MSG); }
338+ }
339+ else
340+ {
341+ EXPECT_LT (rec.m_time_multiple , SIGNIFICANT_MULTIPLE_THRESHOLD) << MSG;
342+ }
343+ #undef MSG
322344 }
323345 }
324346 else
325347 {
326348 if (rec.m_type == Type_idx (typeid (FLOW_LOG_CONFIG_COMPONENT_PAYLOAD_TYPE_DICT_BY_VAL<cfg_t >)))
327349 {
328- EXPECT_LT (rec.m_time_multiple , SIGNIFICANT_MULTIPLE_THRESHOLD)
329- << " Dict type [by-val (slow)] impl [" << dict_type_printable (rec.m_type , true ) << " ] is the default "
330- " but benchmark finds it is not the fastest (of by-val/slow impls), AND it is over the safety "
331- " allowance. Perhaps reconsider the default?" ;
350+ #define MSG " Dict type [by-val (slow)] impl [" << dict_type_printable(rec.m_type, true ) << " ] is the default " \
351+ " but benchmark finds it is not the fastest (of by-val/slow impls), AND it is over the safety " \
352+ " allowance. Perhaps reconsider the default?"
353+
354+ if (do_not_fail_benchmarks)
355+ {
356+ if (rec.m_time_multiple >= SIGNIFICANT_MULTIPLE_THRESHOLD) { FLOW_LOG_WARNING (MSG); }
357+ }
358+ else
359+ {
360+ EXPECT_LT (rec.m_time_multiple , SIGNIFICANT_MULTIPLE_THRESHOLD) << MSG;
361+ }
362+ #undef MSG
332363
333364 /* This isn't a benchmark check but a sanity-check of a basic assumption (slow hashing + hash map = let us
334365 * not default to it, even among the slow-lookup map types). */
@@ -378,11 +409,18 @@ void dict_benchmark(size_t n_cfgs)
378409 const auto slow_timing_vec = analyze_dict_type (false , by_val_timing, by_val_timing1, by_val_time_sum);
379410 FLOW_LOG_INFO (" -- END OF: Results for [n_cfgs=" << n_cfgs << " ] --" );
380411
381- EXPECT_LT (by_ptr_time_sum, by_val_time_sum)
382- << " While individual by-val (slow) dict lookups might occasionally benchmark as faster than "
383- " by-ptr (fast) dict lookups (for lower n_cfgs and just spuriously every now and then), the sum thereof "
384- " should really show them to be overall slow. What happened?" ;
385-
412+ #define MSG " While individual by-val (slow) dict lookups might occasionally benchmark as faster than " \
413+ " by-ptr (fast) dict lookups (for lower n_cfgs and just spuriously every now and then), the sum thereof " \
414+ " should really show them to be overall slow. What happened?"
415+ if (do_not_fail_benchmarks)
416+ {
417+ if (by_ptr_time_sum >= by_val_time_sum) { FLOW_LOG_WARNING (MSG); }
418+ }
419+ else
420+ {
421+ EXPECT_LT (by_ptr_time_sum, by_val_time_sum) << MSG;
422+ }
423+ #undef MSG
386424
387425 /* My (ygoldfel) heart was in the right place with the following check; but while in some real environments
388426 * this straightforwardly passes, on others instead results are muddled together and close. So we'll let it go;
@@ -426,6 +464,11 @@ TEST(Component_cfg_test, Dict_internals_interface)
426464{
427465 dict_test<Dict_ptr_tree_map, Dict_ptr_s_hash_map, Dict_ptr_b_hash_map, Dict_ptr_array, Dict_ptr_sorted_array,
428466 Dict_val_tree_map, Dict_val_s_hash_map, Dict_val_b_hash_map, Dict_val_array, Dict_val_sorted_array>();
467+
468+ /* @todo What about Component_payload_type_dict, the one that combines a Dict_ptr_* and a Dict_val_* and looks up
469+ * first in the former and if needed the other one? Could test that, straightforward though it is.
470+ * It's probably not a huge deal, as we test that end-to-end in the `Interface` test below, from the log::Config
471+ * layer which uses the compoung Component_payload_type_dict. */
429472}
430473
431474#ifdef NDEBUG // These "deaths" occur only if assert()s enabled; else these are guaranteed failures.
@@ -482,6 +525,9 @@ TEST(Component_cfg_test, Interface)
482525 false );
483526 // Logging (and/or per-component verbosity configuring) would begin here and below.
484527
528+ /* These enums are registered, so internally the base index for each enum mentioned will be found;
529+ * but there will be no actual per-component verbosity configured for it; hence defaults to the overall
530+ * verbosity (INFO, seen above in ctor args). */
485531 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, comp0a));
486532 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, comp0b));
487533 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, comp1a));
@@ -500,7 +546,7 @@ TEST(Component_cfg_test, Interface)
500546 EXPECT_FALSE (cfg.output_whether_should_log (Sev::S_TRACE, comp1b));
501547 EXPECT_FALSE (cfg.output_whether_should_log (Sev::S_TRACE, comp3a));
502548 EXPECT_FALSE (cfg.output_whether_should_log (Sev::S_TRACE, comp3b));
503- // These enums are not registered (but same result for now).
549+ // These enums are not registered so no base index found (but same result for now: no per-component verbosity ).
504550 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, compXa));
505551 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, compXb));
506552 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_WARNING, compXa));
@@ -510,6 +556,11 @@ TEST(Component_cfg_test, Interface)
510556
511557 cfg.configure_component_verbosity (Sev::S_TRACE, comp0a);
512558 cfg.configure_component_verbosity (Sev::S_TRACE, comp3b);
559+ /* Some (not all certainly) per-component verbosities have indeed been set.
560+ * So the base index lookup (internally via the Component_payload_type_dict_*::lookup()) will work for
561+ * all but the nX::nx:: component checks; but then only the actually-configured per-component verbosities
562+ * will be found in the big flat table. */
563+
513564 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, comp0a));
514565 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, comp0b));
515566 EXPECT_TRUE (cfg.output_whether_should_log (Sev::S_INFO, comp1a));
@@ -552,4 +603,5 @@ TEST(Component_cfg_test, Interface)
552603 * log::Config aspects. I.e., test from a still-higher layer. Possibly that would go in the unit tests
553604 * for those classes though. As of this writing they don't exist. */
554605} // TEST(Component_cfg_test, Interface)
606+
555607} // namespace flow::log::test
0 commit comments