diff options
author | Henning Baldersheim <balder@yahoo-inc.com> | 2023-03-02 19:01:42 +0100 |
---|---|---|
committer | GitHub <noreply@github.com> | 2023-03-02 19:01:42 +0100 |
commit | e8843502782cf63a490fe9cd45c43329d509b0f5 (patch) | |
tree | 781e61af167eac20a87f523e11e5bd5982a5088d | |
parent | d003f5d8d79313f13d785ead045b9e44db32d06b (diff) | |
parent | 369560356e57aa8bfa21ab7547ec9b6eb5f2d207 (diff) |
Merge pull request #26261 from vespa-engine/balder/enforce-system-time-for-metrics
Balder/enforce system time for metrics
21 files changed, 367 insertions, 393 deletions
diff --git a/metrics/src/tests/metricmanagertest.cpp b/metrics/src/tests/metricmanagertest.cpp index 6d6f21ea7b0..52b17576c5c 100644 --- a/metrics/src/tests/metricmanagertest.cpp +++ b/metrics/src/tests/metricmanagertest.cpp @@ -29,7 +29,7 @@ struct MetricManagerTest : public ::testing::Test { // MetricManager that aren't accessible to "freestanding" fixtures. So we // get the test to do the necessary poking and prodding for us instead. void takeSnapshots(MetricManager& mm, time_t timeToProcess) { - mm.takeSnapshots(mm.getMetricLock(), timeToProcess); + mm.takeSnapshots(mm.getMetricLock(), system_time(vespalib::from_s(timeToProcess))); } }; @@ -165,7 +165,7 @@ getMatchedMetrics(const vespalib::string& config) MetricLockGuard g(mm.getMetricLock()); mm.visit(g, mm.getActiveMetrics(g), visitor, "consumer"); - MetricManager::ConsumerSpec::SP consumerSpec(mm.getConsumerSpec(g, "consumer")); + const MetricManager::ConsumerSpec * consumerSpec = mm.getConsumerSpec(g, "consumer"); return { visitor.toString(), consumerSpec ? consumerSpec->toString() : "Non-existing consumer" }; } @@ -384,11 +384,11 @@ struct BriefValuePrinter : public MetricVisitor { } }; -bool waitForTimeProcessed(const MetricManager& mm, time_t processtime, uint32_t timeout = 120) +bool waitForTimeProcessed(const MetricManager& mm, vespalib::duration processtime, uint32_t timeout = 120) { uint32_t lastchance = time(0) + timeout; while (time(0) < lastchance) { - if (mm.getLastProcessedTime() >= processtime) return true; + if (mm.getLastProcessedTime() >= time_point(processtime)) return true; mm.timeChangedNotification(); std::this_thread::sleep_for(10ms); } @@ -411,14 +411,11 @@ std::string dumpAllSnapshots(const MetricManager& mm, const std::string& consume mm.visit(metricLock, mm.getTotalMetricSnapshot(metricLock), briefValuePrinter, consumer); ost << "Total: " << briefValuePrinter.ost.str() << "\n"; } - std::vector<uint32_t> periods; - { - MetricLockGuard metricLock(mm.getMetricLock()); - periods = mm.getSnapshotPeriods(metricLock); - } - for (uint32_t i=0; i<periods.size(); ++i) { - MetricLockGuard metricLock(mm.getMetricLock()); - const MetricSnapshotSet& set(mm.getMetricSnapshotSet(metricLock, periods[i])); + + MetricLockGuard metricLock(mm.getMetricLock()); + auto periods = mm.getSnapshotPeriods(metricLock); + for (vespalib::duration period : periods) { + const MetricSnapshotSet& set(mm.getMetricSnapshotSet(metricLock, period)); ost << set.getName() << "\n"; for (uint32_t count=0,j=0; j<2; ++j) { if (set.getCount() == 1 && j == 1) continue; @@ -438,9 +435,9 @@ std::string dumpAllSnapshots(const MetricManager& mm, const std::string& consume { \ MetricLockGuard lockGuard(mm.getMetricLock()); \ BriefValuePrinter briefValuePrinter; \ - if (period == -1) { \ + if (period < vespalib::duration::zero()) { \ mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), briefValuePrinter, "snapper"); \ - } else if (period == 0) { \ + } else if (period == vespalib::duration::zero()) { \ mm.visit(lockGuard, mm.getTotalMetricSnapshot(lockGuard), briefValuePrinter, "snapper"); \ } else { \ mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, period), briefValuePrinter, "snapper"); \ @@ -450,8 +447,8 @@ std::string dumpAllSnapshots(const MetricManager& mm, const std::string& consume #define ASSERT_PROCESS_TIME(mm, time) \ { \ - LOG(info, "Waiting for processed time %u.", time); \ - bool gotToCorrectProgress = waitForTimeProcessed(mm, time); \ + LOG(info, "Waiting for processed time %s.", vespalib::to_string(time_point(time)).c_str()); \ + bool gotToCorrectProgress = waitForTimeProcessed(mm, (time)); \ if (!gotToCorrectProgress) \ FAIL() << "Failed to get to processed time within timeout"; \ } @@ -478,8 +475,7 @@ TEST_F(MetricManagerTest, test_snapshots) { MetricLockGuard lockGuard(mm.getMetricLock()); mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), visitor, "snapper"); - MetricManager::ConsumerSpec::SP consumerSpec( - mm.getConsumerSpec(lockGuard, "snapper")); + const MetricManager::ConsumerSpec * consumerSpec = mm.getConsumerSpec(lockGuard, "snapper"); EXPECT_EQ(std::string("\n" "temp.val6\n" "temp.sub.val1\n" @@ -492,12 +488,11 @@ TEST_F(MetricManagerTest, test_snapshots) "*temp.multisub.sum.val1\n" "*temp.multisub.sum.val2\n" "*temp.multisub.sum.valsum\n"), - "\n" + visitor.toString()) << (consumerSpec.get() ? consumerSpec->toString() - : "Non-existing consumer"); + "\n" + visitor.toString()) << (consumerSpec ? consumerSpec->toString() : "Non-existing consumer"); } // Initially, there should be no metrics logged - ASSERT_PROCESS_TIME(mm, 1000); - ASSERT_VALUES(mm, 5 * 60, ""); + ASSERT_PROCESS_TIME(mm, 1000s); + ASSERT_VALUES(mm, 5 * 60s, ""); // Adding metrics done in first five minutes. mySet.val6.addValue(2); @@ -507,10 +502,10 @@ TEST_F(MetricManagerTest, test_snapshots) mySet.val10.a.val2.addValue(2); mySet.val10.b.val1.addValue(1); timer.add_time(5 * 60); - ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60); - ASSERT_VALUES(mm, 5 * 60, "2,4,4,1,7,9,1,1,8,2,10"); - ASSERT_VALUES(mm, 60 * 60, ""); - ASSERT_VALUES(mm, 0 * 60, "2,4,4,1,7,9,1,1,8,2,10"); + ASSERT_PROCESS_TIME(mm, 1000s + 5 * 60s); + ASSERT_VALUES(mm, 5 * 60s, "2,4,4,1,7,9,1,1,8,2,10"); + ASSERT_VALUES(mm, 60 * 60s, ""); + ASSERT_VALUES(mm, 0 * 60s, "2,4,4,1,7,9,1,1,8,2,10"); // Adding metrics done in second five minute period. Total should // be updated to account for both @@ -521,18 +516,18 @@ TEST_F(MetricManagerTest, test_snapshots) mySet.val10.a.val2.addValue(3); mySet.val10.b.val1.addValue(2); timer.add_time(5 * 60); - ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60 * 2); - ASSERT_VALUES(mm, 5 * 60, "4,5,5,1,8,11,2,2,10,3,13"); - ASSERT_VALUES(mm, 60 * 60, ""); - ASSERT_VALUES(mm, 0 * 60, "4,5,5,2,8,11,2,2,10,3,13"); + ASSERT_PROCESS_TIME(mm, 1000s + 5 * 60 * 2s); + ASSERT_VALUES(mm, 5 * 60s, "4,5,5,1,8,11,2,2,10,3,13"); + ASSERT_VALUES(mm, 60 * 60s, ""); + ASSERT_VALUES(mm, 0 * 60s, "4,5,5,2,8,11,2,2,10,3,13"); // Adding another five minute period where nothing have happened. // Metric for last 5 minutes should be 0. timer.add_time(5 * 60); - ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60 * 3); - ASSERT_VALUES(mm, 5 * 60, "0,0,0,0,0,0,0,0,0,0,0"); - ASSERT_VALUES(mm, 60 * 60, ""); - ASSERT_VALUES(mm, 0 * 60, "4,5,5,2,8,11,2,2,10,3,13"); + ASSERT_PROCESS_TIME(mm, 1000s + 5 * 60s * 3); + ASSERT_VALUES(mm, 5 * 60s, "0,0,0,0,0,0,0,0,0,0,0"); + ASSERT_VALUES(mm, 60 * 60s, ""); + ASSERT_VALUES(mm, 0 * 60s, "4,5,5,2,8,11,2,2,10,3,13"); // Advancing time to 60 minute period, we should create a proper // 60 minute period timer. @@ -540,18 +535,18 @@ TEST_F(MetricManagerTest, test_snapshots) for (uint32_t i=0; i<9; ++i) { // 9 x 5 minutes. Avoid snapshot bumping // due to taking snapshots in the past timer.add_time(5 * 60); - ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60 * (4 + i)); + ASSERT_PROCESS_TIME(mm, 1000s + 5 * 60s * (4 + i)); } - ASSERT_VALUES(mm, 5 * 60, "0,0,0,0,0,0,0,0,0,0,0"); - ASSERT_VALUES(mm, 60 * 60, "6,5,5,2,8,11,2,2,10,3,13"); - ASSERT_VALUES(mm, 0 * 60, "6,5,5,2,8,11,2,2,10,3,13"); + ASSERT_VALUES(mm, 5 * 60s, "0,0,0,0,0,0,0,0,0,0,0"); + ASSERT_VALUES(mm, 60 * 60s, "6,5,5,2,8,11,2,2,10,3,13"); + ASSERT_VALUES(mm, 0 * 60s, "6,5,5,2,8,11,2,2,10,3,13"); // Test that reset works - mm.reset(1000); - ASSERT_VALUES(mm, -1, "0,0,0,0,0,0,0,0,0,0,0"); - ASSERT_VALUES(mm, 5 * 60, "0,0,0,0,0,0,0,0,0,0,0"); - ASSERT_VALUES(mm, 60 * 60, "0,0,0,0,0,0,0,0,0,0,0"); - ASSERT_VALUES(mm, 0 * 60, "0,0,0,0,0,0,0,0,0,0,0"); + mm.reset(system_time(1000s)); + ASSERT_VALUES(mm, -1s, "0,0,0,0,0,0,0,0,0,0,0"); + ASSERT_VALUES(mm, 5 * 60s, "0,0,0,0,0,0,0,0,0,0,0"); + ASSERT_VALUES(mm, 60 * 60s, "0,0,0,0,0,0,0,0,0,0,0"); + ASSERT_VALUES(mm, 0 * 60s, "0,0,0,0,0,0,0,0,0,0,0"); } TEST_F(MetricManagerTest, test_json_output) @@ -591,7 +586,7 @@ TEST_F(MetricManagerTest, test_json_output) JsonWriter writer(jsonStream); { MetricLockGuard lockGuard(mm.getMetricLock()); - mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, 300, false), writer, "snapper"); + mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, 300s, false), writer, "snapper"); } jsonStream.finalize(); std::string jsonData = as.str(); @@ -680,7 +675,7 @@ struct MetricSnapshotTestFixture JsonWriter writer(jsonStream); { MetricLockGuard lockGuard(manager.getMetricLock()); - manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300, false), writer, "snapper"); + manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300s, false), writer, "snapper"); } jsonStream.finalize(); return as.str(); @@ -689,10 +684,10 @@ struct MetricSnapshotTestFixture std::string renderLastSnapshotAsText(const std::string& matchPattern = ".*") const { std::ostringstream ss; - TextWriter writer(ss, 300, matchPattern, true); + TextWriter writer(ss, 300s, matchPattern, true); { MetricLockGuard lockGuard(manager.getMetricLock()); - manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300, false), writer, "snapper"); + manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300s, false), writer, "snapper"); } return ss.str(); } @@ -902,7 +897,7 @@ TEST_F(MetricManagerTest, test_text_output) "consumer[1].tags[1]\n" "consumer[1].tags[0] snaptest\n")); std::string expected( - "snapshot \"Active metrics showing updates since last snapshot\" from 1000 to 0 period 0\n" + "snapshot \"Active metrics showing updates since last snapshot\" from 1970-01-01 00:16:40.000 UTC to 1970-01-01 00:00:00.000 UTC period 0\n" "temp.val6 average=2 last=2 min=2 max=2 count=1 total=2\n" "temp.sub.val1 average=4 last=4 min=4 max=4 count=1 total=4\n" "temp.sub.valsum average=4 last=4 min=4 max=4 count=1 total=4\n" @@ -915,7 +910,7 @@ TEST_F(MetricManagerTest, test_text_output) "temp.multisub.sum.val2 average=2 last=2 min=2 max=2 count=1 total=2\n" "temp.multisub.sum.valsum average=10 last=10"); std::ostringstream ost; - TextWriter writer(ost, 300, ".*", true); + TextWriter writer(ost, 300s, ".*", true); { MetricLockGuard lockGuard(mm.getMetricLock()); mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), writer, "snapper"); @@ -938,11 +933,9 @@ TEST_F(MetricManagerTest, text_output_supports_dimensions) fixture.takeSnapshotsOnce(); std::string actual = fixture.renderLastSnapshotAsText("outer.*temp.*val"); std::string expected( - "snapshot \"5 minute\" from 1000 to 1300 period 300\n" - "outer{fancy:stuff}.temp{bar:hyperbar,foo:megafoo}.val1 " - "average=2 last=2 min=2 max=2 count=1 total=2\n" - "outer{fancy:stuff}.temp{bar:hyperbar,foo:megafoo}.val2" - "{baz:superbaz} count=1"); + "snapshot \"5 minute\" from 1970-01-01 00:16:40.000 UTC to 1970-01-01 00:21:40.000 UTC period 300\n" + "outer{fancy:stuff}.temp{bar:hyperbar,foo:megafoo}.val1 average=2 last=2 min=2 max=2 count=1 total=2\n" + "outer{fancy:stuff}.temp{bar:hyperbar,foo:megafoo}.val2{baz:superbaz} count=1"); EXPECT_EQ(expected, actual); } @@ -952,8 +945,8 @@ namespace { std::mutex& _output_mutex; FakeTimer& _timer; - MyUpdateHook(std::ostringstream& output, std::mutex& output_mutex, const char* name, FakeTimer& timer) - : UpdateHook(name), + MyUpdateHook(std::ostringstream& output, std::mutex& output_mutex, const char* name, vespalib::duration period, FakeTimer& timer) + : UpdateHook(name, period), _output(output), _output_mutex(output_mutex), _timer(timer) @@ -981,12 +974,12 @@ TEST_F(MetricManagerTest, test_update_hooks) mm.registerMetric(lockGuard, mySet.set); } - MyUpdateHook preInitShort(output, output_mutex, "BIS", timer); - MyUpdateHook preInitLong(output, output_mutex, "BIL", timer); - MyUpdateHook preInitInfinite(output, output_mutex, "BII", timer); - mm.addMetricUpdateHook(preInitShort, 5); - mm.addMetricUpdateHook(preInitLong, 300); - mm.addMetricUpdateHook(preInitInfinite, 0); + MyUpdateHook preInitShort(output, output_mutex, "BIS", 5s, timer); + MyUpdateHook preInitLong(output, output_mutex, "BIL", 300s, timer); + MyUpdateHook preInitInfinite(output, output_mutex, "BII", 0s, timer); + mm.addMetricUpdateHook(preInitShort); + mm.addMetricUpdateHook(preInitLong); + mm.addMetricUpdateHook(preInitInfinite); // All hooks should get called during initialization @@ -1002,56 +995,56 @@ TEST_F(MetricManagerTest, test_update_hooks) "consumer[1].tags[0] snaptest\n")); output << "Init done\n"; - MyUpdateHook postInitShort(output, output_mutex, "AIS", timer); - MyUpdateHook postInitLong(output, output_mutex, "AIL", timer); - MyUpdateHook postInitInfinite(output, output_mutex, "AII", timer); - mm.addMetricUpdateHook(postInitShort, 5); - mm.addMetricUpdateHook(postInitLong, 400); - mm.addMetricUpdateHook(postInitInfinite, 0); + MyUpdateHook postInitShort(output, output_mutex, "AIS", 5s, timer); + MyUpdateHook postInitLong(output, output_mutex, "AIL", 400s, timer); + MyUpdateHook postInitInfinite(output, output_mutex, "AII", 0s, timer); + mm.addMetricUpdateHook(postInitShort); + mm.addMetricUpdateHook(postInitLong); + mm.addMetricUpdateHook(postInitInfinite); // After 5 seconds the short ones should get another. timer.set_time(1006); - waitForTimeProcessed(mm, 1006); + waitForTimeProcessed(mm, 1006s); // After 4 more seconds the short ones should get another // since last update was a second late. (Stable periods, process time // should not affect how often they are updated) timer.set_time(1010); - waitForTimeProcessed(mm, 1010); + waitForTimeProcessed(mm, 1010s); // Bumping considerably ahead, such that next update is in the past, // we should only get one update called in this period. timer.set_time(1200); - waitForTimeProcessed(mm, 1200); + waitForTimeProcessed(mm, 1200s); // No updates at this time. timer.set_time(1204); - waitForTimeProcessed(mm, 1204); + waitForTimeProcessed(mm, 1204s); // Give all hooks an update - mm.updateMetrics(true); + mm.updateMetrics(); // Last update should not have interfered with periods timer.set_time(1205); - waitForTimeProcessed(mm, 1205); + waitForTimeProcessed(mm, 1205s); // Time is just ahead of a snapshot. timer.set_time(1299); - waitForTimeProcessed(mm, 1299); + waitForTimeProcessed(mm, 1299s); // At time 1300 we are at a 5 minute snapshot bump // All hooks should thus get an update. The one with matching period // should only get one timer.set_time(1300); - waitForTimeProcessed(mm, 1300); + waitForTimeProcessed(mm, 1300s); // The snapshot time currently doesn't count for the metric at period // 400. It will get an event at this time. timer.set_time(1450); - waitForTimeProcessed(mm, 1450); + waitForTimeProcessed(mm, 1450s); std::string expected( "Running init\n" diff --git a/metrics/src/tests/snapshottest.cpp b/metrics/src/tests/snapshottest.cpp index 4d2ea96c36d..5561825e2ba 100644 --- a/metrics/src/tests/snapshottest.cpp +++ b/metrics/src/tests/snapshottest.cpp @@ -4,7 +4,6 @@ #include <vespa/metrics/metrics.h> #include <vespa/metrics/summetric.hpp> #include <vespa/vespalib/gtest/gtest.h> -#include <vespa/vespalib/util/size_literals.h> namespace metrics { @@ -166,8 +165,8 @@ void ASSERT_VALUE(int32_t value, const MetricSnapshot & snapshot, const char *na } struct SnapshotTest : public ::testing::Test { - time_t tick(MetricManager& mgr, time_t currentTime) { - return mgr.tick(mgr.getMetricLock(), currentTime); + void tick(MetricManager& mgr, time_t currentTime) { + mgr.tick(mgr.getMetricLock(), time_point(vespalib::from_s(currentTime))); } }; @@ -221,7 +220,7 @@ TEST_F(SnapshotTest, test_snapshot_two_days) ASSERT_VALUE(0, *snap, "test.set1.set1.countSum"); // 5 minute snapshot - snap = &mm.getMetricSnapshot(lockGuard, 5 * 60); + snap = &mm.getMetricSnapshot(lockGuard, 5 * 60s); ASSERT_VALUE(1, *snap, "test.set1.set1.count1"); ASSERT_VALUE(2, *snap, "test.set1.set1.countSum"); @@ -229,7 +228,7 @@ TEST_F(SnapshotTest, test_snapshot_two_days) ASSERT_VALUE(1, *snap, "test.set1.set1.averageSum"); // 1 hour snapshot - snap = &mm.getMetricSnapshot(lockGuard, 60 * 60); + snap = &mm.getMetricSnapshot(lockGuard, 60 * 60s); ASSERT_VALUE(12, *snap, "test.set1.set1.count1"); ASSERT_VALUE(24, *snap, "test.set1.set1.countSum"); @@ -237,7 +236,7 @@ TEST_F(SnapshotTest, test_snapshot_two_days) ASSERT_VALUE(1, *snap, "test.set1.set1.averageSum"); // 1 day snapshot - snap = &mm.getMetricSnapshot(lockGuard, 24 * 60 * 60); + snap = &mm.getMetricSnapshot(lockGuard, 24 * 60 * 60s); ASSERT_VALUE(288, *snap, "test.set1.set1.count1"); ASSERT_VALUE(576, *snap, "test.set1.set1.countSum"); diff --git a/metrics/src/tests/summetrictest.cpp b/metrics/src/tests/summetrictest.cpp index 09495ff038d..8e988b65b96 100644 --- a/metrics/src/tests/summetrictest.cpp +++ b/metrics/src/tests/summetrictest.cpp @@ -104,8 +104,7 @@ TEST(SumMetricTest, test_remove) TEST(SumMetricTest, test_start_value) { MetricSnapshot snapshot("active"); - SumMetric<LongValueMetric> sum("foo", {}, "foodesc", - &snapshot.getMetrics()); + SumMetric<LongValueMetric> sum("foo", {}, "foodesc", &snapshot.getMetrics()); LongValueMetric start("start", {}, "", 0); start.set(50); sum.setStartValue(start); @@ -115,7 +114,7 @@ TEST(SumMetricTest, test_start_value) MetricSnapshot copy("copy"); copy.recreateSnapshot(snapshot.getMetrics(), true); - snapshot.addToSnapshot(copy, 100); + snapshot.addToSnapshot(copy, system_time(100s)); LongValueMetric value("value", {}, "", &snapshot.getMetrics()); sum.addMetricToSum(value); diff --git a/metrics/src/vespa/metrics/jsonwriter.cpp b/metrics/src/vespa/metrics/jsonwriter.cpp index c0d227b8f5a..1b9df3988e1 100644 --- a/metrics/src/vespa/metrics/jsonwriter.cpp +++ b/metrics/src/vespa/metrics/jsonwriter.cpp @@ -23,12 +23,12 @@ JsonWriter::visitSnapshot(const MetricSnapshot& snapshot) { _stream << Object() << "snapshot" << Object() - << "from" << snapshot.getFromTime() - << "to" << snapshot.getToTime() + << "from" << vespalib::count_s(snapshot.getFromTime().time_since_epoch()) + << "to" << vespalib::count_s(snapshot.getToTime().time_since_epoch()) << End() << "values" << Array(); _flag = SNAPSHOT_STARTED; - _period = snapshot.getPeriod(); + _period = vespalib::count_s(snapshot.getPeriod()); // Only prints second resolution return true; } diff --git a/metrics/src/vespa/metrics/metricmanager.cpp b/metrics/src/vespa/metrics/metricmanager.cpp index df83001a4e2..7fc8222c703 100644 --- a/metrics/src/vespa/metrics/metricmanager.cpp +++ b/metrics/src/vespa/metrics/metricmanager.cpp @@ -10,7 +10,6 @@ #include <vespa/vespalib/util/exceptions.h> #include <vespa/vespalib/util/time.h> #include <vespa/vespalib/stllike/asciistream.h> -#include <vespa/vespalib/stllike/hashtable.hpp> #include <vespa/config/subscription/configsubscriber.hpp> #include <set> #include <sstream> @@ -28,6 +27,8 @@ using vespalib::make_string_short::fmt; using vespalib::count_ms; using vespalib::count_s; using vespalib::from_s; +using vespalib::to_s; +using vespalib::to_string; MetricManager::ConsumerSpec::ConsumerSpec() = default; MetricManager::ConsumerSpec::~ConsumerSpec() = default; @@ -44,19 +45,20 @@ MetricManager::assertMetricLockLocked(const MetricLockGuard& g) const { } } -void -MetricManager::ConsumerSpec::print(std::ostream& out, bool verbose, const std::string& indent) const +vespalib::string +MetricManager::ConsumerSpec::toString() const { - (void) verbose; + vespalib::asciistream out; out << "ConsumerSpec("; std::set<Metric::String> sortedMetrics; for (const Metric::String & name : includedMetrics) { sortedMetrics.insert(name); } for (const auto & s : sortedMetrics) { - out << "\n" << indent << " " << s; + out << "\n" << " " << s; } out << ")"; + return out.str(); } void @@ -79,9 +81,9 @@ MetricManager::MetricManager(std::unique_ptr<Timer> timer) _config(), _consumerConfig(), _snapshots(), - _totalMetrics(std::make_shared<MetricSnapshot>("Empty metrics before init", 0, _activeMetrics.getMetrics(), false)), + _totalMetrics(std::make_shared<MetricSnapshot>("Empty metrics before init", 0s, _activeMetrics.getMetrics(), false)), _timer(std::move(timer)), - _lastProcessedTime(0), + _lastProcessedTime(), _snapshotUnsetMetrics(false), _consumerConfigChanged(false), _metricManagerMetrics("metricmanager", {}, "Metrics for the metric manager upkeep tasks", nullptr), @@ -115,29 +117,26 @@ MetricManager::stop() } void -MetricManager::addMetricUpdateHook(UpdateHook& hook, uint32_t period) +MetricManager::addMetricUpdateHook(UpdateHook& hook) { - hook._period = period; + hook.updateNextCall(_timer->getTime()); std::lock_guard sync(_waiter); - // If we've already initialized manager, log period has been set. - // In this case. Call first time after period - hook._nextCall = count_s(_timer->getTime().time_since_epoch()) + period; - if (period == 0) { - for (UpdateHook * sHook : _snapshotUpdateHooks) { - if (sHook == &hook) { + if ( hook.is_periodic() ) { + for (UpdateHook * pHook : _periodicUpdateHooks) { + if (pHook == &hook) { LOG(warning, "Update hook already registered"); return; } } - _snapshotUpdateHooks.push_back(&hook); + _periodicUpdateHooks.push_back(&hook); } else { - for (UpdateHook * pHook : _periodicUpdateHooks) { - if (pHook == &hook) { + for (UpdateHook * sHook : _snapshotUpdateHooks) { + if (sHook == &hook) { LOG(warning, "Update hook already registered"); return; } } - _periodicUpdateHooks.push_back(&hook); + _snapshotUpdateHooks.push_back(&hook); } } @@ -145,17 +144,17 @@ void MetricManager::removeMetricUpdateHook(UpdateHook& hook) { std::lock_guard sync(_waiter); - if (hook._period == 0) { - for (auto it = _snapshotUpdateHooks.begin(); it != _snapshotUpdateHooks.end(); it++) { + if (hook.is_periodic()) { + for (auto it = _periodicUpdateHooks.begin(); it != _periodicUpdateHooks.end(); it++) { if (*it == &hook) { - _snapshotUpdateHooks.erase(it); + _periodicUpdateHooks.erase(it); return; } } } else { - for (auto it = _periodicUpdateHooks.begin(); it != _periodicUpdateHooks.end(); it++) { + for (auto it = _snapshotUpdateHooks.begin(); it != _snapshotUpdateHooks.end(); it++) { if (*it == &hook) { - _periodicUpdateHooks.erase(it); + _snapshotUpdateHooks.erase(it); return; } } @@ -186,7 +185,7 @@ MetricManager::init(const config::ConfigUri & uri, bool startThread) // Wait for first iteration to have completed, such that it is safe // to access snapshots afterwards. MetricLockGuard sync(_waiter); - while (_lastProcessedTime.load(std::memory_order_relaxed) == 0) { + while (_lastProcessedTime.load(std::memory_order_relaxed) == time_point()) { _cond.wait_for(sync, 1ms); } } else { @@ -382,12 +381,12 @@ MetricManager::handleMetricsAltered(const MetricLockGuard & guard) LOG(info, "Metrics registration changes detected. Handling changes."); } _activeMetrics.getMetrics().clearRegistrationAltered(); - std::map<Metric::String, ConsumerSpec::SP> configMap; + std::map<Metric::String, ConsumerSpec> configMap; LOG(debug, "Calculating new consumer config"); for (const auto & consumer : _config->consumer) { ConsumerMetricBuilder consumerMetricBuilder(consumer); _activeMetrics.getMetrics().visit(consumerMetricBuilder); - configMap[consumer.name] = std::make_shared<ConsumerSpec>(std::move(consumerMetricBuilder._matchedMetrics)); + configMap[consumer.name] = ConsumerSpec(std::move(consumerMetricBuilder._matchedMetrics)); } LOG(debug, "Recreating snapshots to include altered metrics"); _totalMetrics->recreateSnapshot(_activeMetrics.getMetrics(), _snapshotUnsetMetrics); @@ -427,10 +426,10 @@ MetricManager::createSnapshotPeriods(const Config& config) } else { name << length << " seconds"; } - result.push_back(SnapSpec(length, name.str())); + result.emplace_back(vespalib::from_s(length), name.str()); } for (uint32_t i=1; i<result.size(); ++i) { - if (result[i].first % result[i-1].first != 0) { + if (result[i].first % result[i-1].first != vespalib::duration::zero()) { std::ostringstream ost; ost << "Period " << result[i].first << " is not a multiplum of period " << result[i-1].first << " which is needs to be."; @@ -442,10 +441,10 @@ MetricManager::createSnapshotPeriods(const Config& config) result.clear(); } if (result.empty()) { - result.push_back(SnapSpec(60 * 5, "5 minute")); - result.push_back(SnapSpec(60 * 60, "1 hour")); - result.push_back(SnapSpec(60 * 60 * 24, "1 day")); - result.push_back(SnapSpec(60 * 60 * 24 * 7, "1 week")); + result.emplace_back(60s * 5, "5 minute"); + result.emplace_back(60s * 60, "1 hour"); + result.emplace_back(60s * 60 * 24, "1 day"); + result.emplace_back(60s * 60 * 24 * 7, "1 week"); } return result; } @@ -464,16 +463,16 @@ MetricManager::configure(const MetricLockGuard & , std::unique_ptr<Config> confi LOG(debug, "Initializing snapshots as this is first configure call"); std::vector<SnapSpec> snapshotPeriods(createSnapshotPeriods(*config)); - // Set up snapshots only first time. We don't allow live reconfig - // of snapshot periods. - time_t currentTime = count_s(_timer->getTime().time_since_epoch()); + // Set up snapshots only first time. We don't allow live reconfig + // of snapshot periods. + time_point currentTime = _timer->getTime(); _activeMetrics.setFromTime(currentTime); uint32_t count = 1; for (uint32_t i = 0; i< snapshotPeriods.size(); ++i) { uint32_t nextCount = 1; if (i + 1 < snapshotPeriods.size()) { nextCount = snapshotPeriods[i + 1].first / snapshotPeriods[i].first; - if ((snapshotPeriods[i + 1].first % snapshotPeriods[i].first) != 0) { + if ((snapshotPeriods[i + 1].first % snapshotPeriods[i].first) != vespalib::duration::zero()) { throw IllegalStateException("Snapshot periods must be multiplum of each other",VESPA_STRLOC); } } @@ -482,8 +481,8 @@ MetricManager::configure(const MetricLockGuard & , std::unique_ptr<Config> confi _activeMetrics.getMetrics(), _snapshotUnsetMetrics)); count = nextCount; } - // Add all time snapshot. - _totalMetrics = std::make_shared<MetricSnapshot>("All time snapshot", 0, _activeMetrics.getMetrics(), _snapshotUnsetMetrics); + // Add all time snapshot. + _totalMetrics = std::make_shared<MetricSnapshot>("All time snapshot", 0s, _activeMetrics.getMetrics(), _snapshotUnsetMetrics); _totalMetrics->reset(currentTime); } if (_config.get() == 0 || (_config->consumer.size() != config->consumer.size())) { @@ -503,27 +502,24 @@ MetricManager::configure(const MetricLockGuard & , std::unique_ptr<Config> confi } -MetricManager::ConsumerSpec::SP +const MetricManager::ConsumerSpec * MetricManager::getConsumerSpec(const MetricLockGuard &, const Metric::String& consumer) const { auto it(_consumerConfig.find(consumer)); - return (it != _consumerConfig.end() ? it->second : ConsumerSpec::SP()); + return (it != _consumerConfig.end() ? &it->second : nullptr); } -//#define VERIFY_ALL_METRICS_VISITED 1 namespace { struct ConsumerMetricVisitor : public MetricVisitor { const MetricManager::ConsumerSpec& _metricsToMatch; MetricVisitor& _client; -#ifdef VERIFY_ALL_METRICS_VISITED - std::set<Metric::String> _visitedMetrics; -#endif ConsumerMetricVisitor(const MetricManager::ConsumerSpec& spec, MetricVisitor& clientVisitor) - : _metricsToMatch(spec), _client(clientVisitor) - {} + : _metricsToMatch(spec), + _client(clientVisitor) + { } bool visitMetricSet(const MetricSet& metricSet, bool autoGenerated) override { if (metricSet.isTopSet()) return true; @@ -532,26 +528,17 @@ struct ConsumerMetricVisitor : public MetricVisitor { } void doneVisitingMetricSet(const MetricSet& metricSet) override { if (!metricSet.isTopSet()) { -#ifdef VERIFY_ALL_METRICS_VISITED - _visitedMetrics.insert(metricSet.getPath()); -#endif _client.doneVisitingMetricSet(metricSet); } } bool visitCountMetric(const AbstractCountMetric& metric, bool autoGenerated) override { if (_metricsToMatch.contains(metric)) { -#ifdef VERIFY_ALL_METRICS_VISITED - _visitedMetrics.insert(metric.getPath()); -#endif return _client.visitCountMetric(metric, autoGenerated); } return true; } bool visitValueMetric(const AbstractValueMetric& metric, bool autoGenerated) override { if (_metricsToMatch.contains(metric)) { -#ifdef VERIFY_ALL_METRICS_VISITED - _visitedMetrics.insert(metric.getPath()); -#endif return _client.visitValueMetric(metric, autoGenerated); } return true; @@ -568,19 +555,11 @@ MetricManager::visit(const MetricLockGuard & guard, const MetricSnapshot& snapsh if (consumer == "") { snapshot.getMetrics().visit(visitor); } else { - ConsumerSpec::SP consumerSpec(getConsumerSpec(guard, consumer)); - if (consumerSpec.get()) { + const ConsumerSpec * consumerSpec = getConsumerSpec(guard, consumer); + if (consumerSpec) { + ConsumerMetricVisitor consumerVis(*consumerSpec, visitor); snapshot.getMetrics().visit(consumerVis); -#ifdef VERIFY_ALL_METRICS_VISITED - for (auto metric = consumerSpec->includedMetrics) { - if (consumerVis._visitedMetrics.find(metric) - == consumerVis._visitedMetrics.end()) - { - LOG(debug, "Failed to find metric %s to be visited.", metric.c_str()); - } - } -#endif } else { LOGBP(debug, "Requested metrics for non-defined consumer '%s'.", consumer.c_str()); } @@ -590,20 +569,21 @@ MetricManager::visit(const MetricLockGuard & guard, const MetricSnapshot& snapsh visitor.doneVisiting(); } -std::vector<uint32_t> +std::vector<vespalib::duration> MetricManager::getSnapshotPeriods(const MetricLockGuard& l) const { assertMetricLockLocked(l); - std::vector<uint32_t> result(_snapshots.size()); - for (uint32_t i=0; i<_snapshots.size(); ++i) { - result[i] = _snapshots[i]->getPeriod(); + std::vector<vespalib::duration> result; + result.reserve(_snapshots.size()); + for (const auto & snapshot : _snapshots) { + result.emplace_back(snapshot->getPeriod()); } return result; } // Client should have grabbed metrics lock before doing this const MetricSnapshot& -MetricManager::getMetricSnapshot(const MetricLockGuard& l, uint32_t period, bool getInProgressSet) const +MetricManager::getMetricSnapshot(const MetricLockGuard& l, vespalib::duration period, bool getInProgressSet) const { assertMetricLockLocked(l); for (const auto & snapshot : _snapshots) { @@ -614,12 +594,12 @@ MetricManager::getMetricSnapshot(const MetricLockGuard& l, uint32_t period, bool return snapshot->getSnapshot(getInProgressSet); } } - throw IllegalArgumentException(fmt("No snapshot for period of length %u exist.", period), VESPA_STRLOC); + throw IllegalArgumentException(fmt("No snapshot for period of length %f exist.", vespalib::to_s(period)), VESPA_STRLOC); } // Client should have grabbed metrics lock before doing this const MetricSnapshotSet& -MetricManager::getMetricSnapshotSet(const MetricLockGuard& l, uint32_t period) const +MetricManager::getMetricSnapshotSet(const MetricLockGuard& l, vespalib::duration period) const { assertMetricLockLocked(l); for (const auto & snapshot : _snapshots) { @@ -627,7 +607,7 @@ MetricManager::getMetricSnapshotSet(const MetricLockGuard& l, uint32_t period) c return *snapshot; } } - throw IllegalArgumentException(fmt("No snapshot set for period of length %u exist.", period), VESPA_STRLOC); + throw IllegalArgumentException(fmt("No snapshot set for period of length %f exist.", to_s(period)), VESPA_STRLOC); } void @@ -638,38 +618,35 @@ MetricManager::timeChangedNotification() const } void -MetricManager::updateMetrics(bool includeSnapshotOnlyHooks) +MetricManager::updateMetrics() { - LOG(debug, "Calling metric update hooks%s.", includeSnapshotOnlyHooks ? ", including snapshot hooks" : ""); // Ensure we're not in the way of the background thread MetricLockGuard sync(_waiter); - LOG(debug, "Giving %zu periodic update hooks.", _periodicUpdateHooks.size()); - updatePeriodicMetrics(sync, 0, true); - if (includeSnapshotOnlyHooks) { - LOG(debug, "Giving %zu snapshot update hooks.", _snapshotUpdateHooks.size()); - updateSnapshotMetrics(sync); - } + LOG(debug, "Calling %zu periodic update hooks.", _periodicUpdateHooks.size()); + updatePeriodicMetrics(sync, time_point(), true); + updateSnapshotMetrics(sync); } // When this is called, the thread monitor lock has already been grabbed -time_t -MetricManager::updatePeriodicMetrics(const MetricLockGuard & guard, time_t updateTime, bool outOfSchedule) +time_point +MetricManager::updatePeriodicMetrics(const MetricLockGuard & guard, time_point updateTime, bool outOfSchedule) { assertMetricLockLocked(guard); - time_t nextUpdateTime = std::numeric_limits<time_t>::max(); + time_point nextUpdateTime = time_point::max(); time_point preTime = _timer->getTimeInMilliSecs(); for (auto hook : _periodicUpdateHooks) { - if (hook->_nextCall <= updateTime) { + if (hook->expired(updateTime)) { hook->updateMetrics(guard); - if (hook->_nextCall + hook->_period < updateTime) { - if (hook->_nextCall != 0) { - LOG(debug, "Updated hook %s at time %" PRIu64 ", but next run in %u seconds have already passed as " - "time is %" PRIu64 ". Bumping next call to current time + period.", - hook->_name, static_cast<uint64_t>(hook->_nextCall), hook->_period, static_cast<uint64_t>(updateTime)); + if (hook->expired(updateTime - hook->getPeriod())) { + if (hook->has_valid_expiry()) { + LOG(debug, "Updated hook %s at time %s, but next run in %ld seconds have already passed as " + "time is %s. Bumping next call to current time + period.", + hook->getName(), to_string(hook->getNextCall()).c_str(), + count_s(hook->getPeriod()), to_string(updateTime).c_str()); } - hook->_nextCall = updateTime + hook->_period; + hook->updateNextCall(updateTime); } else { - hook->_nextCall += hook->_period; + hook->updateNextCall(); } time_point postTime = _timer->getTimeInMilliSecs(); _periodicHookLatency.addValue(count_ms(postTime - preTime)); @@ -680,7 +657,7 @@ MetricManager::updatePeriodicMetrics(const MetricLockGuard & guard, time_t updat _periodicHookLatency.addValue(count_ms(postTime - preTime)); preTime = postTime; } - nextUpdateTime = std::min(nextUpdateTime, hook->_nextCall); + nextUpdateTime = std::min(nextUpdateTime, hook->getNextCall()); } return nextUpdateTime; } @@ -709,7 +686,7 @@ MetricManager::forceEventLogging() } void -MetricManager::reset(time_t currentTime) +MetricManager::reset(system_time currentTime) { time_point preTime = _timer->getTimeInMilliSecs(); // Resetting implies visiting metrics, which needs to grab metric lock @@ -733,21 +710,20 @@ MetricManager::run() // we constantly add next time to do something from the last timer. // For that to work, we need to initialize timers on first iteration // to set them to current time. - time_t currentTime = count_s(_timer->getTime().time_since_epoch()); + system_time currentTime = _timer->getTime(); for (auto & snapshot : _snapshots) { snapshot->setFromTime(currentTime); } for (auto hook : _periodicUpdateHooks) { - hook->_nextCall = currentTime; + hook->setNextCall(currentTime); } // Ensure correct time for first snapshot _snapshots[0]->getSnapshot().setToTime(currentTime); while (!stop_requested()) { - time_point now = _timer->getTime(); - currentTime = count_s(now.time_since_epoch()); - time_t next = tick(sync, currentTime); + currentTime = _timer->getTime(); + time_point next = tick(sync, currentTime); if (currentTime < next) { - vespalib::duration wait_time = from_s(next - currentTime); + vespalib::duration wait_time = next - currentTime; _cond.wait_for(sync, wait_time); _sleepTimes.addValue(count_ms(wait_time)); } else { @@ -756,10 +732,10 @@ MetricManager::run() } } -time_t -MetricManager::tick(const MetricLockGuard & guard, time_t currentTime) +time_point +MetricManager::tick(const MetricLockGuard & guard, time_point currentTime) { - LOG(spam, "Worker thread starting to process for time %" PRIu64 ".", static_cast<uint64_t>(currentTime)); + LOG(spam, "Worker thread starting to process for time %s.", to_string(currentTime).c_str()); // Check for new config and reconfigure if (_configSubscriber && _configSubscriber->nextConfigNow()) { @@ -772,8 +748,8 @@ MetricManager::tick(const MetricLockGuard & guard, time_t currentTime) checkMetricsAltered(guard); // Set next work time to the time we want to take next snapshot. - time_t nextWorkTime = _snapshots[0]->getToTime() + _snapshots[0]->getPeriod(); - time_t nextUpdateHookTime; + time_point nextWorkTime = _snapshots[0]->getNextWorkTime(); + time_point nextUpdateHookTime; if (nextWorkTime <= currentTime) { // If taking a new snapshot or logging, force calls to all // update hooks. @@ -789,39 +765,38 @@ MetricManager::tick(const MetricLockGuard & guard, time_t currentTime) // Do snapshotting if it is time if (nextWorkTime <= currentTime) takeSnapshots(guard, nextWorkTime); - _lastProcessedTime.store(nextWorkTime <= currentTime ? nextWorkTime : currentTime, std::memory_order_relaxed); - LOG(spam, "Worker thread done with processing for time %" PRIu64 ".", - static_cast<uint64_t>(_lastProcessedTime.load(std::memory_order_relaxed))); - time_t next = _snapshots[0]->getPeriod() + _snapshots[0]->getToTime(); + _lastProcessedTime.store((nextWorkTime <= currentTime ? nextWorkTime : currentTime), std::memory_order_relaxed); + LOG(spam, "Worker thread done with processing for time %s.", + to_string(_lastProcessedTime.load(std::memory_order_relaxed)).c_str()); + time_point next = _snapshots[0]->getNextWorkTime(); next = std::min(next, nextUpdateHookTime); return next; } void -MetricManager::takeSnapshots(const MetricLockGuard & guard, time_t timeToProcess) +MetricManager::takeSnapshots(const MetricLockGuard & guard, system_time timeToProcess) { assertMetricLockLocked(guard); // If not time to do dump data from active snapshot yet, nothing to do if (!_snapshots[0]->timeForAnotherSnapshot(timeToProcess)) { - LOG(spam, "Not time to process snapshot %s at time %" PRIu64 ". Current " - "first period (%u) snapshot goes from %" PRIu64 " to %" PRIu64, - _snapshots[0]->getName().c_str(), static_cast<uint64_t>(timeToProcess), - _snapshots[0]->getPeriod(), static_cast<uint64_t>(_snapshots[0]->getFromTime()), - static_cast<uint64_t>(_snapshots[0]->getToTime())); + LOG(spam, "Not time to process snapshot %s at time %s. Current " + "first period (%f) snapshot goes from %s to %s", + _snapshots[0]->getName().c_str(), to_string(timeToProcess).c_str(), + to_s(_snapshots[0]->getPeriod()), to_string(_snapshots[0]->getFromTime()).c_str(), + to_string(_snapshots[0]->getToTime()).c_str()); return; } time_point preTime = _timer->getTimeInMilliSecs(); - LOG(debug, "Updating %s snapshot and total metrics at time %" PRIu64 ".", - _snapshots[0]->getName().c_str(), static_cast<uint64_t>(timeToProcess)); + LOG(debug, "Updating %s snapshot and total metrics at time %s.", + _snapshots[0]->getName().c_str(), to_string(timeToProcess).c_str()); MetricSnapshot& firstTarget(_snapshots[0]->getNextTarget()); firstTarget.reset(_activeMetrics.getFromTime()); _activeMetrics.addToSnapshot(firstTarget, false, timeToProcess); _activeMetrics.addToSnapshot(*_totalMetrics, false, timeToProcess); _activeMetrics.reset(timeToProcess); - LOG(debug, "After snapshotting, active metrics goes from %" PRIu64 " to %" PRIu64", " - "and 5 minute metrics goes from %" PRIu64 " to %" PRIu64".", - static_cast<uint64_t>(_activeMetrics.getFromTime()), static_cast<uint64_t>(_activeMetrics.getToTime()), - static_cast<uint64_t>(firstTarget.getFromTime()), static_cast<uint64_t>(firstTarget.getToTime())); + LOG(debug, "After snapshotting, active metrics goes from %s to %s, and 5 minute metrics goes from %s to %s.", + to_string(_activeMetrics.getFromTime()).c_str(), to_string(_activeMetrics.getToTime()).c_str(), + to_string(firstTarget.getFromTime()).c_str(), to_string(firstTarget.getToTime()).c_str()); // Update later snapshots if it is time for it for (uint32_t i=1; i<_snapshots.size(); ++i) { @@ -831,15 +806,15 @@ MetricManager::takeSnapshots(const MetricLockGuard & guard, time_t timeToProcess _snapshots[i-1]->getSnapshot().addToSnapshot(target, false, timeToProcess); target.setToTime(timeToProcess); if (!_snapshots[i]->haveCompletedNewPeriod(timeToProcess)) { - LOG(debug, "Not time to roll snapshot %s yet. %u of %u snapshot taken at time %" PRIu64 ", and period of %u " - "is not up yet as we're currently processing for time %" PRIu64 ".", + LOG(debug, "Not time to roll snapshot %s yet. %u of %u snapshot taken at time %s, and period of %f " + "is not up yet as we're currently processing for time %s.", _snapshots[i]->getName().c_str(), _snapshots[i]->getBuilderCount(), _snapshots[i]->getCount(), - static_cast<uint64_t>(_snapshots[i]->getBuilderCount() * _snapshots[i]->getPeriod() + _snapshots[i]->getFromTime()), - _snapshots[i]->getPeriod(), static_cast<uint64_t>(timeToProcess)); + to_string(_snapshots[i]->getBuilderCount() * _snapshots[i]->getPeriod() + _snapshots[i]->getFromTime()).c_str(), + to_s(_snapshots[i]->getPeriod()), to_string(timeToProcess).c_str()); break; } else { - LOG(debug, "Rolled snapshot %s at time %" PRIu64 ".", - _snapshots[i]->getName().c_str(), static_cast<uint64_t>(timeToProcess)); + LOG(debug, "Rolled snapshot %s at time %s.", + _snapshots[i]->getName().c_str(), to_string(timeToProcess).c_str()); } } time_point postTime = _timer->getTimeInMilliSecs(); @@ -852,10 +827,10 @@ MetricManager::getMemoryConsumption(const MetricLockGuard & guard) const assertMetricLockLocked(guard); auto mc = std::make_unique<MemoryConsumption>(); mc->_consumerCount += _consumerConfig.size(); - mc->_consumerMeta += (sizeof(ConsumerSpec::SP) + sizeof(ConsumerSpec)) * _consumerConfig.size(); + mc->_consumerMeta += sizeof(ConsumerSpec) * _consumerConfig.size(); for (const auto & consumer : _consumerConfig) { mc->_consumerId += mc->getStringMemoryUsage(consumer.first, mc->_consumerIdUnique) + sizeof(Metric::String); - consumer.second->addMemoryUsage(*mc); + consumer.second.addMemoryUsage(*mc); } uint32_t preTotal = mc->getTotalMemoryUsage(); _activeMetrics.addMemoryUsage(*mc); diff --git a/metrics/src/vespa/metrics/metricmanager.h b/metrics/src/vespa/metrics/metricmanager.h index c3ce37b451f..99fad4f2ad3 100644 --- a/metrics/src/vespa/metrics/metricmanager.h +++ b/metrics/src/vespa/metrics/metricmanager.h @@ -57,8 +57,6 @@ #include <list> #include <thread> -template class vespalib::hash_set<metrics::Metric::String>; - namespace metrics { class MetricManager @@ -75,20 +73,19 @@ public: * Spec saved from config. If metricSetChildren has content, metric pointed * to is a metric set. */ - struct ConsumerSpec : public vespalib::Printable { - using SP = std::shared_ptr<ConsumerSpec>; - + struct ConsumerSpec { vespalib::hash_set<Metric::String> includedMetrics; + ConsumerSpec(ConsumerSpec &&) noexcept = default; ConsumerSpec & operator= (ConsumerSpec &&) noexcept = default; ConsumerSpec(); - ~ConsumerSpec() override; + ~ConsumerSpec(); bool contains(const Metric& m) const { return (includedMetrics.find(m.getPath()) != includedMetrics.end()); } - void print(std::ostream& out, bool verbose, const std::string& indent) const override; + vespalib::string toString() const; void addMemoryUsage(MemoryConsumption&) const; }; @@ -98,15 +95,15 @@ private: std::unique_ptr<config::ConfigSubscriber> _configSubscriber; std::unique_ptr<config::ConfigHandle<MetricsmanagerConfig>> _configHandle; std::unique_ptr<MetricsmanagerConfig> _config; - std::map<Metric::String, ConsumerSpec::SP> _consumerConfig; + std::map<Metric::String, ConsumerSpec> _consumerConfig; std::list<UpdateHook*> _periodicUpdateHooks; std::list<UpdateHook*> _snapshotUpdateHooks; mutable std::mutex _waiter; mutable std::condition_variable _cond; - std::vector<MetricSnapshotSet::SP> _snapshots; - MetricSnapshot::SP _totalMetrics; + std::vector<std::shared_ptr<MetricSnapshotSet>> _snapshots; + std::shared_ptr<MetricSnapshot> _totalMetrics; std::unique_ptr<Timer> _timer; - std::atomic<time_t> _lastProcessedTime; + std::atomic<time_point> _lastProcessedTime; // Should be added to config, but wont now due to problems with // upgrading bool _snapshotUnsetMetrics; @@ -138,7 +135,7 @@ public: * snapshotting and metric logging, to make the metrics the best as they can * be at those occasions. * - * @param period Period in seconds for how often callback should be called. + * @param period Period for how often callback should be called. * The default value of 0, means only before snapshotting or * logging, while another value will give callbacks each * period seconds. Expensive metrics to calculate will @@ -147,7 +144,7 @@ public: * seconds or so. Any value of period >= the smallest snapshot * time will behave identically as if period is set to 0. */ - void addMetricUpdateHook(UpdateHook&, uint32_t period = 0); + void addMetricUpdateHook(UpdateHook&); /** Remove a metric update hook so it won't get any more updates. */ void removeMetricUpdateHook(UpdateHook&); @@ -157,7 +154,7 @@ public: * nice values before reporting something. * This function can not be called from an update hook callback. */ - void updateMetrics(bool includeSnapshotOnlyHooks = false); + void updateMetrics(); /** * Force event logging to happen now. @@ -191,7 +188,7 @@ public: * Reset all metrics including all snapshots. * This function can not be called from an update hook callback. */ - void reset(time_t currentTime); + void reset(system_time currentTime); /** * Read configuration. Before reading config, all metrics should be set @@ -199,7 +196,10 @@ public: * of consumers. readConfig() will start a config subscription. It should * not be called multiple times. */ - void init(const config::ConfigUri & uri, bool startThread = true); + void init(const config::ConfigUri & uri, bool startThread); + void init(const config::ConfigUri & uri) { + init(uri, true); + } /** * Visit a given snapshot for a given consumer. (Empty consumer name means @@ -237,15 +237,16 @@ public: return *_totalMetrics; } /** While accessing snapshots you should have the metric lock. */ - const MetricSnapshot& getMetricSnapshot( const MetricLockGuard& guard, uint32_t period) const { + const MetricSnapshot& getMetricSnapshot( const MetricLockGuard& guard, vespalib::duration period) const { return getMetricSnapshot(guard, period, false); } - const MetricSnapshot& getMetricSnapshot( const MetricLockGuard&, uint32_t period, bool getInProgressSet) const; - const MetricSnapshotSet& getMetricSnapshotSet(const MetricLockGuard&, uint32_t period) const; + const MetricSnapshot& getMetricSnapshot( const MetricLockGuard&, vespalib::duration period, bool getInProgressSet) const; + const MetricSnapshotSet& getMetricSnapshotSet(const MetricLockGuard&, vespalib::duration period) const; - std::vector<uint32_t> getSnapshotPeriods(const MetricLockGuard& l) const; + std::vector<vespalib::duration> getSnapshotPeriods(const MetricLockGuard& l) const; - ConsumerSpec::SP getConsumerSpec(const MetricLockGuard & guard, const Metric::String& consumer) const; + // Public only for testing. The returned pointer is only valid while holding the lock. + const ConsumerSpec * getConsumerSpec(const MetricLockGuard & guard, const Metric::String& consumer) const; /** * If you add or remove metrics from the active metric sets, normally, @@ -257,7 +258,7 @@ public: void checkMetricsAltered(const MetricLockGuard &); /** Used by unit tests to verify that we have processed for a given time. */ - time_t getLastProcessedTime() const { return _lastProcessedTime.load(std::memory_order_relaxed); } + time_point getLastProcessedTime() const { return _lastProcessedTime.load(std::memory_order_relaxed); } /** Used by unit tests to wake waiters after altering time. */ void timeChangedNotification() const; @@ -267,14 +268,14 @@ public: bool isInitialized() const; private: - void takeSnapshots(const MetricLockGuard &, time_t timeToProcess); + void takeSnapshots(const MetricLockGuard &, system_time timeToProcess); friend struct MetricManagerTest; friend struct SnapshotTest; void configure(const MetricLockGuard & guard, std::unique_ptr<MetricsmanagerConfig> conf); void run(); - time_t tick(const MetricLockGuard & guard, time_t currentTime); + time_point tick(const MetricLockGuard & guard, time_point currentTime); /** * Utility function for updating periodic metrics. * @@ -284,12 +285,12 @@ private: * without adjusting schedule for next update. * @return Time of next hook to be called in the future. */ - time_t updatePeriodicMetrics(const MetricLockGuard & guard, time_t updateTime, bool outOfSchedule); + time_point updatePeriodicMetrics(const MetricLockGuard & guard, time_point updateTime, bool outOfSchedule); void updateSnapshotMetrics(const MetricLockGuard & guard); void handleMetricsAltered(const MetricLockGuard & guard); - using SnapSpec = std::pair<uint32_t, std::string>; + using SnapSpec = std::pair<vespalib::duration, std::string>; static std::vector<SnapSpec> createSnapshotPeriods( const MetricsmanagerConfig& config); void assertMetricLockLocked(const MetricLockGuard& g) const; }; diff --git a/metrics/src/vespa/metrics/metricsnapshot.cpp b/metrics/src/vespa/metrics/metricsnapshot.cpp index 1580f340f0e..cd06fb731c2 100644 --- a/metrics/src/vespa/metrics/metricsnapshot.cpp +++ b/metrics/src/vespa/metrics/metricsnapshot.cpp @@ -6,39 +6,47 @@ #include <vespa/log/log.h> LOG_SETUP(".metrics.snapshot"); +using vespalib::to_string; +using vespalib::to_s; + + namespace metrics { +static constexpr system_time system_time_epoch = system_time(); + MetricSnapshot::MetricSnapshot(const Metric::String& name) : _name(name), _period(0), - _fromTime(0), - _toTime(0), + _fromTime(system_time_epoch), + _toTime(system_time_epoch), _snapshot(new MetricSet("top", {}, "", nullptr)), _metrics() { } -MetricSnapshot::MetricSnapshot(const Metric::String& name, uint32_t period, const MetricSet& source, bool copyUnset) +MetricSnapshot::MetricSnapshot(const Metric::String& name, vespalib::duration period, const MetricSet& source, bool copyUnset) : _name(name), _period(period), - _fromTime(0), - _toTime(0), + _fromTime(system_time_epoch), + _toTime(system_time_epoch), _snapshot(), _metrics() { - Metric* m = source.clone(_metrics, Metric::INACTIVE, 0, copyUnset); - assert(m->isMetricSet()); - _snapshot.reset(static_cast<MetricSet*>(m)); + _snapshot.reset(source.clone(_metrics, Metric::INACTIVE, 0, copyUnset)); _metrics.shrink_to_fit(); } MetricSnapshot::~MetricSnapshot() = default; void -MetricSnapshot::reset(time_t currentTime) +MetricSnapshot::reset() { + reset(system_time_epoch); +} +void +MetricSnapshot::reset(system_time currentTime) { _fromTime = currentTime; - _toTime = 0; + _toTime = system_time_epoch; _snapshot->reset(); } @@ -61,22 +69,19 @@ MetricSnapshot::addMemoryUsage(MemoryConsumption& mc) const { ++mc._snapshotCount; mc._snapshotName += mc.getStringMemoryUsage(_name, mc._snapshotNameUnique); - mc._snapshotMeta += sizeof(MetricSnapshot) - + _metrics.capacity() * sizeof(Metric::SP); + mc._snapshotMeta += sizeof(MetricSnapshot) + _metrics.capacity() * sizeof(Metric::SP); _snapshot->addMemoryUsage(mc); } -MetricSnapshotSet::MetricSnapshotSet( - const Metric::String& name, uint32_t period, - uint32_t count, const MetricSet& source, bool snapshotUnsetMetrics) +MetricSnapshotSet::MetricSnapshotSet(const Metric::String& name, vespalib::duration period, uint32_t count, + const MetricSet& source, bool snapshotUnsetMetrics) : _count(count), _builderCount(0), - _current(new MetricSnapshot(name, period, source, snapshotUnsetMetrics)), - _building(count == 1 ? 0 : new MetricSnapshot( - name, period, source, snapshotUnsetMetrics)) + _current(std::make_unique<MetricSnapshot>(name, period, source, snapshotUnsetMetrics)), + _building(count == 1 ? nullptr : new MetricSnapshot(name, period, source, snapshotUnsetMetrics)) { - _current->reset(0); - if (_building.get()) _building->reset(0); + _current->reset(); + if (_building.get()) _building->reset(); } MetricSnapshot& @@ -87,35 +92,32 @@ MetricSnapshotSet::getNextTarget() } bool -MetricSnapshotSet::haveCompletedNewPeriod(time_t newFromTime) +MetricSnapshotSet::haveCompletedNewPeriod(system_time newFromTime) { if (_count == 1) { _current->setToTime(newFromTime); return true; } _building->setToTime(newFromTime); - // If not time to roll yet, just return + // If not time to roll yet, just return if (++_builderCount < _count) return false; - // Building buffer done. Use that as current and reset current. - MetricSnapshot::UP tmp(std::move(_current)); - _current = std::move(_building); - _building = std::move(tmp); + // Building buffer done. Use that as current and reset current. + std::swap(_current, _building); _building->reset(newFromTime); _builderCount = 0; return true; } bool -MetricSnapshotSet::timeForAnotherSnapshot(time_t currentTime) { - time_t lastTime = getToTime(); - if (currentTime >= lastTime + getPeriod()) { - if (currentTime >= lastTime + 2 * getPeriod()) { - LOG(warning, "Metric snapshot set %s was asked if it was time for " - "another snapshot, a whole period beyond when it " - "should have been done (Last update was at time %lu" - ", current time is %lu and period is %u). " - "Clearing data and updating time to current time.", - getName().c_str(), lastTime, currentTime, getPeriod()); +MetricSnapshotSet::timeForAnotherSnapshot(system_time currentTime) { + system_time lastTime = getToTime(); + vespalib::duration period = getPeriod(); + if (currentTime >= lastTime + period) { + if (currentTime >= lastTime + 2 * period) { + LOG(warning, "Metric snapshot set %s was asked if it was time for another snapshot, a whole period beyond " + "when it should have been done (Last update was at time %s, current time is %s and period " + "is %f seconds). Clearing data and updating time to current time.", + getName().c_str(), to_string(lastTime).c_str(), to_string(currentTime).c_str(), to_s(getPeriod())); reset(currentTime); } return true; @@ -124,7 +126,7 @@ MetricSnapshotSet::timeForAnotherSnapshot(time_t currentTime) { } void -MetricSnapshotSet::reset(time_t currentTime) { +MetricSnapshotSet::reset(system_time currentTime) { if (_count != 1) _building->reset(currentTime); _current->reset(currentTime); _builderCount = 0; @@ -147,7 +149,7 @@ MetricSnapshotSet::addMemoryUsage(MemoryConsumption& mc) const } void -MetricSnapshotSet::setFromTime(time_t fromTime) +MetricSnapshotSet::setFromTime(system_time fromTime) { if (_count != 1) _building->setFromTime(fromTime); _current->setFromTime(fromTime); diff --git a/metrics/src/vespa/metrics/metricsnapshot.h b/metrics/src/vespa/metrics/metricsnapshot.h index cc6ec4cbb2e..945f9dc7326 100644 --- a/metrics/src/vespa/metrics/metricsnapshot.h +++ b/metrics/src/vespa/metrics/metricsnapshot.h @@ -15,54 +15,52 @@ namespace metrics { +using system_time = vespalib::system_time; + class MetricManager; class MetricSnapshot { Metric::String _name; // Period length of this snapshot - uint32_t _period; + vespalib::duration _period; // Time this snapshot was last updated. - time_t _fromTime; + system_time _fromTime; // If set to 0, use _fromTime + _period. - time_t _toTime; + system_time _toTime; // Keeps the metrics set view of the snapshot std::unique_ptr<MetricSet> _snapshot; // Snapshots must own their own metrics mutable std::vector<Metric::UP> _metrics; public: - using UP = std::unique_ptr<MetricSnapshot>; - using SP = std::shared_ptr<MetricSnapshot>; - /** Create a fresh empty top level snapshot. */ MetricSnapshot(const Metric::String& name); /** Create a snapshot of another metric source. */ - MetricSnapshot(const Metric::String& name, uint32_t period, + MetricSnapshot(const Metric::String& name, vespalib::duration period, const MetricSet& source, bool copyUnset); - virtual ~MetricSnapshot(); + ~MetricSnapshot(); - void addToSnapshot(MetricSnapshot& other, bool reset_, time_t currentTime) { + void addToSnapshot(MetricSnapshot& other, bool reset_, system_time currentTime) { _snapshot->addToSnapshot(other.getMetrics(), other._metrics); if (reset_) reset(currentTime); other._toTime = currentTime; } - void addToSnapshot(MetricSnapshot& other, time_t currentTime) const { + void addToSnapshot(MetricSnapshot& other, system_time currentTime) const { _snapshot->addToSnapshot(other.getMetrics(), other._metrics); other._toTime = currentTime; } - void setFromTime(time_t fromTime) { _fromTime = fromTime; } - void setToTime(time_t toTime) { _toTime = toTime; } + void setFromTime(system_time fromTime) { _fromTime = fromTime; } + void setToTime(system_time toTime) { _toTime = toTime; } const Metric::String& getName() const { return _name; } - uint32_t getPeriod() const { return _period; } - time_t getFromTime() const { return _fromTime; } - time_t getToTime() const { return _toTime; } - time_t getLength() const - { return (_toTime != 0 ? _toTime - _fromTime : _fromTime + _period); } + vespalib::duration getPeriod() const { return _period; } + system_time getFromTime() const { return _fromTime; } + system_time getToTime() const { return _toTime; } const MetricSet& getMetrics() const { return *_snapshot; } MetricSet& getMetrics() { return *_snapshot; } - void reset(time_t currentTime); + void reset(system_time currentTime); + void reset(); /** * Recreate snapshot by cloning given metric set and then add the data * from the old one. New metrics have been added. @@ -77,37 +75,42 @@ class MetricSnapshotSet { // before we have a full time window. uint32_t _builderCount; // Number of times we've currently added to the // building instance. - MetricSnapshot::UP _current; // The last full period - MetricSnapshot::UP _building; // The building period + std::unique_ptr<MetricSnapshot> _current; // The last full period + std::unique_ptr<MetricSnapshot> _building; // The building period public: - using SP = std::shared_ptr<MetricSnapshotSet>; - - MetricSnapshotSet(const Metric::String& name, uint32_t period, - uint32_t count, const MetricSet& source, - bool snapshotUnsetMetrics); + MetricSnapshotSet(const Metric::String& name, vespalib::duration period, uint32_t count, + const MetricSet& source, bool snapshotUnsetMetrics); const Metric::String& getName() const { return _current->getName(); } - uint32_t getPeriod() const { return _current->getPeriod(); } - time_t getFromTime() const { return _current->getFromTime(); } - time_t getToTime() const { return _current->getToTime(); } + vespalib::duration getPeriod() const { return _current->getPeriod(); } + system_time getFromTime() const { return _current->getFromTime(); } + system_time getToTime() const { return _current->getToTime(); } + system_time getNextWorkTime() const { return getToTime() + getPeriod(); } uint32_t getCount() const { return _count; } uint32_t getBuilderCount() const { return _builderCount; } - bool hasTemporarySnapshot() const { return (_building.get() != 0); } - MetricSnapshot& getSnapshot(bool temporary = false) - { return *((temporary && _count > 1) ? _building : _current); } - const MetricSnapshot& getSnapshot(bool temporary = false) const - { return *((temporary && _count > 1) ? _building : _current); } + MetricSnapshot& getSnapshot() { + return getSnapshot(false); + } + MetricSnapshot& getSnapshot(bool temporary) { + return *((temporary && _count > 1) ? _building : _current); + } + const MetricSnapshot& getSnapshot() const { + return getSnapshot(false); + } + const MetricSnapshot& getSnapshot(bool temporary) const { + return *((temporary && _count > 1) ? _building : _current); + } MetricSnapshot& getNextTarget(); - bool timeForAnotherSnapshot(time_t currentTime); - bool haveCompletedNewPeriod(time_t newFromTime); - void reset(time_t currentTime); + bool timeForAnotherSnapshot(system_time currentTime); + bool haveCompletedNewPeriod(system_time newFromTime); + void reset(system_time currentTime); /** * Recreate snapshot by cloning given metric set and then add the data * from the old one. New metrics have been added. */ void recreateSnapshot(const MetricSet& metrics, bool copyUnset); void addMemoryUsage(MemoryConsumption&) const; - void setFromTime(time_t fromTime); + void setFromTime(system_time fromTime); }; } // metrics diff --git a/metrics/src/vespa/metrics/state_api_adapter.cpp b/metrics/src/vespa/metrics/state_api_adapter.cpp index 61a1ce7c2a9..136ccf6e06a 100644 --- a/metrics/src/vespa/metrics/state_api_adapter.cpp +++ b/metrics/src/vespa/metrics/state_api_adapter.cpp @@ -9,12 +9,12 @@ namespace metrics { vespalib::string StateApiAdapter::getMetrics(const vespalib::string &consumer) { - metrics::MetricLockGuard guard(_manager.getMetricLock()); - std::vector<uint32_t> periods = _manager.getSnapshotPeriods(guard); + MetricLockGuard guard(_manager.getMetricLock()); + auto periods = _manager.getSnapshotPeriods(guard); if (periods.empty()) { return ""; // no configuration yet } - const metrics::MetricSnapshot &snapshot(_manager.getMetricSnapshot(guard, periods[0])); + const MetricSnapshot &snapshot(_manager.getMetricSnapshot(guard, periods[0])); vespalib::asciistream json; vespalib::JsonStream stream(json); metrics::JsonWriter metricJsonWriter(stream); @@ -26,17 +26,15 @@ StateApiAdapter::getMetrics(const vespalib::string &consumer) vespalib::string StateApiAdapter::getTotalMetrics(const vespalib::string &consumer) { - _manager.updateMetrics(true); - metrics::MetricLockGuard guard(_manager.getMetricLock()); + _manager.updateMetrics(); + MetricLockGuard guard(_manager.getMetricLock()); _manager.checkMetricsAltered(guard); - time_t currentTime = vespalib::count_s(vespalib::steady_clock::now().time_since_epoch()); - auto generated = std::make_unique<metrics::MetricSnapshot>( - "Total metrics from start until current time", 0, - _manager.getTotalMetricSnapshot(guard).getMetrics(), - true); + system_time currentTime = vespalib::system_clock::now(); + auto generated = std::make_unique<MetricSnapshot>("Total metrics from start until current time", 0s, + _manager.getTotalMetricSnapshot(guard).getMetrics(), true); _manager.getActiveMetrics(guard).addToSnapshot(*generated, false, currentTime); generated->setFromTime(_manager.getTotalMetricSnapshot(guard).getFromTime()); - const metrics::MetricSnapshot &snapshot = *generated; + const MetricSnapshot &snapshot = *generated; vespalib::asciistream json; vespalib::JsonStream stream(json); metrics::JsonWriter metricJsonWriter(stream); diff --git a/metrics/src/vespa/metrics/textwriter.cpp b/metrics/src/vespa/metrics/textwriter.cpp index 94a7b7df73b..fbb31e7013a 100644 --- a/metrics/src/vespa/metrics/textwriter.cpp +++ b/metrics/src/vespa/metrics/textwriter.cpp @@ -7,9 +7,11 @@ #include "valuemetric.h" #include <sstream> +using vespalib::to_string; + namespace metrics { -TextWriter::TextWriter(std::ostream& out, uint32_t period, +TextWriter::TextWriter(std::ostream& out, vespalib::duration period, const std::string& regex, bool verbose) : _period(period), _out(out), _regex(), _verbose(verbose) { @@ -19,14 +21,14 @@ TextWriter::TextWriter(std::ostream& out, uint32_t period, } } -TextWriter::~TextWriter() { } +TextWriter::~TextWriter() = default; bool TextWriter::visitSnapshot(const MetricSnapshot& snapshot) { _out << "snapshot \"" << snapshot.getName() << "\" from " - << snapshot.getFromTime() << " to " << snapshot.getToTime() - << " period " << snapshot.getPeriod(); + << to_string(snapshot.getFromTime()) << " to " << to_string(snapshot.getToTime()) + << " period " << vespalib::count_s(snapshot.getPeriod()); return true; } @@ -82,7 +84,7 @@ bool TextWriter::visitValueMetric(const AbstractValueMetric& m, bool) { if (writeCommon(m)) { - m.print(_out, _verbose, " ", _period); + m.print(_out, _verbose, " ", vespalib::count_s(_period)); } return true; } diff --git a/metrics/src/vespa/metrics/textwriter.h b/metrics/src/vespa/metrics/textwriter.h index f060429e931..f23d1cf585c 100644 --- a/metrics/src/vespa/metrics/textwriter.h +++ b/metrics/src/vespa/metrics/textwriter.h @@ -3,20 +3,21 @@ #pragma once #include "metric.h" +#include <vespa/vespalib/util/time.h> #include <regex> #include <optional> namespace metrics { class TextWriter : public MetricVisitor { - uint32_t _period; + vespalib::duration _period; std::ostream& _out; std::vector<std::string> _path; std::optional<std::regex> _regex; bool _verbose; public: - TextWriter(std::ostream& out, uint32_t period, + TextWriter(std::ostream& out, vespalib::duration period, const std::string& regex, bool verbose); ~TextWriter(); diff --git a/metrics/src/vespa/metrics/updatehook.h b/metrics/src/vespa/metrics/updatehook.h index 58d9ef0d743..997bdf0b5a4 100644 --- a/metrics/src/vespa/metrics/updatehook.h +++ b/metrics/src/vespa/metrics/updatehook.h @@ -26,17 +26,28 @@ private: class MetricManager; class UpdateHook { - const char* _name; - time_t _nextCall; - uint32_t _period; - friend class MetricManager; - public: using MetricLockGuard = metrics::MetricLockGuard; - UpdateHook(const char* name) : _name(name), _nextCall(0), _period(0) {} + UpdateHook(const char* name, vespalib::duration period) + : _name(name), + _period(period), + _nextCall() + {} virtual ~UpdateHook() = default; virtual void updateMetrics(const MetricLockGuard & guard) = 0; const char* getName() const { return _name; } + void updateNextCall() { updateNextCall(_nextCall); } + void updateNextCall(time_point now) { setNextCall(now + _period); } + bool is_periodic() const noexcept { return _period != vespalib::duration::zero(); } + bool expired(time_point now) { return _nextCall <= now; } + bool has_valid_expiry() const noexcept { return _nextCall != time_point(); } + vespalib::duration getPeriod() const noexcept { return _period; } + time_point getNextCall() const noexcept { return _nextCall; } + void setNextCall(time_point now) { _nextCall = now; } +private: + const char* _name; + const vespalib::duration _period; + time_point _nextCall; }; } diff --git a/searchcore/src/vespa/searchcore/proton/metrics/metrics_engine.cpp b/searchcore/src/vespa/searchcore/proton/metrics/metrics_engine.cpp index 1ccb3956fc2..4f7e0e66d9f 100644 --- a/searchcore/src/vespa/searchcore/proton/metrics/metrics_engine.cpp +++ b/searchcore/src/vespa/searchcore/proton/metrics/metrics_engine.cpp @@ -42,7 +42,7 @@ MetricsEngine::start(const config::ConfigUri &) void MetricsEngine::addMetricsHook(metrics::UpdateHook &hook) { - _manager->addMetricUpdateHook(hook, 5); + _manager->addMetricUpdateHook(hook); } void diff --git a/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp b/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp index 9a84383c2f4..3f28f75c521 100644 --- a/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp +++ b/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp @@ -94,7 +94,7 @@ class MetricsUpdateHook : public metrics::UpdateHook { DocumentDB &_db; public: explicit MetricsUpdateHook(DocumentDB &s) - : metrics::UpdateHook("documentdb-hook"), + : metrics::UpdateHook("documentdb-hook", 5s), _db(s) {} void updateMetrics(const MetricLockGuard & guard) override { diff --git a/searchcore/src/vespa/searchcore/proton/server/proton.cpp b/searchcore/src/vespa/searchcore/proton/server/proton.cpp index c508706ad28..8ec904760cf 100644 --- a/searchcore/src/vespa/searchcore/proton/server/proton.cpp +++ b/searchcore/src/vespa/searchcore/proton/server/proton.cpp @@ -136,7 +136,7 @@ struct MetricsUpdateHook : metrics::UpdateHook { Proton &self; explicit MetricsUpdateHook(Proton &s) - : metrics::UpdateHook("proton-hook"), + : metrics::UpdateHook("proton-hook", 5s), self(s) {} void updateMetrics(const MetricLockGuard &guard) override { diff --git a/storage/src/tests/common/metricstest.cpp b/storage/src/tests/common/metricstest.cpp index 7231a071319..63d7be7c499 100644 --- a/storage/src/tests/common/metricstest.cpp +++ b/storage/src/tests/common/metricstest.cpp @@ -185,7 +185,7 @@ void MetricsTest::createFakeLoad() } _clock->addSecondsToTime(60); _metricManager->timeChangedNotification(); - while (int64_t(_metricManager->getLastProcessedTime()) < vespalib::count_s(_clock->getMonotonicTime().time_since_epoch())) { + while (_metricManager->getLastProcessedTime() < _clock->getSystemTime()) { std::this_thread::sleep_for(5ms); _metricManager->timeChangedNotification(); } @@ -235,7 +235,7 @@ TEST_F(MetricsTest, snapshot_presenting) { for (uint32_t i=0; i<6; ++i) { _clock->addSecondsToTime(60); _metricManager->timeChangedNotification(); - while (int64_t(_metricManager->getLastProcessedTime()) < vespalib::count_s(_clock->getMonotonicTime().time_since_epoch())) { + while (_metricManager->getLastProcessedTime() < _clock->getSystemTime()) { std::this_thread::sleep_for(1ms); } } @@ -295,8 +295,8 @@ MetricsTest::createSnapshotForPeriod(std::chrono::seconds secs) const { _clock->addSecondsToTime(secs.count()); _metricManager->timeChangedNotification(); - while (int64_t(_metricManager->getLastProcessedTime()) < vespalib::count_s(_clock->getMonotonicTime().time_since_epoch())) { - std::this_thread::sleep_for(100ms); + while (_metricManager->getLastProcessedTime() < _clock->getSystemTime()) { + std::this_thread::sleep_for(5ms); } } diff --git a/storage/src/tests/storageserver/statereportertest.cpp b/storage/src/tests/storageserver/statereportertest.cpp index 3a772c1ddde..380604ae77b 100644 --- a/storage/src/tests/storageserver/statereportertest.cpp +++ b/storage/src/tests/storageserver/statereportertest.cpp @@ -211,7 +211,7 @@ TEST_F(StateReporterTest, report_metrics) { for (uint32_t i = 0; i < 6; ++i) { _clock->addSecondsToTime(60); _metricManager->timeChangedNotification(); - while (int64_t(_metricManager->getLastProcessedTime()) < vespalib::count_s(_clock->getMonotonicTime().time_since_epoch())) { + while (_metricManager->getLastProcessedTime() < _clock->getSystemTime()) { std::this_thread::sleep_for(1ms); } } diff --git a/storage/src/vespa/storage/common/statusmetricconsumer.cpp b/storage/src/vespa/storage/common/statusmetricconsumer.cpp index c6f73540605..68866027cd1 100644 --- a/storage/src/vespa/storage/common/statusmetricconsumer.cpp +++ b/storage/src/vespa/storage/common/statusmetricconsumer.cpp @@ -51,17 +51,9 @@ bool StatusMetricConsumer::reportStatus(std::ostream& out, const framework::HttpUrlPath& path) const { - // Update metrics unless 'dontcallupdatehooks' is 1. Update - // snapshot metrics too, if callsnapshothooks is set to 1. - if (path.get("dontcallupdatehooks", 0) == 0) { - bool updateSnapshotHooks = path.get("callsnapshothooks", 0) == 1; - LOG(debug, "Updating metrics ahead of status page view%s", - updateSnapshotHooks ? ", calling snapshot hooks too" : "."); - _manager.updateMetrics(updateSnapshotHooks); - } else { - LOG(debug, "Not calling update hooks as dontcallupdatehooks option has been given"); - } - int64_t currentTimeS(vespalib::count_s(_component.getClock().getMonotonicTime().time_since_epoch())); + _manager.updateMetrics(); + + vespalib::system_time currentTime = _component.getClock().getSystemTime(); bool json = (path.getAttribute("format") == "json"); int verbosity(path.get("verbosity", 0)); @@ -72,52 +64,53 @@ StatusMetricConsumer::reportStatus(std::ostream& out, if (path.hasAttribute("task") && path.getAttribute("task") == "reset") { std::lock_guard guard(_lock); - _manager.reset(currentTimeS); + _manager.reset(currentTime); } if (path.hasAttribute("interval")) { // Grab the snapshot we want to view more of - int32_t interval(boost::lexical_cast<int32_t>(path.getAttribute("interval"))); + int32_t intervalS(boost::lexical_cast<int32_t>(path.getAttribute("interval"))); metrics::MetricLockGuard metricLock(_manager.getMetricLock()); std::unique_ptr<metrics::MetricSnapshot> generated; const metrics::MetricSnapshot* snapshot; - if (interval == -2) { + if (intervalS == -2) { snapshot = &_manager.getActiveMetrics(metricLock); - _manager.getActiveMetrics(metricLock).setToTime(currentTimeS); - } else if (interval == -1) { + _manager.getActiveMetrics(metricLock).setToTime(currentTime); + } else if (intervalS == -1) { // "Prime" the metric structure by first fetching the set of active // metrics (complete with structure) and resetting these. This // leaves us with an empty metrics set to which we can (in order) // add the total and the active metrics. If this is not done, non- // written metrics won't be included even if copyUnset is true. generated = std::make_unique<metrics::MetricSnapshot>( - "Total metrics from start until current time", 0, + "Total metrics from start until current time", 0s, _manager.getActiveMetrics(metricLock).getMetrics(), copyUnset); - generated->reset(0); - _manager.getTotalMetricSnapshot(metricLock).addToSnapshot(*generated, currentTimeS); - _manager.getActiveMetrics(metricLock).addToSnapshot(*generated, currentTimeS); + generated->reset(); + _manager.getTotalMetricSnapshot(metricLock).addToSnapshot(*generated, currentTime); + _manager.getActiveMetrics(metricLock).addToSnapshot(*generated, currentTime); generated->setFromTime(_manager.getTotalMetricSnapshot(metricLock).getFromTime()); snapshot = generated.get(); - } else if (interval == 0) { + } else if (intervalS == 0) { if (copyUnset) { generated = std::make_unique<metrics::MetricSnapshot>( - _manager.getTotalMetricSnapshot(metricLock).getName(), 0, + _manager.getTotalMetricSnapshot(metricLock).getName(), 0s, _manager.getActiveMetrics(metricLock).getMetrics(), true); - generated->reset(0); - _manager.getTotalMetricSnapshot(metricLock).addToSnapshot(*generated, currentTimeS); + generated->reset(); + _manager.getTotalMetricSnapshot(metricLock).addToSnapshot(*generated, currentTime); snapshot = generated.get(); } else { snapshot = &_manager.getTotalMetricSnapshot(metricLock); } } else { + vespalib::duration interval = vespalib::from_s(intervalS); if (copyUnset) { generated = std::make_unique<metrics::MetricSnapshot>( - _manager.getMetricSnapshot(metricLock, interval).getName(), 0, + _manager.getMetricSnapshot(metricLock, interval).getName(), 0s, _manager.getActiveMetrics(metricLock).getMetrics(), true); - generated->reset(0); + generated->reset(); _manager.getMetricSnapshot(metricLock, interval, temporarySnap) - .addToSnapshot(*generated, currentTimeS); + .addToSnapshot(*generated, currentTime); snapshot = generated.get(); } else { snapshot = &_manager.getMetricSnapshot(metricLock, interval, temporarySnap); diff --git a/storage/src/vespa/storage/storageserver/statemanager.cpp b/storage/src/vespa/storage/storageserver/statemanager.cpp index c59f7797bb8..654fe0e1f5d 100644 --- a/storage/src/vespa/storage/storageserver/statemanager.cpp +++ b/storage/src/vespa/storage/storageserver/statemanager.cpp @@ -18,7 +18,6 @@ #include <vespa/vespalib/util/string_escape.h> #include <vespa/vespalib/util/stringfmt.h> #include <fstream> -#include <ranges> #include <vespa/log/log.h> LOG_SETUP(".state.manager"); @@ -545,10 +544,9 @@ StateManager::getNodeInfo() const stream << "metrics"; try { metrics::MetricLockGuard lock(_metricManager.getMetricLock()); - std::vector<uint32_t> periods(_metricManager.getSnapshotPeriods(lock)); + auto periods(_metricManager.getSnapshotPeriods(lock)); if (!periods.empty()) { - uint32_t period = periods[0]; - const metrics::MetricSnapshot& snapshot(_metricManager.getMetricSnapshot(lock, period)); + const metrics::MetricSnapshot& snapshot(_metricManager.getMetricSnapshot(lock, periods[0])); metrics::JsonWriter metricJsonWriter(stream); _metricManager.visit(lock, snapshot, metricJsonWriter, "fleetcontroller"); } else { diff --git a/storage/src/vespa/storage/storageserver/statereporter.cpp b/storage/src/vespa/storage/storageserver/statereporter.cpp index 205a2d710a6..d9e79d3b7b4 100644 --- a/storage/src/vespa/storage/storageserver/statereporter.cpp +++ b/storage/src/vespa/storage/storageserver/statereporter.cpp @@ -69,11 +69,11 @@ vespalib::string StateReporter::getMetrics(const vespalib::string &consumer) { metrics::MetricLockGuard guard(_manager.getMetricLock()); - std::vector<uint32_t> periods = _manager.getSnapshotPeriods(guard); + auto periods = _manager.getSnapshotPeriods(guard); if (periods.empty()) { return ""; // no configuration yet } - uint32_t interval = periods[0]; + vespalib::duration interval = periods[0]; // To get unset metrics, we have to copy active metrics, clear them // and then assign the snapshot @@ -81,9 +81,8 @@ StateReporter::getMetrics(const vespalib::string &consumer) _manager.getMetricSnapshot(guard, interval).getName(), interval, _manager.getActiveMetrics(guard).getMetrics(), true); - snapshot.reset(0); - _manager.getMetricSnapshot(guard, interval).addToSnapshot( - snapshot, vespalib::count_s(_component.getClock().getSystemTime().time_since_epoch())); + snapshot.reset(); + _manager.getMetricSnapshot(guard, interval).addToSnapshot(snapshot, _component.getClock().getSystemTime()); vespalib::asciistream json; vespalib::JsonStream stream(json); diff --git a/storage/src/vespa/storageframework/defaultimplementation/component/componentregisterimpl.cpp b/storage/src/vespa/storageframework/defaultimplementation/component/componentregisterimpl.cpp index 40c2cc3b111..74d58244636 100644 --- a/storage/src/vespa/storageframework/defaultimplementation/component/componentregisterimpl.cpp +++ b/storage/src/vespa/storageframework/defaultimplementation/component/componentregisterimpl.cpp @@ -126,8 +126,8 @@ namespace { struct MetricHookWrapper : public metrics::UpdateHook { MetricUpdateHook& _hook; - MetricHookWrapper(vespalib::stringref name, MetricUpdateHook& hook) - : metrics::UpdateHook(name.data()), // Expected to point to static name + MetricHookWrapper(vespalib::stringref name, MetricUpdateHook& hook, vespalib::duration period) + : metrics::UpdateHook(name.data(), period), // Expected to point to static name _hook(hook) { } @@ -142,8 +142,8 @@ ComponentRegisterImpl::registerUpdateHook(vespalib::stringref name, vespalib::duration period) { std::lock_guard lock(_componentLock); - auto hookPtr = std::make_unique<MetricHookWrapper>(name, hook); - _metricManager->addMetricUpdateHook(*hookPtr, vespalib::to_s(period)); + auto hookPtr = std::make_unique<MetricHookWrapper>(name, hook, period); + _metricManager->addMetricUpdateHook(*hookPtr); _hooks.emplace_back(std::move(hookPtr)); } |