From: Akhilesh MY (amuttuva) <amuttuva@cisco.com>
Date: Thu, 27 Jul 2023 10:59:36 +0000 (+0000)
Subject: Pull request #3846: profiler: shell commands for time profiler
X-Git-Tag: 3.1.67.0~3
X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=ce91ac13cd2cacf8e4684512fc389ffb985de15a;p=thirdparty%2Fsnort3.git

Pull request #3846: profiler: shell commands for time profiler

Merge in SNORT/snort3 from ~AMUTTUVA/snort3:time_profiling to master

Squashed commit of the following:

commit 153408ae69c20bbe2f8f8afdfe125cc544e37207
Author: Akhilesh MY <amuttuva@cisco.com>
Date:   Fri May 12 10:10:19 2023 -0400

    profiler: shell commands for time profiler

    profiler: Handle reload scenarios and tsan issues

    profiler: remove interdependency with time and memory for accumulation
    change command names to match exposed profiler
---

diff --git a/src/ips_options/test/ips_regex_test.cc b/src/ips_options/test/ips_regex_test.cc
index 2242ea0ec..c462ecf88 100644
--- a/src/ips_options/test/ips_regex_test.cc
+++ b/src/ips_options/test/ips_regex_test.cc
@@ -103,7 +103,7 @@ char* snort_strdup(const char* s)
 MemoryContext::MemoryContext(MemoryTracker&) { }
 MemoryContext::~MemoryContext() = default;
 
-bool TimeProfilerStats::enabled = false;
+THREAD_LOCAL bool TimeProfilerStats::enabled = false;
 }
 
 extern const BaseApi* ips_regex;
diff --git a/src/main/analyzer.cc b/src/main/analyzer.cc
index 4942d67f7..5897c341c 100644
--- a/src/main/analyzer.cc
+++ b/src/main/analyzer.cc
@@ -647,6 +647,7 @@ void Analyzer::init_unprivileged()
     PacketTracer::thread_init();
     HostAttributesManager::initialize();
     RuleContext::set_enabled(sc->profiler->rule.show);
+    TimeProfilerStats::set_enabled(sc->profiler->time.show);
 
     // in case there are HA messages waiting, process them first
     HighAvailabilityManager::process_receive();
diff --git a/src/main/test/distill_verdict_stubs.h b/src/main/test/distill_verdict_stubs.h
index 649af12bc..c2706726f 100644
--- a/src/main/test/distill_verdict_stubs.h
+++ b/src/main/test/distill_verdict_stubs.h
@@ -68,7 +68,7 @@ THREAD_LOCAL bool RuleContext::enabled = false;
 
 void Profiler::start() { }
 void Profiler::stop(uint64_t) { }
-void Profiler::consolidate_stats() { }
+void Profiler::consolidate_stats(snort::ProfilerType) { }
 void Swapper::apply(Analyzer&) { }
 Swapper::~Swapper() = default;
 void OopsHandler::tinit() { }
@@ -128,7 +128,7 @@ namespace snort
 static struct timeval s_packet_time = { 0, 0 };
 THREAD_LOCAL PacketTracer* s_pkt_trace;
 THREAD_LOCAL TimeContext* ProfileContext::curr_time = nullptr;
-bool TimeProfilerStats::enabled = false;
+THREAD_LOCAL bool TimeProfilerStats::enabled = false;
 THREAD_LOCAL PacketCount pc;
 
 void packet_gettimeofday(struct timeval* tv) { *tv = s_packet_time; }
diff --git a/src/network_inspectors/appid/test/appid_http_session_test.cc b/src/network_inspectors/appid/test/appid_http_session_test.cc
index ce88abdd5..ceaf94a71 100644
--- a/src/network_inspectors/appid/test/appid_http_session_test.cc
+++ b/src/network_inspectors/appid/test/appid_http_session_test.cc
@@ -160,8 +160,8 @@ void AppIdDebug::set_constraints(const char*, const AppIdDebugSessionConstraints
 // Profiler mock functions
 void Profiler::register_module(Module*) { }
 void Profiler::register_module(const char*, const char*, Module*) { }
-void Profiler::consolidate_stats() { }
-void Profiler::reset_stats() { }
+void Profiler::consolidate_stats(snort::ProfilerType) { }
+void Profiler::reset_stats(snort::ProfilerType) { }
 void Profiler::show_stats() { }
 
 OdpContext::OdpContext(const AppIdConfig&, snort::SnortConfig*) { }
diff --git a/src/profiler/memory_profiler.cc b/src/profiler/memory_profiler.cc
index c2f937792..91203669f 100644
--- a/src/profiler/memory_profiler.cc
+++ b/src/profiler/memory_profiler.cc
@@ -27,6 +27,7 @@
 #include "profiler_nodes.h"
 #include "profiler_printer.h"
 #include "memory_defs.h"
+#include "control/control.h"
 
 #ifdef UNIT_TEST
 #include "catch/snort_catch.h"
@@ -143,6 +144,16 @@ static void print_fn(StatsTable& t, const View& v)
     t << v.avg_alloc();
 }
 
+struct s_print_table
+{
+    ControlConn* ctrlcon;
+
+    s_print_table(ControlConn* ctrlcon) : ctrlcon(ctrlcon) {}
+
+    void operator()(const char* l) const
+    { LogRespond(ctrlcon, "%s", l); }
+};
+
 } // namespace memory_stats
 
 void show_memory_profiler_stats(ProfilerNodeMap& nodes, const MemoryProfilerConfig& config)
@@ -157,8 +168,9 @@ void show_memory_profiler_stats(ProfilerNodeMap& nodes, const MemoryProfilerConf
         return;
 
     const auto& sorter = memory_stats::sorters[config.sort];
+    const auto& printer_t = memory_stats::s_print_table(nullptr);
 
-    ProfilerPrinter<memory_stats::View> printer(memory_stats::fields, memory_stats::print_fn, sorter);
+    ProfilerPrinter<memory_stats::View> printer(memory_stats::fields, memory_stats::print_fn, sorter, printer_t);
     printer.print_table(s_memory_table_title, root, config.count, config.max_depth);
 }
 
diff --git a/src/profiler/profiler.cc b/src/profiler/profiler.cc
index 1760e8007..b3b3cc27a 100644
--- a/src/profiler/profiler.cc
+++ b/src/profiler/profiler.cc
@@ -48,6 +48,8 @@ THREAD_LOCAL ProfileStats otherPerfStats;
 
 THREAD_LOCAL TimeContext* ProfileContext::curr_time = nullptr;
 THREAD_LOCAL Stopwatch<SnortClock>* run_timer = nullptr;
+THREAD_LOCAL uint64_t first_pkt_num = 0;
+THREAD_LOCAL bool consolidated_once = false;
 
 static ProfilerNodeMap s_profiler_nodes;
 
@@ -74,33 +76,63 @@ void Profiler::register_module(const char* n, const char* pn, Module* m)
 
 void Profiler::start()
 {
+    first_pkt_num = (uint64_t)get_packet_number();
     run_timer = new Stopwatch<SnortClock>;
     run_timer->start();
+    consolidated_once = false;
 }
 
 void Profiler::stop(uint64_t checks)
 {
-    run_timer->stop();
-    totalPerfStats.time.elapsed = run_timer->get();
-    totalPerfStats.time.checks = checks;
+    if ( run_timer )
+    {
+        run_timer->stop();
+        totalPerfStats.time.elapsed = run_timer->get();
+        totalPerfStats.time.checks = checks - first_pkt_num;
 
-    delete run_timer;
-    run_timer = nullptr;
+        delete run_timer;
+        run_timer = nullptr;
+    }
 }
 
-void Profiler::consolidate_stats()
+void Profiler::consolidate_stats(snort::ProfilerType type)
 {
-    s_profiler_nodes.accumulate_nodes();
-    MemoryProfiler::consolidate_fallthrough_stats();
+    if ( !consolidated_once and type == snort::PROFILER_TYPE_TIME )
+    {
+        s_profiler_nodes.accumulate_nodes(snort::PROFILER_TYPE_TIME);
+        consolidated_once = true;
+    }
+    else if ( !consolidated_once and type == snort::PROFILER_TYPE_BOTH )
+    {
+        s_profiler_nodes.accumulate_nodes();
+    }
+
+    if ( consolidated_once and type == snort::PROFILER_TYPE_BOTH )
+    {
+#ifdef ENABLE_MEMORY_PROFILER
+        s_profiler_nodes.accumulate_nodes(PROFILER_TYPE_MEMORY);
+        MemoryProfiler::consolidate_fallthrough_stats();
+#endif
+    }
 }
 
-void Profiler::reset_stats()
+void Profiler::reset_stats(snort::ProfilerType type)
 {
-    s_profiler_nodes.reset_nodes();
-    reset_rule_profiler_stats();
+    if ( type == snort::PROFILER_TYPE_TIME )
+    {
+        totalPerfStats.reset_time();
+        otherPerfStats.reset_time();
+    }
+    else
+    {
+        totalPerfStats.reset();
+        otherPerfStats.reset();
+    }
+
+    s_profiler_nodes.reset_nodes(type);
 }
 
-void Profiler::show_stats()
+void Profiler::prepare_stats()
 {
     const ProfilerNode& root = s_profiler_nodes.get_root();
     auto children = root.get_children();
@@ -108,6 +140,8 @@ void Profiler::show_stats()
     hr_duration runtime = root.get_stats().time.elapsed;
     hr_duration sum = 0_ticks;
 
+    s_profiler_nodes.clear_flex();
+
     for ( auto pn : children )
         sum += pn->get_stats().time.elapsed;
 
@@ -115,7 +149,16 @@ void Profiler::show_stats()
     otherPerfStats.time.elapsed = (runtime > sum) ?  (runtime - sum) : 0_ticks;
 
     s_profiler_nodes.accumulate_flex();
+}
+
+ProfilerNodeMap& Profiler::get_profiler_nodes()
+{
+    return s_profiler_nodes;
+}
 
+void Profiler::show_stats()
+{
+    prepare_stats();
     const auto* config = SnortConfig::get_conf()->get_profiler();
     assert(config);
 
diff --git a/src/profiler/profiler.h b/src/profiler/profiler.h
index 333ec1311..5a9fc2f15 100644
--- a/src/profiler/profiler.h
+++ b/src/profiler/profiler.h
@@ -28,7 +28,8 @@ namespace snort
 {
 class Module;
 }
-
+class ControlConn;
+class ProfilerNodeMap;
 class Profiler
 {
 public:
@@ -38,10 +39,12 @@ public:
     static void start();
     static void stop(uint64_t);
 
-    static void consolidate_stats();
+    static void consolidate_stats(snort::ProfilerType = snort::PROFILER_TYPE_BOTH);
 
-    static void reset_stats();
+    static void reset_stats(snort::ProfilerType = snort::PROFILER_TYPE_BOTH);
+    static void prepare_stats();
     static void show_stats();
+    static ProfilerNodeMap& get_profiler_nodes();
 };
 
 extern THREAD_LOCAL snort::ProfileStats totalPerfStats;
diff --git a/src/profiler/profiler_defs.h b/src/profiler/profiler_defs.h
index b43fef248..bd73d6f09 100644
--- a/src/profiler/profiler_defs.h
+++ b/src/profiler/profiler_defs.h
@@ -33,6 +33,13 @@ namespace snort
 #define ROOT_NODE "total"
 #define FLEX_NODE "other"
 
+enum ProfilerType
+{
+    PROFILER_TYPE_TIME,
+    PROFILER_TYPE_MEMORY,
+    PROFILER_TYPE_BOTH
+};
+
 struct ProfilerConfig
 {
     TimeProfilerConfig time;
@@ -51,11 +58,18 @@ struct SO_PUBLIC ProfileStats
         memory.reset();
     }
 
+    void reset_time()
+    {
+        time.reset();
+    }
+
     bool operator==(const ProfileStats&) const;
     bool operator!=(const ProfileStats& rhs) const
     { return !(*this == rhs); }
 
     ProfileStats& operator+=(const ProfileStats&);
+    ProfileStats& operator+=(const TimeProfilerStats&);
+    ProfileStats& operator+=(const MemoryTracker&);
 
     constexpr ProfileStats() = default;
     constexpr ProfileStats(const TimeProfilerStats& time, const MemoryTracker& memory) :
@@ -73,6 +87,18 @@ inline ProfileStats& ProfileStats::operator+=(const ProfileStats& rhs)
     return *this;
 }
 
+inline ProfileStats& ProfileStats::operator+=(const TimeProfilerStats& rhs)
+{
+    time += rhs;
+    return *this;
+}
+
+inline ProfileStats& ProfileStats::operator+=(const MemoryTracker& rhs)
+{
+    memory.stats += rhs.stats;
+    return *this;
+}
+
 class SO_PUBLIC ProfileContext
 {
 public:
diff --git a/src/profiler/profiler_module.cc b/src/profiler/profiler_module.cc
index 4cb82f845..7502f04ad 100644
--- a/src/profiler/profiler_module.cc
+++ b/src/profiler/profiler_module.cc
@@ -37,6 +37,8 @@
 
 #include "rule_profiler.h"
 #include "rule_profiler_defs.h"
+#include "time_profiler.h"
+#include "time_profiler_defs.h"
 
 using namespace snort;
 
@@ -255,6 +257,101 @@ static const Parameter profiler_dump_params[] =
     { nullptr, Parameter::PT_MAX, nullptr, nullptr, nullptr }
 };
 
+static void time_profiling_start_cmd()
+{
+    // Because profiler is always started in Analyzer::operator()
+    Profiler::stop(0);
+    TimeProfilerStats::set_enabled(true);
+    Profiler::reset_stats(snort::PROFILER_TYPE_TIME);
+    Profiler::start();
+}
+
+static void time_profiling_stop_cmd()
+{
+    TimeProfilerStats::set_enabled(false);
+    Profiler::stop((uint64_t)get_packet_number());
+    Profiler::consolidate_stats(snort::PROFILER_TYPE_TIME);
+}
+
+class ProfilerTimeCmd : public AnalyzerCommand
+{
+public:
+    ProfilerTimeCmd(bool en) : enable(en) { }
+    bool execute(Analyzer&, void**) override
+    {
+        if ( enable )
+            time_profiling_start_cmd();
+        else
+            time_profiling_stop_cmd();
+
+        return true;
+    }
+    const char* stringify() override { return "TIME_PROFILING"; }
+private:
+    bool enable;
+};
+
+static int time_profiling_start(lua_State* L)
+{
+    ControlConn* ctrlcon = ControlConn::query_from_lua(L);
+    if ( TimeProfilerStats::is_enabled() )
+    {
+        LogRespond(ctrlcon, "Time profiling is already started.\n");
+        return 0;
+    }
+    Profiler::reset_stats(snort::PROFILER_TYPE_TIME);
+    TimeProfilerStats::set_enabled(true);
+    main_broadcast_command(new ProfilerTimeCmd(true), ctrlcon);
+    LogRespond(ctrlcon, "Time profiling is started.\n");
+    return 0;
+}
+
+static int time_profiling_stop(lua_State* L)
+{
+    ControlConn* ctrlcon = ControlConn::query_from_lua(L);
+    if ( !TimeProfilerStats::is_enabled() )
+    {
+        LogRespond(ctrlcon, "Time profiling is not started.\n");
+        return 0;
+    }
+
+    TimeProfilerStats::set_enabled(false);
+    main_broadcast_command(new ProfilerTimeCmd(false), ctrlcon);
+    LogRespond(ctrlcon, "Time profiling is stopped.\n");
+    return 0;
+}
+
+static int time_profiling_dump(lua_State* L)
+{
+    ControlConn* ctrlcon = ControlConn::query_from_lua(L);
+    if ( TimeProfilerStats::is_enabled() )
+    {
+        LogRespond(ctrlcon, "Time profiling is still running.\n");
+        return 0;
+    }
+
+    Profiler::prepare_stats();
+
+    const auto* config = SnortConfig::get_conf()->get_profiler();
+    assert(config);
+
+    print_time_profiler_stats(Profiler::get_profiler_nodes(), config->time, ctrlcon);
+
+    return 0;
+}
+
+static int time_profiling_status(lua_State* L)
+{
+    ControlConn* ctrlcon = ControlConn::query_from_lua(L);
+
+    if ( TimeProfilerStats::is_enabled() )
+        LogRespond(ctrlcon, "Time profiling is enabled.\n");
+    else
+        LogRespond(ctrlcon, "Time profiling is disabled.\n");
+
+    return 0;
+}
+
 static const Command profiler_cmds[] =
 {
     { "rule_start", rule_profiling_start,
@@ -269,6 +366,18 @@ static const Command profiler_cmds[] =
     { "rule_dump", rule_profiling_dump,
       profiler_dump_params, "print rule statistics in table or json format (json format prints dates as Unix epoch)" },
 
+    { "module_start", time_profiling_start,
+      nullptr, "enable module time profiling" },
+
+    { "module_stop", time_profiling_stop,
+      nullptr, "disable module time profiling" },
+
+    { "module_dump", time_profiling_dump,
+      nullptr, "print module time profiling statistics" },
+
+    { "module_status", time_profiling_status,
+      nullptr, "show module time profiler status" },
+
     { nullptr, nullptr, nullptr, nullptr }
 };
 
@@ -344,13 +453,21 @@ static const Parameter profiler_params[] =
 class ProfilerReloadTuner : public snort::ReloadResourceTuner
 {
 public:
-    explicit ProfilerReloadTuner(bool enable) : enable(enable)
+    explicit ProfilerReloadTuner(bool enable_rule, bool enable_time) 
+        : enable_rule(enable_rule), enable_time(enable_time)
     {}
     ~ProfilerReloadTuner() override = default;
 
     bool tinit() override
     {
-        RuleContext::set_enabled(enable);
+        RuleContext::set_enabled(enable_rule);
+
+        if ( enable_time && !TimeProfilerStats::is_enabled() )
+            time_profiling_start_cmd();
+
+        else if ( !enable_time && TimeProfilerStats::is_enabled() )
+            time_profiling_stop_cmd();
+
         return false;
     }
 
@@ -361,7 +478,8 @@ public:
     { return true; }
 
 private:
-    bool enable = false;
+    bool enable_rule = false;
+    bool enable_time = false;
 };
 
 template<typename T>
@@ -419,7 +537,8 @@ bool ProfilerModule::end(const char* fqn, int, SnortConfig* sc)
     RuleContext::set_enabled(sc->profiler->rule.show);
 
     if ( Snort::is_reloading() && strcmp(fqn, "profiler") == 0 )
-        sc->register_reload_handler(new ProfilerReloadTuner(sc->profiler->rule.show));
+        sc->register_reload_handler(new ProfilerReloadTuner(sc->profiler->rule.show,
+            sc->profiler->time.show));
 
     return true;
 }
diff --git a/src/profiler/profiler_nodes.cc b/src/profiler/profiler_nodes.cc
index e816b35b2..bf8e33b2a 100644
--- a/src/profiler/profiler_nodes.cc
+++ b/src/profiler/profiler_nodes.cc
@@ -46,7 +46,7 @@ struct GetProfileFunctor
     GetProfileFunctor(const std::string& name) : name(name) { }
 
     virtual ~GetProfileFunctor() = default;
-    virtual const ProfileStats* operator()() = 0;
+    virtual ProfileStats* operator()() = 0;
 
     const std::string name;
 };
@@ -56,10 +56,10 @@ struct GetProfileFromModule : public GetProfileFunctor
     GetProfileFromModule(const std::string& pn, Module* m) :
         GetProfileFunctor(pn), m(m) { }
 
-    const ProfileStats* operator()() override
+    ProfileStats* operator()() override
     {
         // const auto *ps = m->get_profiler_stats();
-        const auto *ps = m->get_profile();
+        auto *ps = m->get_profile();
         if ( ps )
             return ps;
 
@@ -79,7 +79,7 @@ struct GetProfileFromFunction : public GetProfileFunctor
     GetProfileFromFunction(const std::string& pn, get_profile_stats_fn fn) :
         GetProfileFunctor(pn), fn(fn) { }
 
-    const ProfileStats* operator()() override
+    ProfileStats* operator()() override
     { return fn(name.c_str()); }
 
     get_profile_stats_fn fn;
@@ -108,7 +108,7 @@ void ProfilerNode::set(Module* m)
 void ProfilerNode::set(get_profile_stats_fn fn)
 { getter = std::make_shared<GetProfileFromFunction>(name, fn); }
 
-void ProfilerNode::accumulate()
+void ProfilerNode::accumulate(snort::ProfilerType type)
 {
     if ( is_set() )
     {
@@ -118,20 +118,48 @@ void ProfilerNode::accumulate()
             return;
 
         get_stats();
-        stats += *local_stats;
+
+        if ( type == snort::PROFILER_TYPE_TIME )
+            stats += local_stats->time;
+        else if ( type == snort::PROFILER_TYPE_MEMORY )
+            stats += local_stats->memory;
+        else
+            stats += *local_stats;
+    }
+}
+
+void ProfilerNode::reset(ProfilerType type)
+{ 
+    if ( is_set() )
+    {
+        auto* local_stats = (*getter)();
+
+        if ( !local_stats )
+            return;
+
+        if ( type == snort::PROFILER_TYPE_TIME )
+        {
+            stats.reset_time();
+            local_stats->reset_time();
+        }
+        else
+        {
+            stats.reset();
+            local_stats->reset();
+        }
     }
 }
 
 void ProfilerNodeMap::register_node(const std::string &n, const char* pn, Module* m)
 { setup_node(get_node(n), get_node(pn ? pn : ROOT_NODE), m); }
 
-void ProfilerNodeMap::accumulate_nodes()
+void ProfilerNodeMap::accumulate_nodes(ProfilerType type)
 {
     static std::mutex stats_mutex;
     std::lock_guard<std::mutex> lock(stats_mutex);
 
     for ( auto it = nodes.begin(); it != nodes.end(); ++it )
-        it->second.accumulate();
+        it->second.accumulate(type);
 }
 
 void ProfilerNodeMap::accumulate_flex()
@@ -142,12 +170,22 @@ void ProfilerNodeMap::accumulate_flex()
         it->second.accumulate();
 }
 
-void ProfilerNodeMap::reset_nodes()
+void ProfilerNodeMap::clear_flex()
 {
-    for ( auto it = nodes.begin(); it != nodes.end(); ++it )
+    auto it = nodes.find(FLEX_NODE);
+
+    if ( it != nodes.end() )
         it->second.reset();
 }
 
+void ProfilerNodeMap::reset_nodes(ProfilerType type)
+{
+    static std::mutex reset_mutex;
+    std::lock_guard<std::mutex> lock(reset_mutex);
+    for ( auto it = nodes.begin(); it != nodes.end(); ++it )
+        it->second.reset(type);
+}
+
 const ProfilerNode& ProfilerNodeMap::get_root()
 { return get_node(ROOT_NODE); }
 
diff --git a/src/profiler/profiler_nodes.h b/src/profiler/profiler_nodes.h
index 351d4b54d..44618ac87 100644
--- a/src/profiler/profiler_nodes.h
+++ b/src/profiler/profiler_nodes.h
@@ -47,7 +47,7 @@ public:
     { return bool(getter); }
 
     // thread local call
-    void accumulate();
+    void accumulate(snort::ProfilerType = snort::PROFILER_TYPE_BOTH);
 
     const snort::ProfileStats& get_stats() const
     { return stats; }
@@ -55,8 +55,7 @@ public:
     void set_stats(const snort::ProfileStats& ps)
     { stats = ps; }
 
-    void reset()
-    { stats.reset(); }
+    void reset(snort::ProfilerType = snort::PROFILER_TYPE_BOTH);
 
     void add_child(ProfilerNode* node)
     { children.emplace_back(node); }
@@ -91,9 +90,10 @@ public:
 
     void register_node(const std::string&, const char*, snort::Module*);
 
-    void accumulate_nodes();
+    void accumulate_nodes(snort::ProfilerType = snort::PROFILER_TYPE_BOTH);
     void accumulate_flex();
-    void reset_nodes();
+    void clear_flex();
+    void reset_nodes(snort::ProfilerType = snort::PROFILER_TYPE_BOTH);
 
     const ProfilerNode& get_root();
 
diff --git a/src/profiler/profiler_printer.h b/src/profiler/profiler_printer.h
index b1dc4e828..551188fba 100644
--- a/src/profiler/profiler_printer.h
+++ b/src/profiler/profiler_printer.h
@@ -32,6 +32,7 @@
 #include "profiler_stats_table.h"
 #include "profiler_tree_builder.h"
 
+class ControlConn;
 template<typename View>
 struct ProfilerSorter
 {
@@ -61,9 +62,10 @@ public:
     using Entry = typename ProfilerBuilder<View>::Entry;
     using Sorter = ProfilerSorter<View>;
     using PrintFn = std::function<void(StatsTable&, const View&)>;
+    using PrintTableFn = std::function<void(const char*)>;
 
-    ProfilerPrinter(const StatsTable::Field* fields, const PrintFn print, const Sorter& sort) :
-        fields(fields), print(print), sort(sort) { }
+    ProfilerPrinter(const StatsTable::Field* fields, const PrintFn print, const Sorter& sort,
+        const PrintTableFn print_t) : fields(fields), print(print), sort(sort), print_t(print_t){ }
 
     void print_table(const std::string& title, Entry& root, unsigned count, int max_depth = -1)
     {
@@ -91,7 +93,7 @@ public:
             table << StatsTable::HEADER;
         }
 
-        snort::LogMessage("%s", ss.str().c_str());
+        print_t(ss.str().c_str());
 
         print_recursive(root, root, 1, count, max_depth);
         print_row(root, root, 0, 0);
@@ -165,7 +167,7 @@ public:
             }
         }
 
-        snort::LogMessage("%s", ss.str().c_str());
+        print_t(ss.str().c_str());
     }
 
 private:
@@ -173,6 +175,7 @@ private:
     const PrintFn print;
     const Sorter& sort;
     float total = 0;
+    const PrintTableFn print_t;
 };
 
 #endif
diff --git a/src/profiler/time_profiler.cc b/src/profiler/time_profiler.cc
index 471cfb067..2a442019a 100644
--- a/src/profiler/time_profiler.cc
+++ b/src/profiler/time_profiler.cc
@@ -29,6 +29,7 @@
 #include "profiler_printer.h"
 #include "profiler_stats_table.h"
 #include "time_profiler_defs.h"
+#include "control/control.h"
 
 #ifdef UNIT_TEST
 #include "catch/snort_catch.h"
@@ -41,7 +42,7 @@ using namespace snort;
 // enabled is not in SnortConfig to avoid that ugly dependency
 // enabled is not in TimeContext because declaring it SO_PUBLIC made TimeContext visible
 // putting enabled in TimeProfilerStats seems to be the best solution
-bool TimeProfilerStats::enabled = false;
+THREAD_LOCAL bool TimeProfilerStats::enabled = false;
 
 namespace time_stats
 {
@@ -140,13 +141,28 @@ static void print_fn(StatsTable& t, const View& v)
     t << clock_usecs(TO_USECS(v.avg_check()));
 }
 
+struct s_print_table
+{
+    ControlConn* ctrlcon;
+
+    s_print_table(ControlConn* ctrlcon) : ctrlcon(ctrlcon) {}
+
+    void operator()(const char* l) const
+    { LogRespond(ctrlcon, "%s", l); }
+};
+
 } // namespace time_stats
 
 void show_time_profiler_stats(ProfilerNodeMap& nodes, const TimeProfilerConfig& config)
 {
-    if ( !config.show )
+    if ( !TimeProfilerStats::is_enabled() )
         return;
 
+    print_time_profiler_stats(nodes, config, nullptr);
+}
+
+void print_time_profiler_stats(ProfilerNodeMap& nodes, const TimeProfilerConfig& config, ControlConn* ctrlcon)
+{
     ProfilerBuilder<time_stats::View> builder(time_stats::include_fn);
     auto root = builder.build(nodes.get_root());
 
@@ -154,8 +170,9 @@ void show_time_profiler_stats(ProfilerNodeMap& nodes, const TimeProfilerConfig&
         return;
 
     const auto& sorter = time_stats::sorters[config.sort];
+    const auto& printer_t = time_stats::s_print_table(ctrlcon);
 
-    ProfilerPrinter<time_stats::View> printer(time_stats::fields, time_stats::print_fn, sorter);
+    ProfilerPrinter<time_stats::View> printer(time_stats::fields, time_stats::print_fn, sorter, printer_t);
     printer.print_table(s_time_table_title, root, config.count, config.max_depth);
 }
 
diff --git a/src/profiler/time_profiler.h b/src/profiler/time_profiler.h
index 71524fc13..64a698892 100644
--- a/src/profiler/time_profiler.h
+++ b/src/profiler/time_profiler.h
@@ -23,7 +23,9 @@
 
 class ProfilerNodeMap;
 struct TimeProfilerConfig;
+class ControlConn;
 
 void show_time_profiler_stats(ProfilerNodeMap&, const TimeProfilerConfig&);
+void print_time_profiler_stats(ProfilerNodeMap&, const TimeProfilerConfig&, ControlConn*);
 
 #endif
diff --git a/src/profiler/time_profiler_defs.h b/src/profiler/time_profiler_defs.h
index 6779ca5cf..0fcfb2859 100644
--- a/src/profiler/time_profiler_defs.h
+++ b/src/profiler/time_profiler_defs.h
@@ -47,7 +47,7 @@ struct SO_PUBLIC TimeProfilerStats
     hr_duration elapsed;
     uint64_t checks;
     mutable unsigned int ref_count;
-    static bool enabled;
+    static THREAD_LOCAL bool enabled;
 
     static void set_enabled(bool b)
     { enabled = b; }