text: // Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
  
  #include <vespa/metrics/jsonwriter.h>
  #include <vespa/metrics/metrics.h>
  #include <vespa/metrics/metricmanager.h>
  #include <vespa/metrics/state_api_adapter.h>
  #include <vespa/metrics/textwriter.h>
  #include <vespa/metrics/xmlwriter.h>
  #include <vespa/vespalib/data/slime/slime.h>
  #include <vespa/vespalib/gtest/gtest.h>
  #include <vespa/vespalib/stllike/asciistream.h>
  #include <vespa/vespalib/util/size_literals.h>
  #include <vespa/vespalib/util/xmlstream.h>
  #include <vespa/vespalib/util/time.h>
  #include <vespa/vespalib/data/simple_buffer.h>
  #include <thread>
  
  #include <vespa/log/log.h>
  LOG_SETUP(".test.metricmanager");
  
  namespace metrics {
  
  struct MetricManagerTest : public ::testing::Test {
  
      // Ugly indirection hack caused by some tests using friended internals of
      // 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);
      }
  };
  
  namespace {
  
  struct SubMetricSet : public MetricSet
  {
      DoubleValueMetric val1;
      DoubleValueMetric val2;
      SumMetric<DoubleValueMetric> valsum;
  
      SubMetricSet(const Metric::String & name, MetricSet* owner);
      ~SubMetricSet();
  };
  
  
  SubMetricSet::SubMetricSet(const Metric::String & name, MetricSet* owner)
      : MetricSet(name, {{"sub"}}, "sub desc", owner),
        val1("val1", {{"tag4"},{"snaptest"}}, "val1 desc", this),
        val2("val2", {{"tag5"}}, "val2 desc", this),
        valsum("valsum", {{"tag4"},{"snaptest"}}, "valsum desc", this)
  {
      valsum.addMetricToSum(val1);
      valsum.addMetricToSum(val2);
  }
  SubMetricSet::~SubMetricSet() { }
  
  struct MultiSubMetricSet
  {
      MetricSet set;
      LongCountMetric count;
      SubMetricSet a;
      SubMetricSet b;
      SumMetric<MetricSet> sum;
  
      MultiSubMetricSet(MetricSet* owner);
      ~MultiSubMetricSet();
  };
  
  MultiSubMetricSet::MultiSubMetricSet(MetricSet* owner)
      : set("multisub", {{"multisub"}}, "", owner),
        count("count", {{"snaptest"}}, "counter", &set),
        a("a", &set),
        b("b", &set),
        sum("sum", {{"snaptest"}}, "", &set)
  {
      sum.addMetricToSum(a);
      sum.addMetricToSum(b);
  }
  
  MultiSubMetricSet::~MultiSubMetricSet() { }
  
  struct TestMetricSet {
      MetricSet set;
      DoubleValueMetric val1;
      DoubleValueMetric val2;
      DoubleValueMetric val3;
      DoubleValueMetric val4;
      DoubleValueMetric val5;
      DoubleValueMetric val6;
      DoubleValueMetric val7;
      DoubleValueMetric val8;
      SubMetricSet val9;
      MultiSubMetricSet val10;
  
      TestMetricSet();
      ~TestMetricSet();
  };
  
  TestMetricSet::TestMetricSet()
      : set("temp", {{"test"}}, "desc of test set"),
        val1("val1", {{"tag1"}}, "val1 desc", &set),
        val2("val2", {{"tag1"},{"tag2"}}, "val2 desc", &set),
        val3("val3", {{"tag2"},{"tag3"}}, "val3 desc", &set),
        val4("val4", {{"tag3"}}, "val4 desc", &set),
        val5("val5", {{"tag2"}}, "val5 desc", &set),
        val6("val6", {{"tag4"},{"snaptest"}}, "val6 desc", &set),
        val7("val7", {}, "val7 desc", &set),
        val8("val8", {{"tag6"}}, "val8 desc", &set),
        val9("sub", &set),
        val10(&set)
  { }
  
  TestMetricSet::~TestMetricSet() { }
  
  
  struct MetricNameVisitor : public MetricVisitor {
      std::ostringstream ost;
      bool debug;
  
      MetricNameVisitor(bool debug_ = false) : debug(debug_) {}
  
      bool visitMetricSet(const MetricSet& metricSet, bool autoGenerated) override {
          if (debug) {
              ost << "<" << (autoGenerated ? "*" : "")
                  << metricSet.getPath() << ">\n";
          }
          return true;
      }
      void doneVisitingMetricSet(const MetricSet& metricSet) override {
          if (debug) {
              ost << "</" << metricSet.getPath() << ">\n";
          }
      }
  
      bool visitMetric(const Metric& m, bool autoGenerated) override {
          ost << (autoGenerated ? "*" : "") << m.getPath() << "\n";
          return true;
      }
  
      std::string toString() const { return ost.str(); }
  };
  
  }
  
  namespace {
  
  std::pair<std::string, std::string>
  getMatchedMetrics(const vespalib::string& config)
  {
      FastOS_ThreadPool pool(256_Ki);
      TestMetricSet mySet;
      MetricManager mm;
      mm.registerMetric(mm.getMetricLock(), mySet.set);
      mm.init(config, pool);
      MetricNameVisitor visitor;
  
      /** Take a copy to verify clone works.
      std::list<Metric::SP> ownerList;
      MetricSet::UP copy(dynamic_cast<MetricSet*>(
                  mm.getMetrics().clone(ownerList)));
      mm.visit(*copy, visitor, "consumer");
      */
  
      MetricLockGuard g(mm.getMetricLock());
      mm.visit(g, mm.getActiveMetrics(g), visitor, "consumer");
      MetricManager::ConsumerSpec::SP consumerSpec(
              mm.getConsumerSpec(g, "consumer"));
      return std::pair<std::string, std::string>(
              visitor.toString(),
              consumerSpec.get() ? consumerSpec->toString()
                                 : "Non-existing consumer");
  }
  
  }
  
  #define ASSERT_CONSUMER_MATCH(name, expected, config) \
  { \
      std::pair<std::string, std::string> consumerMatch( \
                                              getMatchedMetrics(config)); \
      EXPECT_EQ("\n" + expected, "\n" + consumerMatch.first) << (name + std::string(": ") + consumerMatch.second); \
  }
  
  TEST_F(MetricManagerTest, test_consumer_visitor)
  {
      // Add one tag and a name, check that we get all three.
      ASSERT_CONSUMER_MATCH("testAddTagAndName", std::string(
              "temp.val1\n"
              "temp.val2\n"
              "temp.val4\n"
              "*temp.multisub.sum.val1\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] tag1\n"
              "consumer[0].addedmetrics[2]\n"
              "consumer[0].addedmetrics[0] temp.val4\n"
              "consumer[0].addedmetrics[1] temp.multisub.sum.val1\n"
      );
      // Add two tags, remove one
      ASSERT_CONSUMER_MATCH("testAddAndRemoveTag", std::string(
              "temp.val1\n"
              "temp.val4\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].tags[2]\n"
              "consumer[0].tags[0] tag1\n"
              "consumer[0].tags[1] tag3\n"
              "consumer[0].removedtags[1]\n"
              "consumer[0].removedtags[0] tag2\n"
      );
      // Test simple wildcards
      ASSERT_CONSUMER_MATCH("testWildCards", std::string(
              "temp.val1\n"
              "temp.val2\n"
              "temp.val3\n"
              "temp.val4\n"
              "temp.val5\n"
              "temp.val6\n"
              "temp.val7\n"
              "temp.val8\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].addedmetrics[1]\n"
              "consumer[0].addedmetrics[0] temp.*\n"
              "consumer[0].removedmetrics[2]\n"
              "consumer[0].removedmetrics[0] temp.sub.*\n"
              "consumer[0].removedmetrics[1] temp.multisub.*\n"
      );
      // Test more wildcards
      ASSERT_CONSUMER_MATCH("testWildCards2", std::string(
              "temp.sub.val1\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].addedmetrics[1]\n"
              "consumer[0].addedmetrics[0] temp.*.val1\n"
      );
      // test adding all
      ASSERT_CONSUMER_MATCH("testAddAll", std::string(
              "metricmanager.periodichooklatency\n"
              "metricmanager.snapshothooklatency\n"
              "metricmanager.resetlatency\n"
              "metricmanager.snapshotlatency\n"
              "metricmanager.sleeptime\n"
              "temp.val1\n"
              "temp.val2\n"
              "temp.val3\n"
              "temp.val4\n"
              "temp.val5\n"
              "temp.val6\n"
              "temp.val7\n"
              "temp.val8\n"
              "temp.sub.val1\n"
              "temp.sub.val2\n"
              "*temp.sub.valsum\n"
              "temp.multisub.count\n"
              "temp.multisub.a.val1\n"
              "temp.multisub.a.val2\n"
              "*temp.multisub.a.valsum\n"
              "temp.multisub.b.val1\n"
              "temp.multisub.b.val2\n"
              "*temp.multisub.b.valsum\n"
              "*temp.multisub.sum.val1\n"
              "*temp.multisub.sum.val2\n"
              "*temp.multisub.sum.valsum\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].addedmetrics[1]\n"
              "consumer[0].addedmetrics[0] *\n"
      );
      // test adding all using tags
      ASSERT_CONSUMER_MATCH("testAddAll2", std::string(
              "temp.val1\n"
              "temp.val2\n"
              "temp.val3\n"
              "temp.val4\n"
              "temp.val5\n"
              "temp.val6\n"
              "temp.val7\n"
              "temp.val8\n"
              "temp.sub.val1\n"
              "temp.sub.val2\n"
              "*temp.sub.valsum\n"
              "temp.multisub.count\n"
              "temp.multisub.a.val1\n"
              "temp.multisub.a.val2\n"
              "*temp.multisub.a.valsum\n"
              "temp.multisub.b.val1\n"
              "temp.multisub.b.val2\n"
              "*temp.multisub.b.valsum\n"
              "*temp.multisub.sum.val1\n"
              "*temp.multisub.sum.val2\n"
              "*temp.multisub.sum.valsum\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] *\n"
      );
      // Test that all metrics are added when a metricsset is added by name
      ASSERT_CONSUMER_MATCH("testSpecifiedSetName", std::string(
              "temp.sub.val1\n"
              "temp.sub.val2\n"
              "*temp.sub.valsum\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].addedmetrics[1]\n"
              "consumer[0].addedmetrics[0] temp.sub\n"
      );
      // Test that all metrics are added when a metricsset is added by tag
      ASSERT_CONSUMER_MATCH("testSpecifiedSetTag", std::string(
              "temp.sub.val1\n"
              "temp.sub.val2\n"
              "*temp.sub.valsum\n"
              "temp.multisub.a.val1\n"
              "temp.multisub.a.val2\n"
              "*temp.multisub.a.valsum\n"
              "temp.multisub.b.val1\n"
              "temp.multisub.b.val2\n"
              "*temp.multisub.b.valsum\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] sub\n"
      );
      // Test that all metrics are added from the set except those with a
      // certain tag.
      ASSERT_CONSUMER_MATCH("testSpecifiedSetTagWithExceptionTags", std::string(
              "temp.val1\n"
              "temp.val4\n"
              "temp.val7\n"
              "temp.val8\n"
              "temp.sub.val2\n"
              "temp.multisub.count\n"
              "temp.multisub.a.val2\n"
              "temp.multisub.b.val2\n"
              "*temp.multisub.sum.val2\n"
          ),
              "raw:"
              "consumer[1]\n"
              "consumer[0].name consumer\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] test\n"
              "consumer[0].removedtags[2]\n"
              "consumer[0].removedtags[0] tag2\n"
              "consumer[0].removedtags[1] tag4\n"
      );
  };
  
  namespace {
  
  struct FakeTimer : public MetricManager::Timer {
      time_t _time;
      FakeTimer(time_t startTime = 0) : _time(startTime) {}
      time_t getTime() const override { return _time; }
  };
  
  struct BriefValuePrinter : public MetricVisitor {
      uint32_t count;
      std::ostringstream ost;
  
      BriefValuePrinter() : count(0), ost() {}
  
      bool visitMetric(const Metric& metric, bool) override {
          if (++count > 1) ost << ",";
          //ost << metric.getPath() << ":";
          ost << metric.getDoubleValue("value");
          return true;
      }
  };
  
  bool waitForTimeProcessed(const MetricManager& mm,
                            time_t processtime, uint32_t timeout = 120)
  {
      uint32_t lastchance = time(0) + timeout;
      while (time(0) < lastchance) {
          if (mm.getLastProcessedTime() >= processtime) return true;
          mm.timeChangedNotification();
          std::this_thread::sleep_for(10ms);
      }
      return false;
  }
  
  std::string dumpAllSnapshots(const MetricManager& mm,
                               const std::string& consumer)
  {
      std::ostringstream ost;
      ost << "\n";
      {
          MetricLockGuard metricLock(mm.getMetricLock());
          BriefValuePrinter briefValuePrinter;
          mm.visit(metricLock, mm.getActiveMetrics(metricLock),
                   briefValuePrinter, consumer);
          ost << "Current: " << briefValuePrinter.ost.str() << "\n";
      }
      {
          MetricLockGuard metricLock(mm.getMetricLock());
          BriefValuePrinter briefValuePrinter;
          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]));
          ost << set.getName() << "\n";
          uint32_t count = 0;
          for (uint32_t j=0; j<2; ++j) {
              if (set.getCount() == 1 && j == 1) continue;
              const MetricSnapshot& snap(set.getSnapshot(j == 1));
              BriefValuePrinter briefValuePrinter;
              mm.visit(metricLock, snap, briefValuePrinter, consumer);
              ost << "  " << count++ << " " << &snap.getMetrics() << ": "
                      << briefValuePrinter.ost.str() << "\n";
          }
      }
      return ost.str();
  }
  
  }
  
  #define ASSERT_VALUES(mm, period, expected) \
  { \
      MetricLockGuard lockGuard(mm.getMetricLock()); \
      BriefValuePrinter briefValuePrinter; \
      if (period == -1) { \
          mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), \
                   briefValuePrinter, "snapper"); \
      } else if (period == 0) { \
          mm.visit(lockGuard, mm.getTotalMetricSnapshot(lockGuard), \
                   briefValuePrinter, "snapper"); \
      } else { \
          mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, period), \
                   briefValuePrinter, "snapper"); \
      } \
      EXPECT_EQ(std::string(expected), briefValuePrinter.ost.str()) << dumpAllSnapshots(mm, "snapper"); \
  }
  
  #define ASSERT_PROCESS_TIME(mm, time) \
  { \
      LOG(info, "Waiting for processed time %u.", time); \
      bool gotToCorrectProgress = waitForTimeProcessed(mm, time); \
      if (!gotToCorrectProgress) \
          FAIL() << "Failed to get to processed time within timeout"; \
  }
  
  TEST_F(MetricManagerTest, test_snapshots)
  {
      FastOS_ThreadPool pool(256_Ki);
      FakeTimer* timer = new FakeTimer(1000);
      std::unique_ptr<MetricManager::Timer> timerImpl(timer);
      TestMetricSet mySet;
      MetricManager mm(std::move(timerImpl));
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.registerMetric(lockGuard, mySet.set);
      }
      mm.init("raw:"
              "consumer[2]\n"
              "consumer[0].name snapper\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] snaptest\n"
              "consumer[1].name log\n"
              "consumer[1].tags[1]\n"
              "consumer[1].tags[0] snaptest\n",
              pool);
      MetricNameVisitor visitor;
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), visitor, "snapper");
          MetricManager::ConsumerSpec::SP consumerSpec(
                  mm.getConsumerSpec(lockGuard, "snapper"));
          EXPECT_EQ(std::string("\n"
                                "temp.val6\n"
                                "temp.sub.val1\n"
                                "*temp.sub.valsum\n"
                                "temp.multisub.count\n"
                                "temp.multisub.a.val1\n"
                                "*temp.multisub.a.valsum\n"
                                "temp.multisub.b.val1\n"
                                "*temp.multisub.b.valsum\n"
                                "*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");
      }
      // Initially, there should be no metrics logged
      ASSERT_PROCESS_TIME(mm, 1000);
      ASSERT_VALUES(mm, 5 * 60, "");
  
      // Adding metrics done in first five minutes.
      mySet.val6.addValue(2);
      mySet.val9.val1.addValue(4);
      mySet.val10.count.inc();
      mySet.val10.a.val1.addValue(7);
      mySet.val10.a.val2.addValue(2);
      mySet.val10.b.val1.addValue(1);
      timer->_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");
  
      // Adding metrics done in second five minute period. Total should
      // be updated to account for both
      mySet.val6.addValue(4);
      mySet.val9.val1.addValue(5);
      mySet.val10.count.inc();
      mySet.val10.a.val1.addValue(8);
      mySet.val10.a.val2.addValue(3);
      mySet.val10.b.val1.addValue(2);
      timer->_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");
  
      //std::cerr << dumpAllSnapshots(mm, "snapper") << "\n";
  
      // Adding another five minute period where nothing have happened.
      // Metric for last 5 minutes should be 0.
      timer->_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");
  
      // Advancing time to 60 minute period, we should create a proper
      // 60 minute period timer.
      mySet.val6.addValue(6);
      for (uint32_t i=0; i<9; ++i) { // 9 x 5 minutes. Avoid snapshot bumping
                                     // due to taking snapshots in the past
          timer->_time += 5 * 60;
          ASSERT_PROCESS_TIME(mm, 1000 + 5 * 60 * (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");
  
      // 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");
  }
  
  TEST_F(MetricManagerTest, test_xml_output)
  {
      FastOS_ThreadPool pool(256_Ki);
      FakeTimer* timer = new FakeTimer(1000);
      std::unique_ptr<MetricManager::Timer> timerImpl(timer);
      MetricManager mm(std::move(timerImpl));
      TestMetricSet mySet;
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.registerMetric(lockGuard, mySet.set);
      }
  
      // Initialize metric manager to get snapshots created.
      mm.init("raw:"
              "consumer[2]\n"
              "consumer[0].name snapper\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] snaptest\n"
              "consumer[1].name log\n"
              "consumer[1].tags[1]\n"
              "consumer[1].tags[0] snaptest\n",
              pool);
  
      takeSnapshots(mm, 1000);
  
      // Adding metrics to have some values in them
      mySet.val6.addValue(2);
      mySet.val9.val1.addValue(4);
      mySet.val10.count.inc();
      mySet.val10.a.val1.addValue(7);
      mySet.val10.a.val2.addValue(2);
      mySet.val10.b.val1.addValue(1);
  
      timer->_time = 1300;
      takeSnapshots(mm, 1300);
  
      std::string expected(
              "'<snapshot name=\"5 minute\" from=\"1000\" to=\"1300\" period=\"300\">\n"
              "  <temp>\n"
              "    <val6 average=\"2\" last=\"2\" min=\"2\" max=\"2\" count=\"1\"/>\n"
              "    <sub>\n"
              "      <val1 average=\"4\" last=\"4\" min=\"4\" max=\"4\" count=\"1\"/>\n"
              "      <valsum average=\"4\" last=\"4\" min=\"4\" max=\"4\" count=\"1\"/>\n"
              "    </sub>\n"
              "    <multisub>\n"
              "      <count count=\"1\"/>\n"
              "      <a>\n"
              "        <val1 average=\"7\" last=\"7\" min=\"7\" max=\"7\" count=\"1\"/>\n"
              "        <valsum average=\"9\" last=\"9\"/>\n"
              "      </a>\n"
              "      <b>\n"
              "        <val1 average=\"1\" last=\"1\" min=\"1\" max=\"1\" count=\"1\"/>\n"
              "        <valsum average=\"1\" last=\"1\" min=\"1\" max=\"1\" count=\"1\"/>\n"
              "      </b>\n"
              "      <sum>\n"
              "        <val1 average=\"8\" last=\"8\"/>\n"
              "        <val2 average=\"2\" last=\"2\" min=\"2\" max=\"2\" count=\"1\"/>\n"
              "        <valsum average=\"10\" last=\"10\"/>\n"
              "      </sum>\n"
              "    </multisub>\n"
              "  </temp>\n"
              "</snapshot>'");
  
      std::ostringstream ost;
      vespalib::XmlOutputStream xos(ost, "  ");
      XmlWriter writer(xos, 300, 0);
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, 300, false),
                   writer, "snapper");
      }
      std::string actual(ost.str());
      // Not bothering to match all the nitty gritty details as it will test
      // more than it needs to. Just be here in order to check on XML output
      // easily if needed.
      EXPECT_EQ(expected, "'" + actual + "'");
  }
  
  TEST_F(MetricManagerTest, test_json_output)
  {
      FastOS_ThreadPool pool(256_Ki);
      FakeTimer* timer = new FakeTimer(1000);
      std::unique_ptr<MetricManager::Timer> timerImpl(timer);
      MetricManager mm(std::move(timerImpl));
      TestMetricSet mySet;
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.registerMetric(lockGuard, mySet.set);
      }
  
      // Initialize metric manager to get snapshots created.
      mm.init("raw:"
              "consumer[1]\n"
              "consumer[0].name snapper\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] snaptest\n",
              pool);
  
      takeSnapshots(mm, 1000);
  
      // Adding metrics to have some values in them
      mySet.val6.addValue(2);
      mySet.val9.val1.addValue(4);
      mySet.val10.count.inc();
      mySet.val10.a.val1.addValue(7);
      mySet.val10.a.val2.addValue(2);
      mySet.val10.b.val1.addValue(1);
  
      timer->_time = 1300;
      takeSnapshots(mm, 1300);
  
      // Create json output
      vespalib::asciistream as;
      vespalib::JsonStream jsonStream(as);
      JsonWriter writer(jsonStream);
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.visit(lockGuard, mm.getMetricSnapshot(lockGuard, 300, false),
                   writer, "snapper");
      }
      jsonStream.finalize();
      std::string jsonData = as.str();
      // Parse it back
      using namespace vespalib::slime;
      vespalib::Slime slime;
      size_t parsed = JsonFormat::decode(vespalib::Memory(jsonData), slime);
      if (parsed == 0) {
          vespalib::SimpleBuffer buffer;
          JsonFormat::encode(slime, buffer, false);
          std::ostringstream ost;
          ost << "Failed to parse JSON: '\n"
              << jsonData << "'\n:" << buffer.get().make_string() << "\n";
          EXPECT_EQ(jsonData.size(), parsed) << ost.str();
      }
      // Verify some content
      EXPECT_EQ(1000.0, slime.get()["snapshot"]["from"].asDouble()) << jsonData;
      EXPECT_EQ(1300.0, slime.get()["snapshot"]["to"].asDouble()) << jsonData;
      EXPECT_EQ(vespalib::string("temp.val6"),
                slime.get()["values"][0]["name"].asString().make_string()) << jsonData;
      EXPECT_EQ(vespalib::string("val6 desc"),
                slime.get()["values"][0]["description"].asString().make_string()) << jsonData;
      EXPECT_EQ(2.0, slime.get()["values"][0]["values"]["average"].asDouble()) << jsonData;
      EXPECT_EQ(1.0, slime.get()["values"][0]["values"]["count"].asDouble()) << jsonData;
      EXPECT_EQ(2.0, slime.get()["values"][0]["values"]["min"].asDouble()) << jsonData;
      EXPECT_EQ(2.0, slime.get()["values"][0]["values"]["max"].asDouble()) << jsonData;
      EXPECT_EQ(2.0, slime.get()["values"][0]["values"]["last"].asDouble()) << jsonData;
  
      EXPECT_EQ(vespalib::string("temp.multisub.sum.valsum"),
                slime.get()["values"][10]["name"].asString().make_string()) << jsonData;
      EXPECT_EQ(vespalib::string("valsum desc"),
                slime.get()["values"][10]["description"].asString().make_string()) << jsonData;
      EXPECT_EQ(10.0, slime.get()["values"][10]["values"]["average"].asDouble()) << jsonData;
      EXPECT_EQ(3.0, slime.get()["values"][10]["values"]["count"].asDouble()) << jsonData;
      EXPECT_EQ(1.0, slime.get()["values"][10]["values"]["min"].asDouble()) << jsonData;
      EXPECT_EQ(7.0, slime.get()["values"][10]["values"]["max"].asDouble()) << jsonData;
      EXPECT_EQ(10.0, slime.get()["values"][10]["values"]["last"].asDouble()) << jsonData;
  
      metrics::StateApiAdapter adapter(mm);
      vespalib::string normal = adapter.getMetrics("snapper");
      EXPECT_EQ(vespalib::string(jsonData), normal);
      vespalib::string total = adapter.getTotalMetrics("snapper");
      EXPECT_GT(total.size(), 0);
      EXPECT_NE(total, normal);
  }
  
  namespace {
  
  struct MetricSnapshotTestFixture
  {
      static const size_t DEFAULT_THREAD_STACK_SIZE = 256_Ki;
  
      MetricManagerTest& test;
      FastOS_ThreadPool pool;
      FakeTimer* timer;
      MetricManager manager;
      MetricSet& mset;
  
      MetricSnapshotTestFixture(MetricManagerTest& callerTest, MetricSet& metricSet)
          : test(callerTest),
            pool(DEFAULT_THREAD_STACK_SIZE),
            timer(new FakeTimer(1000)),
            manager(std::unique_ptr<MetricManager::Timer>(timer)),
            mset(metricSet)
      {
          {
              MetricLockGuard lockGuard(manager.getMetricLock());
              manager.registerMetric(lockGuard, mset);
          }
  
          // Initialize metric manager to get snapshots created.
          manager.init(
                  "raw:"
                  "consumer[1]\n"
                  "consumer[0].name snapper\n"
                  "consumer[0].addedmetrics[1]\n"
                  "consumer[0].addedmetrics[0] *\n",
                  pool);
  
          test.takeSnapshots(manager, 1000);
      }
  
      // Take snapshot of metric values from time 1000 to time 1300
      void takeSnapshotsOnce() {
          timer->_time = 1300;
          test.takeSnapshots(manager, 1300);
      }
  
      std::string renderLastSnapshotAsJson() const {
          vespalib::asciistream as;
          vespalib::JsonStream jsonStream(as, true);
          JsonWriter writer(jsonStream);
          {
              MetricLockGuard lockGuard(manager.getMetricLock());
              manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300, false),
                            writer, "snapper");
          }
          jsonStream.finalize();
          return as.str();
      }
  
      std::string renderLastSnapshotAsText(
              const std::string& matchPattern = ".*") const
      {
          std::ostringstream ss;
          TextWriter writer(ss, 300, matchPattern, true);
          {
              MetricLockGuard lockGuard(manager.getMetricLock());
              manager.visit(lockGuard, manager.getMetricSnapshot(lockGuard, 300, false),
                            writer, "snapper");
          }
          return ss.str();
      }
  };
  
  class JsonMetricWrapper
  {
      std::string _jsonText;
      vespalib::Slime _tree;
  public:
      JsonMetricWrapper(const std::string& jsonText);
      ~JsonMetricWrapper();
  
      // XXX ideally all these should be const, but is not clear how/if it's
      // possible to get a const cursor into the underlying tree.
      vespalib::slime::Cursor& root() { return _tree.get(); }
  
      vespalib::slime::Cursor& nthMetric(size_t metricIndex) {
          return root()["values"][metricIndex];
      }
  
      size_t nthMetricDimensionCount(size_t metricIndex) {
          return nthMetric(metricIndex)["dimensions"].children();
      }
  
      std::string nthMetricName(size_t metricIndex) {
         return nthMetric(metricIndex)["name"].asString().make_string();
      }
  
      std::string nthMetricDimension(size_t metricIndex, const std::string& key) {
          return nthMetric(metricIndex)["dimensions"][key]
                  .asString().make_string();
      }
  
      // Verify that the nth metric has the given name and the given set of 
      // dimension key-values. Cannot use name alone to check, as multiple metrics
      // may have same name but different dimensions and output ordering of
      // metrics is well defined as being that of the insertion order.
      void verifyDimensions(size_t metricIndex,
                            const std::string& name,
                            const Metric::Tags& dimensions) {
          EXPECT_EQ(name, nthMetricName(metricIndex)) << _jsonText;
          EXPECT_EQ(dimensions.size(), nthMetricDimensionCount(metricIndex)) << _jsonText;
          for (auto& dim : dimensions) {
              EXPECT_EQ(std::string(dim.value()), nthMetricDimension(metricIndex, dim.key())) << _jsonText;
          }
      }
  };
  
  JsonMetricWrapper::JsonMetricWrapper(const std::string& jsonText)
      : _jsonText(jsonText)
  {
      vespalib::slime::JsonFormat::decode(vespalib::Memory(jsonText), _tree);
  }
  JsonMetricWrapper::~JsonMetricWrapper() { }
  
  struct DimensionTestMetricSet : MetricSet
  {
      DoubleValueMetric val1;
      LongCountMetric val2;
  
      DimensionTestMetricSet(MetricSet* owner = nullptr);
      ~DimensionTestMetricSet();
  };
  
  DimensionTestMetricSet::DimensionTestMetricSet(MetricSet* owner)
      : MetricSet("temp", {{"foo", "megafoo"}, {"bar", "hyperbar"}}, "", owner),
        val1("val1", {{"tag1"}}, "val1 desc", this),
        val2("val2", {{"baz", "superbaz"}}, "val2 desc", this)
  { }
  DimensionTestMetricSet::~DimensionTestMetricSet() { }
  
  }
  
  TEST_F(MetricManagerTest, json_output_supports_multiple_dimensions)
  {
      DimensionTestMetricSet mset;
      MetricSnapshotTestFixture fixture(*this, mset);
  
      mset.val1.addValue(2);
      mset.val2.inc();
  
      fixture.takeSnapshotsOnce();
      std::string actual = fixture.renderLastSnapshotAsJson();
      JsonMetricWrapper json(actual);
  
      json.verifyDimensions(0, "temp.val1",
                            {{"foo", "megafoo"}, {"bar", "hyperbar"}});
      json.verifyDimensions(1, "temp.val2",
                            {{"foo", "megafoo"}, {"bar", "hyperbar"},
                             {"baz", "superbaz"}});
  }
  
  namespace {
  
  struct NestedDimensionTestMetricSet : MetricSet
  {
      DimensionTestMetricSet nestedSet;
  
      NestedDimensionTestMetricSet()
          : MetricSet("outer", {{"fancy", "stuff"}}, ""),
            nestedSet(this)
      {
      }
  };
  
  }
  
  TEST_F(MetricManagerTest, json_output_can_nest_dimensions_from_multiple_metric_sets)
  {
      NestedDimensionTestMetricSet mset;
      MetricSnapshotTestFixture fixture(*this, mset);
  
      mset.nestedSet.val1.addValue(2);
      mset.nestedSet.val2.inc();
  
      fixture.takeSnapshotsOnce();
      std::string actual = fixture.renderLastSnapshotAsJson();
      JsonMetricWrapper json(actual);
  
      json.verifyDimensions(0, "outer.temp.val1",
                            {{"foo", "megafoo"}, {"bar", "hyperbar"},
                             {"fancy", "stuff"}});
      json.verifyDimensions(1, "outer.temp.val2",
                            {{"foo", "megafoo"}, {"bar", "hyperbar"},
                             {"baz", "superbaz"}, {"fancy", "stuff"}});
  }
  
  namespace {
  
  struct DimensionOverridableTestMetricSet : MetricSet
  {
      DoubleValueMetric val;
  
      DimensionOverridableTestMetricSet(const std::string& dimValue,
                                  MetricSet* owner = nullptr)
          : MetricSet("temp", {{"foo", dimValue}}, "", owner),
            val("val", {}, "val desc", this)
      { }
  };
  
  struct SameNamesTestMetricSet : MetricSet
  {
      DimensionOverridableTestMetricSet set1;
      DimensionOverridableTestMetricSet set2;
  
      SameNamesTestMetricSet();
      ~SameNamesTestMetricSet();
  };
  
  SameNamesTestMetricSet::SameNamesTestMetricSet()
      : MetricSet("outer", {{"fancy", "stuff"}}, ""),
        set1("bar", this),
        set2("baz", this)
  { }
  SameNamesTestMetricSet::~SameNamesTestMetricSet() { }
  
  }
  
  TEST_F(MetricManagerTest, json_output_can_have_multiple_sets_with_same_name)
  {
      SameNamesTestMetricSet mset;
      MetricSnapshotTestFixture fixture(*this, mset);
  
      mset.set1.val.addValue(2);
      mset.set2.val.addValue(5);
  
      fixture.takeSnapshotsOnce();
      std::string actual = fixture.renderLastSnapshotAsJson();
      JsonMetricWrapper json(actual);
  
      // Note the identical names. Only difference is the dimensions per set.
      json.verifyDimensions(0, "outer.temp.val",
                            {{"foo", "bar"}, {"fancy", "stuff"}});
      json.verifyDimensions(1, "outer.temp.val",
                            {{"foo", "baz"}, {"fancy", "stuff"}});
  }
  
  TEST_F(MetricManagerTest, test_text_output)
  {
      FastOS_ThreadPool pool(256_Ki);
      FakeTimer* timer = new FakeTimer(1000);
      std::unique_ptr<MetricManager::Timer> timerImpl(timer);
      MetricManager mm(std::move(timerImpl));
      TestMetricSet mySet;
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.registerMetric(lockGuard, mySet.set);
      }
          // Adding metrics to have some values in them
      mySet.val6.addValue(2);
      mySet.val9.val1.addValue(4);
      mySet.val10.count.inc();
      mySet.val10.a.val1.addValue(7);
      mySet.val10.a.val2.addValue(2);
      mySet.val10.b.val1.addValue(1);
          // Initialize metric manager to get snapshots created.
      mm.init("raw:"
              "consumer[2]\n"
              "consumer[0].name snapper\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] snaptest\n"
              "consumer[1].name log\n"
              "consumer[1].tags[1]\n"
              "consumer[1].tags[0] snaptest\n",
              pool);
      std::string expected(
          "snapshot \"Active metrics showing updates since last snapshot\" from 1000 to 0 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"
          "temp.multisub.count count=1\n"
          "temp.multisub.a.val1 average=7 last=7 min=7 max=7 count=1 total=7\n"
          "temp.multisub.a.valsum average=9 last=9\n"
          "temp.multisub.b.val1 average=1 last=1 min=1 max=1 count=1 total=1\n"
          "temp.multisub.b.valsum average=1 last=1 min=1 max=1 count=1 total=1\n"
          "temp.multisub.sum.val1 average=8 last=8\n"
          "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);
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.visit(lockGuard, mm.getActiveMetrics(lockGuard), writer, "snapper");
      }
      std::string actual(ost.str());
      // Not bothering to match all the nitty gritty details as it will test
      // more than it needs to. Just be here in order to check on XML output
      // easily if needed.
      EXPECT_EQ(expected, actual);
  }
  
  TEST_F(MetricManagerTest, text_output_supports_dimensions)
  {
      NestedDimensionTestMetricSet mset;
      MetricSnapshotTestFixture fixture(*this, mset);
  
      mset.nestedSet.val1.addValue(2);
      mset.nestedSet.val2.inc();
  
      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");
      EXPECT_EQ(expected, actual);
  }
  
  namespace {
      struct MyUpdateHook : public UpdateHook {
          std::ostringstream& _output;
          FakeTimer& _timer;
  
          MyUpdateHook(std::ostringstream& output, const char* name,
                       FakeTimer& timer)
              : UpdateHook(name), _output(output), _timer(timer) {}
  
          void updateMetrics(const MetricLockGuard & ) override {
              _output << _timer.getTime() << ": " << getName() << " called\n";
          }
      };
  }
  
  TEST_F(MetricManagerTest, test_update_hooks)
  {
      std::ostringstream output;
      FastOS_ThreadPool pool(256_Ki);
      FakeTimer* timer = new FakeTimer(1000);
      std::unique_ptr<MetricManager::Timer> timerImpl(timer);
          // Add a metric set just so one exist
      TestMetricSet mySet;
      MetricManager mm(std::move(timerImpl));
      {
          MetricLockGuard lockGuard(mm.getMetricLock());
          mm.registerMetric(lockGuard, mySet.set);
      }
  
      MyUpdateHook preInitShort(output, "BIS", *timer);
      MyUpdateHook preInitLong(output, "BIL", *timer);
      MyUpdateHook preInitInfinite(output, "BII", *timer);
      mm.addMetricUpdateHook(preInitShort, 5);
      mm.addMetricUpdateHook(preInitLong, 300);
      mm.addMetricUpdateHook(preInitInfinite, 0);
  
      // All hooks should get called during initialization
  
      // Initialize metric manager to get snapshots created.
      output << "Running init\n";
      mm.init("raw:"
              "consumer[2]\n"
              "consumer[0].name snapper\n"
              "consumer[0].tags[1]\n"
              "consumer[0].tags[0] snaptest\n"
              "consumer[1].name log\n"
              "consumer[1].tags[1]\n"
              "consumer[1].tags[0] snaptest\n",
              pool);
      output << "Init done\n";
  
      MyUpdateHook postInitShort(output, "AIS", *timer);
      MyUpdateHook postInitLong(output, "AIL", *timer);
      MyUpdateHook postInitInfinite(output, "AII", *timer);
      mm.addMetricUpdateHook(postInitShort, 5);
      mm.addMetricUpdateHook(postInitLong, 400);
      mm.addMetricUpdateHook(postInitInfinite, 0);
  
      // After 5 seconds the short ones should get another.
  
      timer->_time = 1006;
      waitForTimeProcessed(mm, 1006);
  
      // 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->_time = 1010;
      waitForTimeProcessed(mm, 1010);
  
      // Bumping considerably ahead, such that next update is in the past,
      // we should only get one update called in this period.
  
      timer->_time = 1200;
      waitForTimeProcessed(mm, 1200);
  
      // No updates at this time.
      timer->_time = 1204;
      waitForTimeProcessed(mm, 1204);
  
      // Give all hooks an update
      mm.updateMetrics(true);
  
      // Last update should not have interfered with periods
      timer->_time = 1205;
      waitForTimeProcessed(mm, 1205);
  
      // Time is just ahead of a snapshot.
      timer->_time = 1299;
      waitForTimeProcessed(mm, 1299);
  
      // 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->_time = 1300;
      waitForTimeProcessed(mm, 1300);
  
      // The snapshot time currently doesn't count for the metric at period
      // 400. It will get an event at this time.
      timer->_time = 1450;
      waitForTimeProcessed(mm, 1450);
  
      std::string expected(
          "Running init\n"
          "1000: BIS called\n"
          "1000: BIL called\n"
          "Init done\n"
          "1006: BIS called\n"
          "1006: AIS called\n"
          "1010: BIS called\n"
          "1010: AIS called\n"
          "1200: BIS called\n"
          "1200: AIS called\n"
          "1204: BIS called\n"
          "1204: BIL called\n"
          "1204: AIS called\n"
          "1204: AIL called\n"
          "1204: BII called\n"
          "1204: AII called\n"
          "1205: BIS called\n"
          "1205: AIS called\n"
          "1299: BIS called\n"
          "1299: AIS called\n"
          "1300: BIS called\n"
          "1300: BIL called\n"
          "1300: AIS called\n"
          "1300: AIL called\n"
          "1300: BII called\n"
          "1300: AII called\n"
          "1450: BIS called\n"
          "1450: AIS called\n"
          "1450: AIL called\n"
      );
      std::string actual(output.str());
      EXPECT_EQ(expected, actual);
  }
  
  }
  