Avoid filling log with unused metrics events.

13 files changed, 11 insertions, 149 deletions

diff --git a/metrics/src/vespa/metrics/countmetric.cpp b/metrics/src/vespa/metrics/countmetric.cpp
index 0c2504b2077..672df721dc0 100644
--- a/metrics/src/vespa/metrics/countmetric.cpp
+++ b/metrics/src/vespa/metrics/countmetric.cpp
@@ -17,12 +17,6 @@ AbstractCountMetric::logWarning(const char* msg, const char * op) const
     LOG(warning, "%s", ost.str().data());
 }
 
-void
-AbstractCountMetric::sendLogCountEvent(Metric::String name, uint64_t value) const
-{
-    EV_COUNT(name.c_str(), value);
-}
-
 template class CountMetric<uint64_t, true>;
 
 } // metrics
diff --git a/metrics/src/vespa/metrics/countmetric.h b/metrics/src/vespa/metrics/countmetric.h
index 675b5698049..de34e9330e6 100644
--- a/metrics/src/vespa/metrics/countmetric.h
+++ b/metrics/src/vespa/metrics/countmetric.h
@@ -40,7 +40,6 @@ protected:
     }
 
     void logWarning(const char* msg, const char * op) const;
-    void sendLogCountEvent(Metric::String name, uint64_t value) const;
 };
 
 template<typename T, bool SumOnAdd>
@@ -49,10 +48,6 @@ class CountMetric : public AbstractCountMetric
     using Values = CountMetricValues<T>;
     MetricValueSet<Values> _values;
 
-    enum Flag { LOG_IF_UNSET = 2 };
-
-    bool logIfUnset() const { return _values.hasFlag(LOG_IF_UNSET); }
-
 public:
     CountMetric(const String& name, Tags dimensions,
                 const String& description, MetricSet* owner = 0);
@@ -64,7 +59,6 @@ public:
     MetricValueClass::UP getValues() const override {
         return MetricValueClass::UP(new Values(_values.getValues()));
     }
-    void logOnlyIfSet() { _values.removeFlag(LOG_IF_UNSET); }
 
     void set(T value);
     void inc(T value = 1);
@@ -89,10 +83,6 @@ public:
     T getValue() const { return _values.getValues()._value; }
 
     void reset() override { _values.reset(); }
-
-    bool logFromTotalMetrics() const override { return true; }
-    bool logEvent(const String& fullName) const override;
-
     void print(std::ostream&, bool verbose,
                const std::string& indent, uint64_t secondsPassed) const override;
 
diff --git a/metrics/src/vespa/metrics/countmetric.hpp b/metrics/src/vespa/metrics/countmetric.hpp
index 810ba7e371d..8b5c226a5f5 100644
--- a/metrics/src/vespa/metrics/countmetric.hpp
+++ b/metrics/src/vespa/metrics/countmetric.hpp
@@ -12,9 +12,7 @@ CountMetric<T, SumOnAdd>::CountMetric(const String& name, Tags dimensions,
                                       const String& desc, MetricSet* owner)
     : AbstractCountMetric(name, std::move(dimensions), desc, owner),
       _values()
-{
-    _values.setFlag(LOG_IF_UNSET);
-}
+{}
 
 template <typename T, bool SumOnAdd>
 CountMetric<T, SumOnAdd>::CountMetric(const CountMetric<T, SumOnAdd>& other,
@@ -132,17 +130,6 @@ CountMetric<T, SumOnAdd>::addToPart(Metric& other) const
 }
 
 template <typename T, bool SumOnAdd>
-bool
-CountMetric<T, SumOnAdd>::logEvent(const String& fullName) const
-{
-    Values values(_values.getValues());
-    if (!logIfUnset() && values._value == 0) return false;
-    sendLogCountEvent(
-            fullName, static_cast<uint64_t>(values._value));
-    return true;
-}
-
-template <typename T, bool SumOnAdd>
 void
 CountMetric<T, SumOnAdd>::print(std::ostream& out, bool verbose,
                                 const std::string& indent,
diff --git a/metrics/src/vespa/metrics/metric.h b/metrics/src/vespa/metrics/metric.h
index 845f40a335b..dbbe0f09eb8 100644
--- a/metrics/src/vespa/metrics/metric.h
+++ b/metrics/src/vespa/metrics/metric.h
@@ -163,10 +163,6 @@ public:
     /** Reset all metric values. */
     virtual void reset() = 0;
 
-    virtual bool logFromTotalMetrics() const { return false; }
-    /** Implement to make metric able to log event. */
-    virtual bool logEvent(const String& fullName) const = 0;
-
     void print(std::ostream& out, bool verbose,
                        const std::string& indent) const override {
         print(out, verbose, indent, 0);
diff --git a/metrics/src/vespa/metrics/metricmanager.cpp b/metrics/src/vespa/metrics/metricmanager.cpp
index 04f7568bfba..7b7a17d92e8 100644
--- a/metrics/src/vespa/metrics/metricmanager.cpp
+++ b/metrics/src/vespa/metrics/metricmanager.cpp
@@ -68,13 +68,13 @@ MetricManager::MetricManager(std::unique_ptr<Timer> timer)
       _configHandle(),
       _config(),
       _consumerConfig(),
-      _logPeriod(5 * 60, 0),
       _snapshots(),
       _totalMetrics(std::make_shared<MetricSnapshot>(
                 "Empty metrics before init", 0, _activeMetrics.getMetrics(),
                 false)),
       _timer(std::move(timer)),
       _lastProcessedTime(0),
+      _firstIteration(true),
       _forceEventLogging(false),
       _snapshotUnsetMetrics(false),
       _consumerConfigChanged(false),
@@ -111,7 +111,7 @@ MetricManager::addMetricUpdateHook(UpdateHook& hook, uint32_t period)
     vespalib::MonitorGuard sync(_waiter);
         // If we've already initialized manager, log period has been set.
         // In this case. Call first time after period
-    hook._nextCall = (_logPeriod.second == 0 ? 0 : _timer->getTime() + period);
+    hook._nextCall = _timer->getTime() + period;
     if (period == 0) {
         for (UpdateHook * sHook : _snapshotUpdateHooks) {
             if (sHook == &hook) {
@@ -740,29 +740,6 @@ MetricManager::reset(time_t currentTime)
     _resetLatency.addValue(postTime - preTime);
 }
 
-namespace {
-
-    struct LogMetricVisitor : public MetricVisitor {
-        bool _total;
-
-        LogMetricVisitor(bool totalVals) : _total(totalVals) {}
-
-        bool visitMetric(const Metric& metric, bool autoGenerated) override {
-            (void) autoGenerated;
-            if (metric.logFromTotalMetrics() ^ _total) return true;
-            Metric::String logName = metric.getPath();
-            std::replace(logName.begin(), logName.end(), '.', '_');
-            if (!metric.logEvent(logName)) {
-                LOG(spam, "Not logging event from metric %s.%s as no values "
-                          "have been added to metric.",
-                    metric.getPath().c_str(), metric.getName().c_str());
-            }
-            return true;
-        }
-    };
-
-} // End of anonymous namespace
-
 void
 MetricManager::run()
 {
@@ -784,17 +761,13 @@ MetricManager::tick(const MetricLockGuard & guard, time_t currentTime)
 {
     LOG(spam, "Worker thread starting to process for time %" PRIu64 ".",
         static_cast<uint64_t>(currentTime));
-    bool firstIteration = (_logPeriod.second == 0);
         // For a slow system to still be doing metrics tasks each n'th
         // second, rather than each n'th + time to do something seconds,
         // 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 nextWorkTime;
-    if (firstIteration) {
-            // Setting next log period to now, such that we log metrics
-            // straight away
-        _logPeriod.second = currentTime;
+    if (_firstIteration) {
         for (uint32_t i=0; i<_snapshots.size(); ++i) {
             _snapshots[i]->setFromTime(currentTime);
         }
@@ -803,6 +776,7 @@ MetricManager::tick(const MetricLockGuard & guard, time_t currentTime)
         }
             // Ensure correct time for first snapshot
         _snapshots[0]->getSnapshot().setToTime(currentTime);
+        _firstIteration = false;
     }
 
     // Check for new config and reconfigure
@@ -832,45 +806,12 @@ MetricManager::tick(const MetricLockGuard & guard, time_t currentTime)
     }
         // Do snapshotting if it is time
     if (nextWorkTime <= currentTime) takeSnapshots(guard, nextWorkTime);
-        // Log if it is time
-    if (_logPeriod.second <= currentTime || _forceEventLogging) {
-        LogMetricVisitor totalVisitor(true);
-        LogMetricVisitor fiveMinVisitor(false);
-        if (_logPeriod.second <= currentTime) {
-            LOG(debug, "Logging total metrics.");
-            visit(guard, *_totalMetrics, totalVisitor, "log");
-            visit(guard, _snapshots[0]->getSnapshot(), fiveMinVisitor , "log");
-            if (_logPeriod.second + _logPeriod.first < currentTime) {
-                uint64_t next = _snapshots[0]->getFromTime() + _logPeriod.first;
-                LOG(warning, "Logged events at time %" PRIu64 " for time %"
-                             PRIu64 ". Since this is more than a period %u "
-                             "in the past, next run has been set to next "
-                             "snapshot time at %" PRIu64 ".",
-                    static_cast<uint64_t>(currentTime), static_cast<uint64_t>(_logPeriod.second), _logPeriod.first, next);
-                _logPeriod.second = next;
-            } else {
-                _logPeriod.second += _logPeriod.first;
-            }
-        } else {
-            LOG(debug, "Logging total metrics out of sequence.");
-            metrics::MetricSnapshot snapshot(
-                    "Total out of sequence metrics from start until "
-                    "current time", 0, _totalMetrics->getMetrics(),
-                    _snapshotUnsetMetrics);
-            _activeMetrics.addToSnapshot(snapshot, false, currentTime);
-            snapshot.setFromTime(_totalMetrics->getFromTime());
-            visit(guard, snapshot, totalVisitor, "log");
-            visit(guard, snapshot, fiveMinVisitor, "log");
-        }
-        _forceEventLogging = false;
-    }
+
     _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 = std::min(
-            _logPeriod.second,
-            _snapshots[0]->getPeriod() + _snapshots[0]->getToTime());
+    time_t next = _snapshots[0]->getPeriod() + _snapshots[0]->getToTime();
     next = std::min(next, nextUpdateHookTime);
     return next;
 }
diff --git a/metrics/src/vespa/metrics/metricmanager.h b/metrics/src/vespa/metrics/metricmanager.h
index f2b2926873f..223813683d0 100644
--- a/metrics/src/vespa/metrics/metricmanager.h
+++ b/metrics/src/vespa/metrics/metricmanager.h
@@ -107,11 +107,11 @@ private:
     std::list<UpdateHook*> _snapshotUpdateHooks;
     vespalib::Monitor _waiter;
     typedef std::pair<uint32_t, time_t> PeriodTimePair;
-    PeriodTimePair _logPeriod;
     std::vector<MetricSnapshotSet::SP> _snapshots;
     MetricSnapshot::SP _totalMetrics;
     std::unique_ptr<Timer> _timer;
     std::atomic<time_t> _lastProcessedTime;
+    bool _firstIteration;
     bool _forceEventLogging;
     // Should be added to config, but wont now due to problems with
     // upgrading
diff --git a/metrics/src/vespa/metrics/metricset.cpp b/metrics/src/vespa/metrics/metricset.cpp
index b4238dc0a7c..5cb25cee560 100644
--- a/metrics/src/vespa/metrics/metricset.cpp
+++ b/metrics/src/vespa/metrics/metricset.cpp
@@ -281,14 +281,6 @@ MetricSet::addTo(Metric& other, std::vector<Metric::UP> *ownerList) const
     }
 }
 
-bool
-MetricSet::logEvent(const String& fullName) const
-{
-    (void) fullName;
-    throw vespalib::IllegalStateException(
-            "logEvent() cannot be called on metrics set.", VESPA_STRLOC);
-}
-
 void
 MetricSet::reset()
 {
diff --git a/metrics/src/vespa/metrics/metricset.h b/metrics/src/vespa/metrics/metricset.h
index da3f2c26cde..66225b8f868 100644
--- a/metrics/src/vespa/metrics/metricset.h
+++ b/metrics/src/vespa/metrics/metricset.h
@@ -51,8 +51,6 @@ public:
 
     bool visit(MetricVisitor&, bool tagAsAutoGenerated = false) const override;
 
-    bool logEvent(const String& fullName) const override;
-
     void print(std::ostream&, bool verbose, const std::string& indent, uint64_t secondsPassed) const override;
 
     // These should never be called on metrics set.
diff --git a/metrics/src/vespa/metrics/summetric.h b/metrics/src/vespa/metrics/summetric.h
index c461fb25313..f04c1696638 100644
--- a/metrics/src/vespa/metrics/summetric.h
+++ b/metrics/src/vespa/metrics/summetric.h
@@ -59,7 +59,6 @@ public:
     void addMetricToSum(const AddendMetric&);
     void removeMetricFromSum(const AddendMetric&);
 
-    bool logEvent(const String& fullName) const override;
     void print(std::ostream&, bool verbose, const std::string& indent, uint64_t secondsPassed) const override;
     int64_t getLongValue(stringref id) const override;
     double getDoubleValue(stringref id) const override;
diff --git a/metrics/src/vespa/metrics/summetric.hpp b/metrics/src/vespa/metrics/summetric.hpp
index fc3c3a5e019..9520456a974 100644
--- a/metrics/src/vespa/metrics/summetric.hpp
+++ b/metrics/src/vespa/metrics/summetric.hpp
@@ -251,15 +251,6 @@ SumMetric<AddendMetric>::getDoubleValue(stringref id) const
 }
 
 template<typename AddendMetric>
-bool
-SumMetric<AddendMetric>::logEvent(const String & fullName) const
-{
-    std::pair<std::vector<Metric::UP>, Metric::UP> sum(generateSum());
-    if (sum.second.get() == 0) return false;
-    return sum.second->logEvent(fullName);
-}
-
-template<typename AddendMetric>
 void
 SumMetric<AddendMetric>::print(std::ostream& out, bool verbose,
                                const std::string& indent,
diff --git a/metrics/src/vespa/metrics/valuemetric.cpp b/metrics/src/vespa/metrics/valuemetric.cpp
index 48baa59c7a0..8c1e49d425c 100644
--- a/metrics/src/vespa/metrics/valuemetric.cpp
+++ b/metrics/src/vespa/metrics/valuemetric.cpp
@@ -23,12 +23,6 @@ AbstractValueMetric::logWarning(const char* msg, const char * op) const
 }
 
 void
-AbstractValueMetric::sendLogEvent(Metric::String name, double value) const
-{
-    EV_VALUE(name.c_str(), value);
-}
-
-void
 AbstractValueMetric::logNonFiniteValueWarning() const
 {
     if (hasWarned.exchange(true, std::memory_order_relaxed) == false) {
diff --git a/metrics/src/vespa/metrics/valuemetric.h b/metrics/src/vespa/metrics/valuemetric.h
index 44a4e551cba..6e120af191d 100644
--- a/metrics/src/vespa/metrics/valuemetric.h
+++ b/metrics/src/vespa/metrics/valuemetric.h
@@ -48,15 +48,13 @@ class ValueMetric : public AbstractValueMetric {
     MetricValueSet<Values> _values;
 
     enum Flag {
-        SUMMED_AVERAGE = 2, UNSET_ON_ZERO_VALUE = 4, LOG_IF_UNSET = 8
+        SUMMED_AVERAGE = 2, UNSET_ON_ZERO_VALUE = 4
     };
 
     bool summedAverage() const override { return _values.hasFlag(SUMMED_AVERAGE); }
 
     bool unsetOnZeroValue() const { return _values.hasFlag(UNSET_ON_ZERO_VALUE); }
 
-    bool logIfUnset() const { return _values.hasFlag(LOG_IF_UNSET); }
-
     void add(const Values &values, bool sumOnAdd);
 
     void dec(const Values &values);
@@ -93,8 +91,6 @@ public:
 
     void unsetOnZeroValue() { _values.setFlag(UNSET_ON_ZERO_VALUE); }
 
-    void logOnlyIfSet() { _values.removeFlag(LOG_IF_UNSET); }
-
     ValueMetric *clone(std::vector<Metric::UP> &, CopyType type, MetricSet *owner,
                        bool /*includeUnused*/) const override {
         return new ValueMetric<AvgVal,TotVal,SumOnAdd>(*this, type, owner);
@@ -135,7 +131,6 @@ public:
     AvgVal getLast() const { return _values.getValues()._last; }
 
     void reset() override { _values.reset(); }
-    bool logEvent(const String& fullName) const override;
 
     void print(std::ostream&, bool verbose,
                const std::string& indent, uint64_t secondsPassed) const override;
diff --git a/metrics/src/vespa/metrics/valuemetric.hpp b/metrics/src/vespa/metrics/valuemetric.hpp
index 8b2ee532614..10c640b5926 100644
--- a/metrics/src/vespa/metrics/valuemetric.hpp
+++ b/metrics/src/vespa/metrics/valuemetric.hpp
@@ -15,9 +15,7 @@ ValueMetric<AvgVal, TotVal, SumOnAdd>::ValueMetric(
         const String& description, MetricSet* owner)
     : AbstractValueMetric(name, std::move(dimensions), description, owner),
       _values()
-{
-    _values.setFlag(LOG_IF_UNSET);
-}
+{}
 
 template<typename AvgVal, typename TotVal, bool SumOnAdd>
 ValueMetric<AvgVal, TotVal, SumOnAdd>::ValueMetric(
@@ -25,8 +23,7 @@ ValueMetric<AvgVal, TotVal, SumOnAdd>::ValueMetric(
         CopyType copyType, MetricSet* owner)
     : AbstractValueMetric(other, owner),
       _values(other._values, copyType == CLONE ? other._values.size() : 1)
-{
-}
+{}
 
 template<typename AvgVal, typename TotVal, bool SumOnAdd>
 ValueMetric<AvgVal, TotVal, SumOnAdd>::~ValueMetric() { }
@@ -182,18 +179,6 @@ ValueMetric<AvgVal, TotVal, SumOnAdd>::getAverage() const
 }
 
 template<typename AvgVal, typename TotVal, bool SumOnAdd>
-bool
-ValueMetric<AvgVal, TotVal, SumOnAdd>::logEvent(const String& fullName) const
-{
-    Values values(_values.getValues());
-    if (!logIfUnset() && !inUse(values)) return false;
-    sendLogEvent(fullName, SumOnAdd
-            ? static_cast<double>(values._last)
-            : static_cast<double>(values._total) / values._count);
-    return true;
-}
-
-template<typename AvgVal, typename TotVal, bool SumOnAdd>
 void
 ValueMetric<AvgVal, TotVal, SumOnAdd>::print(
         std::ostream& out, bool verbose, const std::string& indent,