Print trace information regarding IPC delay

This patch adds Tracer class for priting debug information.

Change-Id: Ia1439e7d86b94e9a03f377f3d372eeb7b8eec565
Signed-off-by: Hwankyu Jhun <h.jhun@samsung.com>

diff --git a/src/rpc-port/accepted-port-internal.cc b/src/rpc-port/accepted-port-internal.cc
index 8306fa3b1a896ea575979c663d55eff97f0ef001..838378dabf90e5faa49a27ad53ec9329188cd3bb 100644 (file)
--- a/src/rpc-port/accepted-port-internal.cc
+++ b/src/rpc-port/accepted-port-internal.cc
@@ -27,15 +27,15 @@
 namespace rpc_port {
 namespace internal {
 
-AcceptedPort::AcceptedPort(int read_fd, int write_fd, std::string id,
+AcceptedPort::AcceptedPort(int read_fd, int write_fd, pid_t pid, std::string id,
                            std::string inst, IEvent* listener, bool is_delegate)
-    : Port(read_fd, write_fd, std::move(id), std::move(inst)),
+    : Port(read_fd, write_fd, pid, std::move(id), std::move(inst)),
       listener_(listener),
       is_delegate_(is_delegate) {}
 
-AcceptedPort::AcceptedPort(int read_fd, int write_fd, std::string id,
+AcceptedPort::AcceptedPort(int read_fd, int write_fd, pid_t pid, std::string id,
                            IEvent* listener, bool is_delegate)
-    : Port(read_fd, write_fd, std::move(id)),
+    : Port(read_fd, write_fd, pid, std::move(id)),
       listener_(listener),
       is_delegate_(is_delegate) {}
 

diff --git a/src/rpc-port/accepted-port-internal.hh b/src/rpc-port/accepted-port-internal.hh
index 89cd5962f266ad2a573adcf5b52ee46d17bd47da..cc77055727189bdfeeee5067e4b4baaf748dcc47 100644 (file)
--- a/src/rpc-port/accepted-port-internal.hh
+++ b/src/rpc-port/accepted-port-internal.hh
@@ -35,10 +35,10 @@ class AcceptedPort : public Port {
     virtual void OnSocketDisconnected(int fd) = 0;
   };
 
-  AcceptedPort(int read_fd, int write_fd, std::string id, std::string inst,
+  AcceptedPort(int read_fd, int write_fd, pid_t pid, std::string id,
+               std::string inst, IEvent* listener, bool is_delegate);
+  AcceptedPort(int read_fd, int write_fd, pid_t pid, std::string id,
                IEvent* listener, bool is_delegate);
-  AcceptedPort(int read_fd, int write_fd, std::string id, IEvent* listener,
-               bool is_delegate);
   virtual ~AcceptedPort();
 
   bool IsDelegate() const;

diff --git a/src/rpc-port/debug-port-internal.cc b/src/rpc-port/debug-port-internal.cc
index ad21a70c66660332fd888fa2708c0f62fefb697e..f94417e58bbdbae856ddc0f0855252e0b5ef608c 100644 (file)
--- a/src/rpc-port/debug-port-internal.cc
+++ b/src/rpc-port/debug-port-internal.cc
@@ -223,7 +223,7 @@ void DebugPortImpl::Init() {
     int fd = Connect();
     if (fd < 0) break;
 
-    port_.reset(new Port(-1, fd, "Debug"));
+    port_.reset(new Port(-1, fd, -1, "Debug"));
     if (Watch(fd) < 0) break;
 
     SetConnectionStatus(true);
@@ -351,7 +351,7 @@ int DebugPortImpl::AppComCb(const char* endpoint, aul_app_com_result_e result,
     if (fd < 0) return -1;
 
     std::lock_guard<std::recursive_mutex> lock(handle->GetMutex());
-    handle->port_.reset(new Port(-1, fd, "Debug"));
+    handle->port_.reset(new Port(-1, fd, -1, "Debug"));
     int ret = handle->Watch(fd);
     if (ret < 0) return -1;
 

diff --git a/src/rpc-port/port-internal.cc b/src/rpc-port/port-internal.cc
index 4fc3ed359521057a8bbcf3be74c527c4aa922693..df33007d1fb78118d5c909076d714706a0cd592a 100644 (file)
--- a/src/rpc-port/port-internal.cc
+++ b/src/rpc-port/port-internal.cc
@@ -52,9 +52,10 @@ enum PortStatus {
 
 }  // namespace
 
-Port::Port(int read_fd, int write_fd, std::string id)
+Port::Port(int read_fd, int write_fd, pid_t pid, std::string id)
     : read_fd_(read_fd),
       write_fd_(write_fd),
+      pid_(pid),
       id_(std::move(id)),
       instance_(""),
       seq_(0) {
@@ -66,9 +67,11 @@ Port::Port(int read_fd, int write_fd, std::string id)
   if (read_fd > -1) SetReceiveTimeout(-1);
 }
 
-Port::Port(int read_fd, int write_fd, std::string id, std::string instance)
+Port::Port(int read_fd, int write_fd, pid_t pid, std::string id,
+           std::string instance)
     : read_fd_(read_fd),
       write_fd_(write_fd),
+      pid_(pid),
       id_(std::move(id)),
       instance_(std::move(instance)),
       seq_(0) {
@@ -313,6 +316,8 @@ const std::string& Port::GetInstance() const { return instance_; }
 
 uint32_t Port::GetSeq() { return ++seq_; }
 
+pid_t Port::GetPid() const { return pid_; }
+
 // LCOV_EXCL_START
 gboolean Port::UnixFdSourceFunc(gint fd, GIOCondition condition,
                                 gpointer data) {

diff --git a/src/rpc-port/port-internal.hh b/src/rpc-port/port-internal.hh
index 24cbf85fca96d80e3dbf6b54c05eb5ed8ac40b2e..49fe70551de8e3fc7fe8cc1be3c8140d541af70d 100644 (file)
--- a/src/rpc-port/port-internal.hh
+++ b/src/rpc-port/port-internal.hh
@@ -36,8 +36,9 @@ namespace internal {
 
 class Port : public std::enable_shared_from_this<Port> {
  public:
-  Port(int read_fd, int write_fd, std::string id, std::string instance);
-  Port(int read_fd, int write_fd, std::string id);
+  Port(int read_fd, int write_fd, pid_t pid, std::string id,
+       std::string instance);
+  Port(int read_fd, int write_fd, pid_t pid, std::string id);
   virtual ~Port();
 
   virtual void Disconnect();
@@ -58,6 +59,7 @@ class Port : public std::enable_shared_from_this<Port> {
   std::recursive_mutex& GetWriteMutex() const;
   const std::string& GetInstance() const;
   uint32_t GetSeq();
+  pid_t GetPid() const;
 
  private:
   // LCOV_EXCL_START
@@ -75,6 +77,7 @@ class Port : public std::enable_shared_from_this<Port> {
  private:
   int read_fd_;
   int write_fd_;
+  pid_t pid_;
   std::string id_;
   std::string instance_;
   std::atomic<uint32_t> seq_;

diff --git a/src/rpc-port/proxy-internal.cc b/src/rpc-port/proxy-internal.cc
index 2925d489ea6d717930472d81f1f939844ae76ad9..eed4169c537c5745e4cce6133ff9230eac69abd1 100644 (file)
--- a/src/rpc-port/proxy-internal.cc
+++ b/src/rpc-port/proxy-internal.cc
@@ -32,6 +32,7 @@
 #include "rpc-port/exception-internal.hh"
 #include "rpc-port/glib-internal.hh"
 #include "rpc-port/log-private.hh"
+#include "rpc-port/peer-cred-internal.hh"
 #include "rpc-port/request-internal.hh"
 #include "rpc-port/response-internal.hh"
 
@@ -132,12 +133,16 @@ int Proxy::Connect(bool sync) {
                             &delegate_client_[1]);
   if (ret != RPC_PORT_ERROR_NONE) return ret;
 
+  auto peer_cred =
+      std::unique_ptr<PeerCred>(PeerCred::Get(main_client_[0]->GetFd()));
+  pid_ = peer_cred->GetPid();
+  _D("pid=%d", pid_);
   if (sync) {
     main_port_.reset(new ProxyPort(main_client_[0]->RemoveFd(),
-                                   main_client_[1]->RemoveFd(), target_appid_,
-                                   this, false));
+                                   main_client_[1]->RemoveFd(), pid_,
+                                   target_appid_, this, false));
     delegate_port_.reset(new ProxyPort(delegate_client_[0]->RemoveFd(),
-                                       delegate_client_[1]->RemoveFd(),
+                                       delegate_client_[1]->RemoveFd(), pid_,
                                        target_appid_, this));
     DebugPort::AddSession(port_name_, main_port_, delegate_port_);
     listener_->OnConnected(target_appid_, main_port_.get());
@@ -628,7 +633,7 @@ std::unique_ptr<ClientChannel> Proxy::GetClient(int fd, bool* is_read,
 void Proxy::SetPort(int fd, bool is_read, bool is_delegate) {
   if (is_delegate) {
     if (!delegate_port_)
-      delegate_port_.reset(new ProxyPort(-1, -1, target_appid_, this));
+      delegate_port_.reset(new ProxyPort(-1, -1, pid_, target_appid_, this));
 
     if (is_read) {
       _W("[DELEGATE] read_fd=%d", fd);
@@ -639,7 +644,7 @@ void Proxy::SetPort(int fd, bool is_read, bool is_delegate) {
     }
   } else {
     if (!main_port_)
-      main_port_.reset(new ProxyPort(-1, -1, target_appid_, this, false));
+      main_port_.reset(new ProxyPort(-1, -1, pid_, target_appid_, this, false));
 
     if (is_read) {
       _W("[MAIN] read_fd=%d", fd);
@@ -653,9 +658,9 @@ void Proxy::SetPort(int fd, bool is_read, bool is_delegate) {
   if (main_port_ && main_port_->GetReadFd() > 0 &&
       main_port_->GetWriteFd() > 0 && delegate_port_ &&
       delegate_port_->GetReadFd() > 0 && delegate_port_->GetWriteFd() > 0) {
-    _W("[CONNECTED] target_appid=%s, port_name=%s, main_fd=%d:%d, "
+    _W("[CONNECTED] target=%s(%d), port_name=%s, main_fd=%d:%d, "
        "delegate_fd=%d:%d",
-       target_appid_.c_str(), port_name_.c_str(), main_port_->GetReadFd(),
+       target_appid_.c_str(), pid_, port_name_.c_str(), main_port_->GetReadFd(),
        main_port_->GetWriteFd(), delegate_port_->GetReadFd(),
        delegate_port_->GetWriteFd());
     DebugPort::AddSession(port_name_, main_port_, delegate_port_);

diff --git a/src/rpc-port/proxy-internal.hh b/src/rpc-port/proxy-internal.hh
index 4543be5284d0716a5035d2ce6b19ba0b328add6b..9ec8b578cc43c9a3243f075de7ba8a4e209b6a92 100644 (file)
--- a/src/rpc-port/proxy-internal.hh
+++ b/src/rpc-port/proxy-internal.hh
@@ -94,6 +94,7 @@ class Proxy : public std::enable_shared_from_this<Proxy>,
  private:
   std::string port_name_;
   std::string port_path_;
+  pid_t pid_ = -1;
   std::shared_ptr<ProxyPort> main_port_;
   std::shared_ptr<ProxyPort> delegate_port_;
   IEventListener* listener_ = nullptr;

diff --git a/src/rpc-port/proxy-port-internal.cc b/src/rpc-port/proxy-port-internal.cc
index a93a0d8a993f53608fcfff1a60825780b8d00ad2..af5179a79c6834d33c98af87c65d206ed656a454 100644 (file)
--- a/src/rpc-port/proxy-port-internal.cc
+++ b/src/rpc-port/proxy-port-internal.cc
@@ -26,9 +26,9 @@
 namespace rpc_port {
 namespace internal {
 
-ProxyPort::ProxyPort(int read_fd, int write_fd, std::string id,
+ProxyPort::ProxyPort(int read_fd, int write_fd, pid_t pid, std::string id,
                      IEvent* listener, bool is_delegate)
-    : Port(read_fd, write_fd, std::move(id)),
+    : Port(read_fd, write_fd, pid, std::move(id)),
       listener_(listener),
       is_delegate_(is_delegate) {
   if (read_fd > -1)

diff --git a/src/rpc-port/proxy-port-internal.hh b/src/rpc-port/proxy-port-internal.hh
index e7a47b1386c418f3f1d050428c80d7a7782d0a76..e78bbba401b9798ee1acf9bb58f07177be0538ee 100644 (file)
--- a/src/rpc-port/proxy-port-internal.hh
+++ b/src/rpc-port/proxy-port-internal.hh
@@ -18,6 +18,8 @@
 #define PROXY_PORT_INTERNAL_HH_
 
 #include <glib.h>
+#include <sys/types.h>
+#include <unistd.h>
 
 #include <string>
 
@@ -35,8 +37,8 @@ class ProxyPort : public Port {
     virtual void OnSocketDisconnected(int fd) = 0;
   };
 
-  ProxyPort(int read_fd, int write_fd, std::string id, IEvent* listener,
-            bool is_delegate = true);
+  ProxyPort(int read_fd, int write_fd, pid_t pid, std::string id,
+            IEvent* listener, bool is_delegate = true);
   virtual ~ProxyPort();
 
   bool IsDelegate() const;

diff --git a/src/rpc-port/rpc-port-parcel.cc b/src/rpc-port/rpc-port-parcel.cc
index eab50f55a94238c5ef361e462feca3740a4aa69e..721cc7c7ba7d5799b1e72f7408aaf87699200362 100644 (file)
--- a/src/rpc-port/rpc-port-parcel.cc
+++ b/src/rpc-port/rpc-port-parcel.cc
@@ -26,6 +26,7 @@
 #include "log-private.hh"
 #include "parcel-internal.hh"
 #include "port-internal.hh"
+#include "tracer-internal.hh"
 
 #define MAX_PARCEL_SIZE (1024 * 1024 * 10)
 
@@ -54,6 +55,7 @@ static int __rpc_port_parcel_create_from_port(rpc_port_parcel_h* h,
 
   internal::Port* pt = static_cast<internal::Port*>(port);
   {
+    internal::Tracer tracer(pt->GetPid(), pt->GetId(), __FUNCTION__);
     std::lock_guard<std::recursive_mutex> lock(pt->GetReadMutex());
     int ret = rpc_port_read(port, &len, 4);
     if (ret != 0) return ret;
@@ -110,6 +112,7 @@ RPC_API int rpc_port_parcel_send(rpc_port_parcel_h h, rpc_port_h port) {
 
   internal::Port* pt = static_cast<internal::Port*>(port);
   {
+    internal::Tracer tracer(pt->GetPid(), pt->GetId(), __FUNCTION__);
     std::lock_guard<std::recursive_mutex> lock(pt->GetWriteMutex());
     int ret = rpc_port_write(port, &len, sizeof(len));
     if (ret != 0) return ret;

diff --git a/src/rpc-port/rpc-port.cc b/src/rpc-port/rpc-port.cc
index 0e8fdd7540a7b9e3a9c67faf11947f50dda719f3..e80ed30ade4e994e3b609c01ec3394d93a4f6640 100644 (file)
--- a/src/rpc-port/rpc-port.cc
+++ b/src/rpc-port/rpc-port.cc
@@ -30,6 +30,7 @@
 #include "port-internal.hh"
 #include "proxy-internal.hh"
 #include "stub-internal.hh"
+#include "tracer-internal.hh"
 
 #undef RPC_API
 #define RPC_API extern "C" __attribute__((visibility("default")))
@@ -338,6 +339,7 @@ RPC_API int rpc_port_proxy_connect(rpc_port_proxy_h h, const char* appid,
   if (h == nullptr || appid == nullptr || port == nullptr)
     return RPC_PORT_ERROR_INVALID_PARAMETER;
 
+  rpc_port::internal::Tracer tracer(-1, appid, __FUNCTION__);
   auto p = static_cast<std::shared_ptr<::ProxyExt>*>(h);
   auto* proxy = p->get();
   _W("rpc_port_proxy_connect(%p, %s, %s)", proxy, appid, port);
@@ -351,6 +353,7 @@ RPC_API int rpc_port_proxy_connect_sync(rpc_port_proxy_h h, const char* appid,
   if (h == nullptr || appid == nullptr || port == nullptr)
     return RPC_PORT_ERROR_INVALID_PARAMETER;
 
+  rpc_port::internal::Tracer tracer(-1, appid, __FUNCTION__);
   auto p = static_cast<std::shared_ptr<::ProxyExt>*>(h);
   auto* proxy = p->get();
   _W("rpc_port_proxy_connect(%p, %s, %s)", proxy, appid, port);
@@ -489,6 +492,7 @@ RPC_API int rpc_port_stub_listen(rpc_port_stub_h h) {
     return RPC_PORT_ERROR_INVALID_PARAMETER;
 
   _W("rpc_port_stub_listen(%p)", h);
+  rpc_port::internal::Tracer tracer(-1, "amd", __FUNCTION__);
   auto p = static_cast<::StubExt*>(h);
   std::lock_guard<std::recursive_mutex> lock(p->GetMutex());
 

diff --git a/src/rpc-port/stub-internal.cc b/src/rpc-port/stub-internal.cc
index fa32935e6ea918045def797982465aed3ffe8f02..879638ea67cf26d8c56a0c09d191f2ce38333440 100644 (file)
--- a/src/rpc-port/stub-internal.cc
+++ b/src/rpc-port/stub-internal.cc
@@ -260,17 +260,18 @@ void Stub::OnSocketDisconnected(gint fd) {
 }
 
 void Stub::AddAcceptedPort(const std::string& sender_appid,
-    const std::string& instance, const std::string& port_type, int fd) {
+                           const std::string& instance,
+                           const std::string& port_type, int fd, pid_t pid) {
   std::lock_guard<std::recursive_mutex> lock(GetMutex());
   if (port_type == kPortTypeMainWrite) {
     ports_.emplace_back(
-        new AcceptedPort(-1, fd, sender_appid, instance, this, false));
+        new AcceptedPort(-1, fd, pid, sender_appid, instance, this, false));
   } else if (port_type == kPortTypeMainRead) {
     auto port = FindPort(instance);
     if (port) port->SetReadFd(fd);
   } else if (port_type == kPortTypeDelegateWrite) {
     ports_.emplace_back(
-        new AcceptedPort(-1, fd, sender_appid, instance, this, true));
+        new AcceptedPort(-1, fd, pid, sender_appid, instance, this, true));
   } else if (port_type == kPortTypeDelegateRead) {
     auto port = FindDelegatePort(instance);
     if (port) port->SetReadFd(fd);
@@ -326,7 +327,7 @@ void Stub::CheckPermission(const std::shared_ptr<Request>& request,
     client->SetNonblock();
     int client_fd = client->RemoveFd();
     AddAcceptedPort(app_id, request->GetInstance(), request->GetPortType(),
-                    client_fd);
+                    client_fd, cred->GetPid());
   };
 
   int res;

diff --git a/src/rpc-port/stub-internal.hh b/src/rpc-port/stub-internal.hh
index af15f68916efd54f6845974a3a8625fb26ba9465..e6100d1f51cc4412e516e1153a46e6607945a6b8 100644 (file)
--- a/src/rpc-port/stub-internal.hh
+++ b/src/rpc-port/stub-internal.hh
@@ -66,7 +66,8 @@ class Stub : public Server::IEvent, public AcceptedPort::IEvent {
 
  private:
   void AddAcceptedPort(const std::string& sender_appid,
-      const std::string& instance, const std::string& port_type, int fd);
+                       const std::string& instance,
+                       const std::string& port_type, int fd, pid_t pid);
   void RemoveAcceptedPorts(std::string instance);
   std::recursive_mutex& GetMutex() const;
   int GetFdFromSystemd();

diff --git a/src/rpc-port/tracer-internal.cc b/src/rpc-port/tracer-internal.cc
new file mode 100644 (file)
index 0000000..7fd21e4
--- /dev/null
+++ b/src/rpc-port/tracer-internal.cc
@@ -0,0 +1,52 @@
+/*
+ * Copyright (c) 2017 - 2021 Samsung Electronics Co., Ltd.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include "rpc-port/tracer-internal.hh"
+
+#include <dlog.h>
+#include <sys/types.h>
+#include <unistd.h>
+
+#include <utility>
+
+namespace rpc_port {
+namespace internal {
+
+Tracer::Tracer(pid_t dest_pid, std::string dest, std::string func)
+    : dest_pid_(dest_pid),
+      dest_(std::move(dest)),
+      func_(std::move(func)),
+      start_(std::chrono::steady_clock::now()) {}
+
+Tracer::~Tracer() {
+  auto end = std::chrono::steady_clock::now();
+  std::chrono::duration<double> elapsed_time = end - start_;
+  if (elapsed_time.count() > 0.1f) {
+    auto start_time = std::chrono::duration_cast<std::chrono::duration<double>>(
+                          start_.time_since_epoch())
+                          .count();
+    auto end_time = std::chrono::duration_cast<std::chrono::duration<double>>(
+                        end.time_since_epoch())
+                        .count();
+    dlog_print(DLOG_INFO, "VTRACE",
+               "[%s]:Took:%.3f s:[%.3f~%.3f]:S[%d]:D[%d:%s]", func_.c_str(),
+               elapsed_time.count(), start_time, end_time, gettid(), dest_pid_,
+               dest_.c_str());
+  }
+}
+
+}  // namespace internal
+}  // namespace rpc_port

diff --git a/src/rpc-port/tracer-internal.hh b/src/rpc-port/tracer-internal.hh
new file mode 100644 (file)
index 0000000..f451e55
--- /dev/null
+++ b/src/rpc-port/tracer-internal.hh
@@ -0,0 +1,43 @@
+/*
+ * Copyright (c) 2017 - 2021 Samsung Electronics Co., Ltd.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef TRACER_INTERNAL_HH_
+#define TRACER_INTERNAL_HH_
+
+#include <unistd.h>
+
+#include <chrono>
+#include <string>
+
+namespace rpc_port {
+namespace internal {
+
+class Tracer {
+ public:
+  explicit Tracer(pid_t dest_pid, std::string dest, std::string func);
+  ~Tracer();
+
+ private:
+  pid_t dest_pid_;
+  std::string dest_;
+  std::string func_;
+  std::chrono::time_point<std::chrono::steady_clock> start_;
+};
+
+}  // namespace internal
+}  // namespace rpc_port
+
+#endif  // TRACER_INTERNAL_HH_