Measure syscall timings in Interconnect KIKIMR-15192

x-ydb-stable-ref: b5a1b56ccae72d0629280e8a1247f041f9c72ce7

4 files changed, 18 insertions, 8 deletions

diff --git a/library/cpp/actors/interconnect/interconnect_counters.cpp b/library/cpp/actors/interconnect/interconnect_counters.cpp
index 224160d4b4f..7d05960393c 100644
--- a/library/cpp/actors/interconnect/interconnect_counters.cpp
+++ b/library/cpp/actors/interconnect/interconnect_counters.cpp
@@ -165,8 +165,9 @@ namespace {
             ++*SpuriousWriteWakeups;
         }
 
-        void IncSendSyscalls() override {
+        void IncSendSyscalls(ui64 ns) override {
             ++*SendSyscalls;
+            *SendSyscallsNs += ns;
         }
 
         void IncInflyLimitReach() override {
@@ -197,8 +198,9 @@ namespace {
             ++*ch.IncomingEvents;
         }
 
-        void IncRecvSyscalls() override {
+        void IncRecvSyscalls(ui64 ns) override {
             ++*RecvSyscalls;
+            *RecvSyscallsNs += ns;
         }
 
         void AddTotalBytesRead(ui64 value) override {
@@ -288,7 +290,9 @@ namespace {
             if (updateGlobal) {
                 OutputBuffersTotalSize = Counters->GetCounter("OutputBuffersTotalSize");
                 SendSyscalls = Counters->GetCounter("SendSyscalls", true);
+                SendSyscallsNs = Counters->GetCounter("SendSyscallsNs", true);
                 RecvSyscalls = Counters->GetCounter("RecvSyscalls", true);
+                RecvSyscallsNs = Counters->GetCounter("RecvSyscallsNs", true);
                 SpuriousReadWakeups = Counters->GetCounter("SpuriousReadWakeups", true);
                 UsefulReadWakeups = Counters->GetCounter("UsefulReadWakeups", true);
                 SpuriousWriteWakeups = Counters->GetCounter("SpuriousWriteWakeups", true);
@@ -323,8 +327,10 @@ namespace {
         NMonitoring::TDynamicCounters::TCounterPtr QueueUtilization;
         NMonitoring::TDynamicCounters::TCounterPtr SubscribersCount;
         NMonitoring::TDynamicCounters::TCounterPtr SendSyscalls;
+        NMonitoring::TDynamicCounters::TCounterPtr SendSyscallsNs;
         NMonitoring::TDynamicCounters::TCounterPtr ClockSkewMicrosec;
         NMonitoring::TDynamicCounters::TCounterPtr RecvSyscalls;
+        NMonitoring::TDynamicCounters::TCounterPtr RecvSyscallsNs;
         NMonitoring::TDynamicCounters::TCounterPtr UsefulReadWakeups;
         NMonitoring::TDynamicCounters::TCounterPtr SpuriousReadWakeups;
         NMonitoring::TDynamicCounters::TCounterPtr UsefulWriteWakeups;
@@ -480,7 +486,7 @@ namespace {
             SpuriousWriteWakeups_->Inc();
         }
 
-        void IncSendSyscalls() override {
+        void IncSendSyscalls(ui64 /*ns*/) override {
             SendSyscalls_->Inc();
         }
 
@@ -512,7 +518,7 @@ namespace {
             ch.IncomingEvents->Inc();
         }
 
-        void IncRecvSyscalls() override {
+        void IncRecvSyscalls(ui64 /*ns*/) override {
             RecvSyscalls_->Inc();
         }
 
diff --git a/library/cpp/actors/interconnect/interconnect_counters.h b/library/cpp/actors/interconnect/interconnect_counters.h
index e30f03a0bcc..e28288d996a 100644
--- a/library/cpp/actors/interconnect/interconnect_counters.h
+++ b/library/cpp/actors/interconnect/interconnect_counters.h
@@ -32,7 +32,7 @@ public:
     virtual void IncDisconnections() = 0;
     virtual void IncUsefulWriteWakeups() = 0;
     virtual void IncSpuriousWriteWakeups() = 0;
-    virtual void IncSendSyscalls() = 0;
+    virtual void IncSendSyscalls(ui64 ns) = 0;
     virtual void IncInflyLimitReach() = 0;
     virtual void IncDisconnectByReason(const TString& s) = 0;
     virtual void IncUsefulReadWakeups() = 0;
@@ -40,7 +40,7 @@ public:
     virtual void SetPeerInfo(const TString& name, const TString& dataCenterId) = 0;
     virtual void AddInputChannelsIncomingTraffic(ui16 channel, ui64 incomingTraffic) = 0;
     virtual void IncInputChannelsIncomingEvents(ui16 channel) = 0;
-    virtual void IncRecvSyscalls() = 0;
+    virtual void IncRecvSyscalls(ui64 ns) = 0;
     virtual void AddTotalBytesRead(ui64 value) = 0;
     virtual void UpdateLegacyPingTimeHist(ui64 value) = 0;
     virtual void UpdateOutputChannelTraffic(ui16 channel, ui64 value) = 0;
diff --git a/library/cpp/actors/interconnect/interconnect_tcp_input_session.cpp b/library/cpp/actors/interconnect/interconnect_tcp_input_session.cpp
index c7fca64c600..45b47ac63b1 100644
--- a/library/cpp/actors/interconnect/interconnect_tcp_input_session.cpp
+++ b/library/cpp/actors/interconnect/interconnect_tcp_input_session.cpp
@@ -354,12 +354,14 @@ namespace NActors {
         TString err;
         LWPROBE_IF_TOO_LONG(SlowICReadFromSocket, ms) {
             do {
+                const ui64 begin = GetCycleCountFast();
 #ifndef _win_
                 recvres = iovcnt == 1 ? Socket->Recv(iovec->iov_base, iovec->iov_len, &err) : Socket->ReadV(iovec, iovcnt);
 #else
                 recvres = Socket->Recv(iovec[0].iov_base, iovec[0].iov_len, &err);
 #endif
-                Metrics->IncRecvSyscalls();
+                const ui64 end = GetCycleCountFast();
+                Metrics->IncRecvSyscalls((end - begin) * 1'000'000 / GetCyclesPerMillisecond());
             } while (recvres == -EINTR);
         }
 
diff --git a/library/cpp/actors/interconnect/interconnect_tcp_session.cpp b/library/cpp/actors/interconnect/interconnect_tcp_session.cpp
index 2ded7f9f537..2a396512a03 100644
--- a/library/cpp/actors/interconnect/interconnect_tcp_session.cpp
+++ b/library/cpp/actors/interconnect/interconnect_tcp_session.cpp
@@ -586,12 +586,14 @@ namespace NActors {
                 TString err;
                 ssize_t r = 0;
                 do {
+                    const ui64 begin = GetCycleCountFast();
 #ifndef _win_
                     r = iovcnt == 1 ? Socket->Send(iovec[0].iov_base, iovec[0].iov_len, &err) : Socket->WriteV(iovec, iovcnt);
 #else
                     r = Socket->Send(iovec[0].iov_base, iovec[0].iov_len, &err);
 #endif
-                    Proxy->Metrics->IncSendSyscalls();
+                    const ui64 end = GetCycleCountFast();
+                    Proxy->Metrics->IncSendSyscalls((end - begin) * 1'000'000 / GetCyclesPerMillisecond());
                 } while (r == -EINTR);
 
                 LOG_DEBUG_IC_SESSION("ICS16", "written# %zd iovcnt# %d err# %s", r, iovcnt, err.data());