feat(perf): add logs to pinpoint performance issues

dom/src/dom/root_node.cc

@@ -67,9 +67,12 @@ void RootNode::RemoveEventListener(const std::string& name, uint64_t listener_id
 void RootNode::ReleaseResources() {}
 
 void RootNode::CreateDomNodes(std::vector<std::shared_ptr<DomInfo>>&& nodes) {
+    HP_PERF_LOG("CreateDomNodes Begin");
+
   for (const auto& interceptor : interceptors_) {
     interceptor->OnDomNodeCreate(nodes);
   }
+    HP_PERF_LOG("CreateDomNodes Interceptor callback done");
   std::vector<std::shared_ptr<DomNode>> nodes_to_create;
   for (const auto& node_info : nodes) {
     auto& node = node_info->dom_node;
@@ -85,6 +88,7 @@ void RootNode::CreateDomNodes(std::vector<std::shared_ptr<DomInfo>>&& nodes) {
     node->HandleEvent(event);
     OnDomNodeCreated(node);
   }
+    HP_PERF_LOG("CreateDomNodes Nodes created and finished callback");
   for (const auto& node : nodes_to_create) {
     node->SetRenderInfo({node->GetId(), node->GetPid(), node->GetSelfIndex()});
   }
@@ -94,6 +98,7 @@ void RootNode::CreateDomNodes(std::vector<std::shared_ptr<DomInfo>>&& nodes) {
   if (!nodes_to_create.empty()) {
     dom_operations_.push_back({DomOperation::Op::kOpCreate, nodes_to_create});
   }
+    HP_PERF_LOG("CreateDomNodes End");
 }
 
 void RootNode::UpdateDomNodes(std::vector<std::shared_ptr<DomInfo>>&& nodes) {
@@ -272,14 +277,21 @@ void RootNode::CallFunction(uint32_t id, const std::string& name, const DomArgum
 }
 
 void RootNode::SyncWithRenderManager(const std::shared_ptr<RenderManager>& render_manager) {
+  HP_PERF_LOG("RootNode::SyncWithRenderManager");
+  unsigned long cnt = dom_operations_.size();
   FlushDomOperations(render_manager);
+  HP_PERF_LOG("RootNode::FlushDomOperations Done, dom op count:%lld", cnt);
+  cnt = event_operations_.size();
   FlushEventOperations(render_manager);
+  HP_PERF_LOG("RootNode::FlushEventOperations Done, event op count:%d",cnt);
   DoAndFlushLayout(render_manager);
+  HP_PERF_LOG("RootNode::DoAndFlushLayout Done");
   auto dom_manager = dom_manager_.lock();
   if (dom_manager) {
     dom_manager->RecordDomEndTimePoint();
   }
   render_manager->EndBatch(GetWeakSelf());
+  HP_PERF_LOG("RootNode::SyncWithRenderManager End");
 }
 
 void RootNode::AddEvent(uint32_t id, const std::string& event_name) {
@@ -422,6 +434,7 @@ void RootNode::DoAndFlushLayout(const std::shared_ptr<RenderManager>& render_man
 
 void RootNode::FlushDomOperations(const std::shared_ptr<RenderManager>& render_manager) {
   for (auto& dom_operation : dom_operations_) {
+    HP_PERF_LOG("RootNode::FlushDomOperations dom_operation.op cnt:%lld", dom_operation.nodes.size());
     MarkLayoutNodeDirty(dom_operation.nodes);
     switch (dom_operation.op) {
       case DomOperation::Op::kOpCreate:

driver/js/src/modules/scene_builder_module.cc

@@ -1,4 +1,4 @@
-/*
+  /*
  *
  * Tencent is pleased to support the open source community by making
  * Hippy available.
@@ -27,6 +27,7 @@
 #include "driver/modules/scene_builder_module.h"
 #include "driver/modules/ui_manager_module.h"
 #include "driver/scope.h"
+#include "footstone/logging.h"
 #include "footstone/string_view.h"
 #include "footstone/string_view_utils.h"
 
@@ -419,12 +420,15 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       size_t argument_count,
       const std::shared_ptr<CtxValue> arguments[],
       std::shared_ptr<CtxValue>&) -> std::shared_ptr<CtxValue> {
+    HP_PERF_LOG("SceneBuilder.create()");
     auto scope = weak_scope.lock();
     if (!scope) {
+       HP_PERF_LOG("SceneBuilder.create() exit with error");
       return nullptr;
     }
     auto ret = HandleJsValue(scope->GetContext(), arguments[0], scope);
     SceneBuilder::Create(scope->GetDomManager(), scope->GetRootNode(), std::move(std::get<2>(ret)));
+    HP_PERF_LOG("SceneBuilder.create() End");
     return nullptr;
   };
   class_template.functions.emplace_back(std::move(create_func_def));
@@ -436,12 +440,16 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       size_t argument_count,
       const std::shared_ptr<CtxValue> arguments[],
       std::shared_ptr<CtxValue>&) -> std::shared_ptr<CtxValue> {
+    HP_PERF_LOG("SceneBuilder.update()");
     auto scope = weak_scope.lock();
     if (!scope) {
+      HP_PERF_LOG("SceneBuilder.update() exit with error");
       return nullptr;
     }
     auto ret = HandleJsValue(scope->GetContext(), arguments[0], scope);
     SceneBuilder::Update(scope->GetDomManager(), scope->GetRootNode(), std::move(std::get<2>(ret)));
+    HP_PERF_LOG("SceneBuilder.update() End");
+
     return nullptr;
   };
   class_template.functions.emplace_back(std::move(update_func_def));
@@ -452,8 +460,11 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
                                         const std::shared_ptr<CtxValue> arguments[],
                                         std::shared_ptr<CtxValue>&)
       -> std::shared_ptr<CtxValue> {
+    HP_PERF_LOG("SceneBuilder.move()");
+
     auto scope = weak_scope.lock();
     if (!scope) {
+    HP_PERF_LOG("SceneBuilder.move() exit with error");
       return nullptr;
     }
     auto weak_dom_manager = scope->GetDomManager();
@@ -469,11 +480,13 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
         auto node = context->CopyArrayElement(info, 0);
         auto id_tuple = GetNodeId(context, node);
         if (!std::get<0>(id_tuple)) {
+          HP_PERF_LOG("SceneBuilder.move() exit with error");
           return nullptr;
         }
 
         auto pid_tuple = GetNodePid(context, node);
         if (!std::get<0>(pid_tuple)) {
+          HP_PERF_LOG("SceneBuilder.move() exit with error");
           return nullptr;
         }
         if (length >= 2) {
@@ -489,6 +502,7 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       }
     }
     SceneBuilder::Move(weak_dom_manager, scope->GetRootNode(), std::move(dom_infos));
+    HP_PERF_LOG("SceneBuilder.move() End");
     return nullptr;
   };
   class_template.functions.emplace_back(std::move(move_func_def));
@@ -500,8 +514,11 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       size_t argument_count,
       const std::shared_ptr<CtxValue> arguments[],
       std::shared_ptr<CtxValue>&) -> std::shared_ptr<CtxValue> {
+    HP_PERF_LOG("SceneBuilder.delete()");
+
     auto scope = weak_scope.lock();
     if (!scope) {
+      HP_PERF_LOG("SceneBuilder.delete() exit with error");
       return nullptr;
     }
     auto nodes = arguments[0];
@@ -521,6 +538,8 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
 
         auto pid_tuple = GetNodePid(context, node);
         if (!std::get<0>(pid_tuple)) {
+          HP_PERF_LOG("SceneBuilder.delete() exit with error");
+
           return nullptr;
         }
         dom_infos.push_back(std::make_shared<DomInfo>(
@@ -532,6 +551,8 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       }
     }
     SceneBuilder::Delete(scope->GetDomManager(), scope->GetRootNode(), std::move(dom_infos));
+    HP_PERF_LOG("SceneBuilder.delete() End");
+
     return nullptr;
   };
   class_template.functions.emplace_back(std::move(delete_func_def));
@@ -543,14 +564,17 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       size_t argument_count,
       const std::shared_ptr<CtxValue> arguments[],
       std::shared_ptr<CtxValue>&) -> std::shared_ptr<CtxValue> {
+      HP_PERF_LOG("SceneBuilder.addEventListener()");
     auto scope = weak_scope.lock();
     if (!scope) {
+      HP_PERF_LOG("SceneBuilder.addEventListener() exit with error");
       return nullptr;
     }
     Scope::EventListenerInfo listener_info;
     HandleEventListenerInfo(scope->GetContext(), argument_count, arguments, listener_info);
     auto dom_listener_info = scope->AddListener(listener_info);
     SceneBuilder::AddEventListener(scope->GetDomManager(), scope->GetRootNode(), dom_listener_info);
+    HP_PERF_LOG("SceneBuilder.addEventListener() End");
     return nullptr;
   };
   class_template.functions.emplace_back(std::move(add_event_listener_def));
@@ -562,14 +586,18 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       size_t argument_count,
       const std::shared_ptr<CtxValue> arguments[],
       std::shared_ptr<CtxValue>&) -> std::shared_ptr<CtxValue> {
+      HP_PERF_LOG("SceneBuilder.removeEventListener()");
+
     auto scope = weak_scope.lock();
     if (!scope) {
+      HP_PERF_LOG("SceneBuilder.removeEventListener() exit with error");
       return nullptr;
     }
     Scope::EventListenerInfo listener_info;
     HandleEventListenerInfo(scope->GetContext(), argument_count, arguments, listener_info);
     auto dom_listener_info = scope->RemoveListener(listener_info);
     SceneBuilder::RemoveEventListener(scope->GetDomManager(), scope->GetRootNode(), dom_listener_info);
+    HP_PERF_LOG("SceneBuilder.removeEventListener() End");
     return nullptr;
   };
   class_template.functions.emplace_back(std::move(remove_event_listener_def));
@@ -582,11 +610,14 @@ std::shared_ptr<ClassTemplate<SceneBuilder>> RegisterSceneBuilder(const std::wea
       size_t argument_count,
       const std::shared_ptr<CtxValue> arguments[],
       std::shared_ptr<CtxValue>&) -> std::shared_ptr<CtxValue> {
+    HP_PERF_LOG("SceneBuilder.build()");
     auto scope = weak_scope.lock();
     if (!scope) {
+      HP_PERF_LOG("SceneBuilder.build() exit with error");
       return nullptr;
     }
     SceneBuilder::Build(scope->GetDomManager(), scope->GetRootNode());
+    HP_PERF_LOG("SceneBuilder.build() End");
     return nullptr;
   };
   class_template.functions.emplace_back(std::move(build_func_def));

driver/js/src/napi/jsc/jsc_ctx.cc

@@ -30,6 +30,7 @@
 #include "driver/vm/native_source_code.h"
 #include "driver/vm/jsc/jsc_vm.h"
 
+
 namespace hippy {
 inline namespace driver {
 inline namespace napi {
@@ -665,8 +666,8 @@ bool JSCCtx::IsObject(const std::shared_ptr<CtxValue>& value) {
 }
 
 string_view JSCCtx::CopyFunctionName(const std::shared_ptr<CtxValue>& function) {
-  FOOTSTONE_UNIMPLEMENTED();
-  return "";
+    FOOTSTONE_UNIMPLEMENTED();
+    return "";
 }
 
 bool JSCCtx::GetEntriesFromObject(const std::shared_ptr<CtxValue>& value,
@@ -892,25 +893,31 @@ std::shared_ptr<CtxValue> JSCCtx::CallFunction(const std::shared_ptr<CtxValue>&
                                                const std::shared_ptr<CtxValue> argv[]) {
   auto function_value = std::static_pointer_cast<JSCCtxValue>(function);
   JSValueRef exception = nullptr;
+  HP_PERF_LOG("JSCCtx::CallFunction");
   auto function_object = JSValueToObject(context_, function_value->value_, &exception);
   if (exception) {
     SetException(std::make_shared<JSCCtxValue>(context_, exception));
+      HP_PERF_LOG("JSCCtx::CallFunction End with exception");
+
     return nullptr;
   }
 
   auto receiver_value = std::static_pointer_cast<JSCCtxValue>(receiver);
   auto receiver_object = JSValueToObject(context_, receiver_value->value_, &exception);
   if (exception) {
     SetException(std::make_shared<JSCCtxValue>(context_, exception));
+      HP_PERF_LOG("JSCCtx::CallFunction End with exception");
     return nullptr;
   }
 
   if (argc <= 0) {
     auto ret_value_ref = JSObjectCallAsFunction(context_, function_object, receiver_object, 0, nullptr, &exception);
     if (exception) {
       SetException(std::make_shared<JSCCtxValue>(context_, exception));
+      HP_PERF_LOG("JSCCtx::CallFunction End with exception");
       return nullptr;
     }
+    HP_PERF_LOG("JSCCtx::CallFunction End with exception");
     return std::make_shared<JSCCtxValue>(context_, ret_value_ref);
   }
 
@@ -923,12 +930,15 @@ std::shared_ptr<CtxValue> JSCCtx::CallFunction(const std::shared_ptr<CtxValue>&
   auto ret_value_ref = JSObjectCallAsFunction(context_, function_object, receiver_object, argc, values, &exception);
   if (exception) {
     SetException(std::make_shared<JSCCtxValue>(context_, exception));
+    HP_PERF_LOG("JSCCtx::CallFunction End with exception");
     return nullptr;
   }
 
   if (!ret_value_ref) {
+    HP_PERF_LOG("JSCCtx::CallFunction End with exception");
     return nullptr;
   }
+  HP_PERF_LOG("JSCCtx::CallFunction End with exception");
 
   return std::make_shared<JSCCtxValue>(context_, ret_value_ref);
 }
@@ -1124,6 +1134,7 @@ std::shared_ptr<CtxValue> JSCCtx::RunScript(const string_view& data,
   if (StringViewUtils::IsEmpty(data)) {
     return nullptr;
   }
+  HP_PERF_LOG("JSCCtx::RunScript");
 
   JSStringRef js = JSCVM::CreateJSCString(data);
   JSValueRef exception = nullptr;
@@ -1139,13 +1150,15 @@ std::shared_ptr<CtxValue> JSCCtx::RunScript(const string_view& data,
 
   if (exception) {
     SetException(std::make_shared<JSCCtxValue>(context_, exception));
+    HP_PERF_LOG("JSCCtx::RunScript Error");
     return nullptr;
   }
 
   if (!value) {
+    HP_PERF_LOG("JSCCtx::RunScript Error");
     return nullptr;
   }
-
+  HP_PERF_LOG("JSCCtx::RunScript End");
   return std::make_shared<JSCCtxValue>(context_, value);
 }
 

modules/footstone/include/footstone/logging.h

@@ -20,6 +20,8 @@
 
 #pragma once
 
+#if defined(__cplusplus)
+
 #include <cassert>
 #include <codecvt>
 #include <mutex>
@@ -105,7 +107,29 @@ class LogMessage {
     }
     delegate_ = delegate;
   }
-
+  inline static void LogWithFormat(const char * file, int line, const char *format, ...){
+    char *log_msg = NULL;
+    va_list args;
+    va_start(args, format);
+    int ret = vasprintf(&log_msg, format, args);
+    va_end(args);
+
+    if (ret <= 0 && log_msg == NULL) {
+        return;
+    }
+
+    std::ostringstream s;
+    s<<"thread:"<<pthread_self()<<", "<<log_msg<<std::endl;
+
+    if (LogMessage::delegate_) {
+      delegate_(s, TDF_LOG_WARNING);
+    } else {
+      default_delegate_(s, TDF_LOG_WARNING);
+    }
+
+    free(log_msg);
+  }
+
   std::ostringstream& stream() { return stream_; }
 
  private:
@@ -186,3 +210,19 @@ bool ShouldCreateLogMessage(LogSeverity severity);
   do {                      \
     (void)(expr);           \
   } while (0)
+
+#endif
+
+inline void HPDoPerfLog( const char* file, int line, const char *format, ...){
+    va_list args;
+    va_start(args, format);
+    footstone::LogMessage::LogWithFormat(file, line, format, args);
+    va_end(args);
+}
+
+void HPDoPerfLog( const char *, int, const char *format, ...);
+#define HP_PERF_LOG(format, ...) \
+  HPDoPerfLog(__FILE_NAME__, __LINE__, "[HP PERF]"                      \
+        " " format,                                    \
+         ##__VA_ARGS__)
+

modules/footstone/src/platform/ios/logging.cc

@@ -90,6 +90,8 @@ LogMessage::~LogMessage() {
   }
 }
 
+
+
 int GetVlogVerbosity() { return std::max(-1, LOG_INFO - GetMinLogLevel()); }
 
 bool ShouldCreateLogMessage(LogSeverity severity) { return severity >= GetMinLogLevel(); }

modules/ios/base/HPLog.h

@@ -19,6 +19,7 @@
  * See the License for the specific language governing permissions and
  * limitations under the License.
  */
+# if defined(__OBJC__)
 
 #import <Foundation/Foundation.h>
 
@@ -134,3 +135,4 @@ HP_EXTERN void HPPerformBlockWithLogPrefix(void (^block)(void), NSString *prefix
 
 HP_EXTERN void HPLogNativeInternal(HPLogLevel, const char *, int, NSDictionary *, NSString *, ...) NS_FORMAT_FUNCTION(5, 6);
 
+#endif // defined(__OBJC__)