Add support for saiplayer bulk API and add performance timers (sonic-net#666)

* [sairedis] Add PerformanceIntervalTimer class

* [sairedis] Add deserialize tests

* [sairedis] Add performance timer to route_entry bulk create

* [sairedis] Add PerformanceIntervalTimer class to makefile

* [saiplayer] Add support for bulk generic API and bulk route_entry

* [vs] Add performance timer for route_entry create API

* [syncd] Fix for ZeroMQSelectableChannel thread join

* [syncd] Add performance timers to syncd route_entry create and db

Author: kcudnik

lib/inc/PerformanceIntervalTimer.h

@@ -0,0 +1,51 @@
+#pragma once
+
+#include "swss/sal.h"
+
+#include <chrono>
+#include <string>
+
+namespace sairediscommon
+{
+    class PerformanceIntervalTimer
+    {
+        public:
+
+            static constexpr unsigned int DEFAULT_LIMIT = 10000;
+
+        public:
+
+            PerformanceIntervalTimer(
+                    _In_ const char* msg,
+                    _In_ uint64_t limit = DEFAULT_LIMIT);
+
+            ~PerformanceIntervalTimer() = default; // non virtual
+
+        public:
+
+            void start();
+
+            void stop();
+
+            void inc(
+                    _In_ uint64_t val = 1);
+
+            void reset();
+
+        public:
+
+            static bool m_enable;
+
+        private:
+
+            std::string m_msg;
+
+            std::chrono::time_point<std::chrono::high_resolution_clock> m_start;
+            std::chrono::time_point<std::chrono::high_resolution_clock> m_stop;
+
+            uint64_t m_limit;
+            uint64_t m_count;
+            uint64_t m_calls;
+            uint64_t m_total;
+    };
+}

lib/src/Makefile.am

@@ -10,6 +10,7 @@ lib_LTLIBRARIES = libsairedis.la
 
 noinst_LIBRARIES = libSaiRedis.a
 libSaiRedis_a_SOURCES = \
+						 PerformanceIntervalTimer.cpp \
 						 ZeroMQChannel.cpp \
 						 Channel.cpp \
 						 Context.cpp \

lib/src/PerformanceIntervalTimer.cpp

@@ -0,0 +1,63 @@
+#include "PerformanceIntervalTimer.h"
+
+#include "swss/logger.h"
+
+using namespace sairediscommon;
+
+bool PerformanceIntervalTimer::m_enable = true;
+
+PerformanceIntervalTimer::PerformanceIntervalTimer(
+        _In_ const char*msg,
+        _In_ uint64_t limit):
+    m_msg(msg),
+    m_limit(limit)
+{
+    SWSS_LOG_ENTER();
+
+    reset();
+}
+
+void PerformanceIntervalTimer::start()
+{
+    SWSS_LOG_ENTER();
+
+    m_start = std::chrono::high_resolution_clock::now();
+}
+
+void PerformanceIntervalTimer::stop()
+{
+    SWSS_LOG_ENTER();
+
+    m_stop = std::chrono::high_resolution_clock::now();
+}
+
+void PerformanceIntervalTimer::inc(
+        _In_ uint64_t val)
+{
+    SWSS_LOG_ENTER();
+
+    m_count += val;
+
+    m_calls++;
+
+    m_total += std::chrono::duration_cast<std::chrono::nanoseconds>(m_stop-m_start).count();
+
+    if (m_count >= m_limit)
+    {
+        if (m_enable)
+        {
+            SWSS_LOG_NOTICE("%zu (calls %zu) %s op took: %zu ms", m_count, m_calls, m_msg.c_str(), m_total/1000000);
+        }
+
+        reset();
+    }
+}
+
+void PerformanceIntervalTimer::reset()
+{
+    SWSS_LOG_ENTER();
+
+    m_count = 0;
+    m_calls = 0;
+    m_total = 0;
+}

lib/src/RedisRemoteSaiInterface.cpp

@@ -6,6 +6,7 @@
 #include "SkipRecordAttrContainer.h"
 #include "SwitchContainer.h"
 #include "ZeroMQChannel.h"
+#include "PerformanceIntervalTimer.h"
 
 #include "sairediscommon.h"
 
@@ -16,6 +17,7 @@
 
 using namespace sairedis;
 using namespace saimeta;
+using namespace sairediscommon;
 using namespace std::placeholders;
 
 std::string joinFieldValues(
@@ -1541,6 +1543,10 @@ sai_status_t RedisRemoteSaiInterface::bulkCreate(
 
     // TODO support mode
 
+    static PerformanceIntervalTimer timer("RedisRemoteSaiInterface::bulkCreate(route_entry)");
+
+    timer.start();
+
     std::vector<std::string> serialized_object_ids;
 
     // on create vid is put in db by syncd
@@ -1550,15 +1556,20 @@ sai_status_t RedisRemoteSaiInterface::bulkCreate(
         serialized_object_ids.push_back(str_object_id);
     }
 
-    return bulkCreate(
+    auto status = bulkCreate(
             SAI_OBJECT_TYPE_ROUTE_ENTRY,
             serialized_object_ids,
             attr_count,
             attr_list,
             mode,
             object_statuses);
-}
 
+    timer.stop();
+
+    timer.inc(object_count);
+
+    return status;
+}
 
 sai_status_t RedisRemoteSaiInterface::bulkCreate(
         _In_ uint32_t object_count,

lib/src/tests.cpp

@@ -6,6 +6,7 @@ extern "C" {
 
 #include "swss/logger.h"
 #include "swss/table.h"
+#include "swss/tokenize.h"
 
 #include "meta/sai_serialize.h"
 #include "meta/SaiAttributeList.h"
@@ -104,6 +105,63 @@ void test_serialize_remove_route_entry(int n)
     std::cout << "ms: " << (double)us.count()/1000 << " / " << n << std::endl;
 }
 
+void test_deserialize_route_entry_meta(int n)
+{
+    SWSS_LOG_ENTER();
+
+    // meta key 123ms/10k
+    auto s = serialize_route_entry();
+    // auto s = sai_serialize_route_entry(get_route_entry());
+
+    std::cout << s << std::endl;
+
+    auto start = std::chrono::high_resolution_clock::now();
+
+    for (int i = 0; i < n; i++)
+    {
+        sai_object_meta_key_t mk;
+        sai_deserialize_object_meta_key(s, mk);
+
+        //sai_route_entry_t route_entry;
+        //sai_deserialize_route_entry(s, route_entry);
+    }
+
+    auto end = std::chrono::high_resolution_clock::now();
+    auto time = end - start;
+    auto us = std::chrono::duration_cast<std::chrono::microseconds>(time);
+    std::cout << "ms: " << (double)us.count()/1000 << " / " << n << std::endl;
+}
+
+void test_deserialize_route_entry(int n)
+{
+    SWSS_LOG_ENTER();
+
+    // 7.2 ms
+    // 8.9 ms with try/catch
+    // 13ms for entire object meta key
+
+    char buffer[1000];
+
+    sai_route_entry_t route_entry = get_route_entry();
+    sai_serialize_route_entry(buffer, &route_entry);
+
+    auto s = std::string(buffer);
+
+    std::cout << s << std::endl;
+
+    auto start = std::chrono::high_resolution_clock::now();
+
+    for (int i = 0; i < n; i++)
+    {
+        sai_deserialize_route_entry(s.c_str(), &route_entry);
+    }
+
+    auto end = std::chrono::high_resolution_clock::now();
+    auto time = end - start;
+    auto us = std::chrono::duration_cast<std::chrono::microseconds>(time);
+    std::cout << "ms: " << (double)us.count()/1000 << " / " << n << std::endl;
+}
+
 void test_serialize_remove_oid(int n)
 {
     SWSS_LOG_ENTER();
@@ -664,14 +722,142 @@ void test_ContextConfigContainer()
     auto ccc = ContextConfigContainer::loadFromFile("context_config.json");
 }
 
+static std::vector<std::string> tokenize(
+        _In_ std::string input,
+        _In_ const std::string &delim)
+{
+    SWSS_LOG_ENTER();
+
+    /*
+     * input is modified so it can't be passed as reference
+     */
+
+    std::vector<std::string> tokens;
+
+    size_t pos = 0;
+
+    while ((pos = input.find(delim)) != std::string::npos)
+    {
+        std::string token = input.substr(0, pos);
+
+        input.erase(0, pos + delim.length());
+        tokens.push_back(token);
+    }
+
+    tokens.push_back(input);
+
+    return tokens;
+}
+
+static sai_object_type_t deserialize_object_type(
+        _In_ const std::string& s)
+{
+    SWSS_LOG_ENTER();
+
+    sai_object_type_t object_type;
+
+    sai_deserialize_object_type(s, object_type);
+
+    return object_type;
+}
+
+void test_tokenize_bulk_route_entry()
+{
+    SWSS_LOG_ENTER();
+
+    auto header = "2020-09-24.21:06:54.045505|C|SAI_OBJECT_TYPE_ROUTE_ENTRY";
+    auto route = "||{\"dest\":\"20c1:bb0:0:80::/64\",\"switch_id\":\"oid:0x21000000000000\",\"vr\":\"oid:0x3000000000022\"}|SAI_ROUTE_ENTRY_ATTR_NEXT_HOP_ID=oid:0x500000000066c";
+
+    std::string line = header;
+
+    int per = 100;
+
+    for (int i = 0; i < per; i++)
+    {
+        line += route;
+    }
+
+    auto tstart = std::chrono::high_resolution_clock::now();
+
+    int n = 1000;
+
+    for (int c = 0; c < n; c++)
+    {
+        auto fields = tokenize(line, "||");
+
+        auto first = fields.at(0); // timestamp|action|objecttype
+
+        std::string str_object_type = swss::tokenize(first, '|').at(2);
+
+        sai_object_type_t object_type = deserialize_object_type(str_object_type);
+
+        std::vector<std::string> object_ids;
+
+        std::vector<std::shared_ptr<SaiAttributeList>> attributes;
+
+        for (size_t idx = 1; idx < fields.size(); ++idx)
+        {
+            // object_id|attr=value|...
+            const std::string &joined = fields[idx];
+
+            auto split = swss::tokenize(joined, '|');
+
+            std::string str_object_id = split.front();
+
+            object_ids.push_back(str_object_id);
+
+            std::vector<swss::FieldValueTuple> entries; // attributes per object id
+
+            SWSS_LOG_DEBUG("processing: %s", joined.c_str());
+
+            for (size_t i = 1; i < split.size(); ++i)
+            {
+                const auto &item = split[i];
+
+                auto start = item.find_first_of("=");
+
+                auto field = item.substr(0, start);
+                auto value = item.substr(start + 1);
+
+                swss::FieldValueTuple entry(field, value);
+
+                entries.push_back(entry);
+            }
+
+            // since now we converted this to proper list, we can extract attributes
+
+            std::shared_ptr<SaiAttributeList> list =
+                std::make_shared<SaiAttributeList>(object_type, entries, false);
+
+            attributes.push_back(list);
+        }
+    }
+
+    auto tend = std::chrono::high_resolution_clock::now();
+    auto time = tend - tstart;
+    auto us = std::chrono::duration_cast<std::chrono::microseconds>(time);
+
+    std::cout << "ms: " << (double)us.count()/1000.0 / n << " n " << n << " / per " << per << std::endl;
+    std::cout << "s: " << (double)us.count()/1000000.0 << " for total routes: " <<( n * per) << std::endl;
+}
+
 int main()
 {
     SWSS_LOG_ENTER();
 
+    std::cout << " * test tokenize bulk route entry" << std::endl;
+
+    test_tokenize_bulk_route_entry();
+
     std::cout << " * test ContextConfigContainer" << std::endl;
 
     test_ContextConfigContainer();
 
+    std::cout << " * test deserialize route_entry" << std::endl;
+
+    test_deserialize_route_entry_meta(10000);
+    test_deserialize_route_entry(10000);
+
     std::cout << " * test remove" << std::endl;
 
     test_serialize_remove_route_entry(10000);