From cebf113d7b671d9c68fa9be62413b552f591fa70 Mon Sep 17 00:00:00 2001 From: Ruifan Yuan Date: Thu, 7 Sep 2023 16:06:38 +0800 Subject: [PATCH] feat(perf): add logs to pinpoint performance issues --- dom/src/dom/root_node.cc | 13 ++++++ driver/js/src/modules/scene_builder_module.cc | 33 ++++++++++++++- driver/js/src/napi/jsc/jsc_ctx.cc | 19 +++++++-- modules/footstone/include/footstone/logging.h | 42 ++++++++++++++++++- modules/footstone/src/platform/ios/logging.cc | 2 + modules/ios/base/HPLog.h | 2 + .../native/ios/renderer/NativeRenderImpl.mm | 11 +++++ .../ios/renderer/NativeRenderManager.mm | 11 ++++- 8 files changed, 126 insertions(+), 7 deletions(-) diff --git a/dom/src/dom/root_node.cc b/dom/src/dom/root_node.cc index 4963c0f2bbf..bdf778bb64f 100644 --- a/dom/src/dom/root_node.cc +++ b/dom/src/dom/root_node.cc @@ -69,9 +69,12 @@ void RootNode::ReleaseResources() { } void RootNode::CreateDomNodes(std::vector>&& nodes) { + HP_PERF_LOG("CreateDomNodes Begin"); + for (const auto& interceptor : interceptors_) { interceptor->OnDomNodeCreate(nodes); } + HP_PERF_LOG("CreateDomNodes Interceptor callback done"); std::vector> nodes_to_create; for (const auto& node_info : nodes) { auto& node = node_info->dom_node; @@ -87,6 +90,7 @@ void RootNode::CreateDomNodes(std::vector>&& 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()}); } @@ -96,6 +100,7 @@ void RootNode::CreateDomNodes(std::vector>&& 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>&& nodes) { @@ -274,14 +279,21 @@ void RootNode::CallFunction(uint32_t id, const std::string& name, const DomArgum } void RootNode::SyncWithRenderManager(const std::shared_ptr& 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) { @@ -424,6 +436,7 @@ void RootNode::DoAndFlushLayout(const std::shared_ptr& render_man void RootNode::FlushDomOperations(const std::shared_ptr& 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: diff --git a/driver/js/src/modules/scene_builder_module.cc b/driver/js/src/modules/scene_builder_module.cc index 27a8f6bfb6f..07468ce1d25 100644 --- a/driver/js/src/modules/scene_builder_module.cc +++ b/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> RegisterSceneBuilder(const std::wea size_t argument_count, const std::shared_ptr arguments[], std::shared_ptr&) -> std::shared_ptr { + 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> RegisterSceneBuilder(const std::wea size_t argument_count, const std::shared_ptr arguments[], std::shared_ptr&) -> std::shared_ptr { + 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> RegisterSceneBuilder(const std::wea const std::shared_ptr arguments[], std::shared_ptr&) -> std::shared_ptr { + 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> 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> 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> RegisterSceneBuilder(const std::wea size_t argument_count, const std::shared_ptr arguments[], std::shared_ptr&) -> std::shared_ptr { + 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> 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( @@ -532,6 +551,8 @@ std::shared_ptr> 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> RegisterSceneBuilder(const std::wea size_t argument_count, const std::shared_ptr arguments[], std::shared_ptr&) -> std::shared_ptr { + 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> RegisterSceneBuilder(const std::wea size_t argument_count, const std::shared_ptr arguments[], std::shared_ptr&) -> std::shared_ptr { + 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> RegisterSceneBuilder(const std::wea size_t argument_count, const std::shared_ptr arguments[], std::shared_ptr&) -> std::shared_ptr { + 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)); diff --git a/driver/js/src/napi/jsc/jsc_ctx.cc b/driver/js/src/napi/jsc/jsc_ctx.cc index de1dff41291..4d58c8a0482 100644 --- a/driver/js/src/napi/jsc/jsc_ctx.cc +++ b/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& value) { } string_view JSCCtx::CopyFunctionName(const std::shared_ptr& function) { - FOOTSTONE_UNIMPLEMENTED(); - return ""; + FOOTSTONE_UNIMPLEMENTED(); + return ""; } bool JSCCtx::GetEntriesFromObject(const std::shared_ptr& value, @@ -892,9 +893,12 @@ std::shared_ptr JSCCtx::CallFunction(const std::shared_ptr& const std::shared_ptr argv[]) { auto function_value = std::static_pointer_cast(function); JSValueRef exception = nullptr; + HP_PERF_LOG("JSCCtx::CallFunction"); auto function_object = JSValueToObject(context_, function_value->value_, &exception); if (exception) { SetException(std::make_shared(context_, exception)); + HP_PERF_LOG("JSCCtx::CallFunction End with exception"); + return nullptr; } @@ -902,6 +906,7 @@ std::shared_ptr JSCCtx::CallFunction(const std::shared_ptr& auto receiver_object = JSValueToObject(context_, receiver_value->value_, &exception); if (exception) { SetException(std::make_shared(context_, exception)); + HP_PERF_LOG("JSCCtx::CallFunction End with exception"); return nullptr; } @@ -909,8 +914,10 @@ std::shared_ptr JSCCtx::CallFunction(const std::shared_ptr& auto ret_value_ref = JSObjectCallAsFunction(context_, function_object, receiver_object, 0, nullptr, &exception); if (exception) { SetException(std::make_shared(context_, exception)); + HP_PERF_LOG("JSCCtx::CallFunction End with exception"); return nullptr; } + HP_PERF_LOG("JSCCtx::CallFunction End with exception"); return std::make_shared(context_, ret_value_ref); } @@ -923,12 +930,15 @@ std::shared_ptr JSCCtx::CallFunction(const std::shared_ptr& auto ret_value_ref = JSObjectCallAsFunction(context_, function_object, receiver_object, argc, values, &exception); if (exception) { SetException(std::make_shared(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(context_, ret_value_ref); } @@ -1124,6 +1134,7 @@ std::shared_ptr 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 JSCCtx::RunScript(const string_view& data, if (exception) { SetException(std::make_shared(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(context_, value); } diff --git a/modules/footstone/include/footstone/logging.h b/modules/footstone/include/footstone/logging.h index 9df4862185e..e31c8f9ce08 100644 --- a/modules/footstone/include/footstone/logging.h +++ b/modules/footstone/include/footstone/logging.h @@ -20,6 +20,8 @@ #pragma once +#if defined(__cplusplus) + #include #include #include @@ -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:"<= GetMinLogLevel(); } diff --git a/modules/ios/base/HPLog.h b/modules/ios/base/HPLog.h index 02b4573dcf8..a51540087f3 100644 --- a/modules/ios/base/HPLog.h +++ b/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 @@ -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__) diff --git a/renderer/native/ios/renderer/NativeRenderImpl.mm b/renderer/native/ios/renderer/NativeRenderImpl.mm index 87be2c192e0..587b58af859 100644 --- a/renderer/native/ios/renderer/NativeRenderImpl.mm +++ b/renderer/native/ios/renderer/NativeRenderImpl.mm @@ -679,6 +679,9 @@ - (void)flushUIBlocksOnRootNode:(std::weak_ptr)rootNode { if (!strongRootNode) { return; } + unsigned int rand = arc4random(); + HP_PERF_LOG("flushUIBlocksOnRootNode(random id:%u", rand); + int32_t rootTag = strongRootNode->GetId(); NSArray *previousPendingUIBlocks = _pendingUIBlocks; _pendingUIBlocks = [NSMutableArray new]; @@ -687,18 +690,26 @@ - (void)flushUIBlocksOnRootNode:(std::weak_ptr)rootNode { // Execute the previously queued UI blocks dispatch_async(dispatch_get_main_queue(), ^{ if (weakManager) { + HP_PERF_LOG("flushUIBlocksOnRootNode on main thread(random id:%u)",rand); + int cnt = 0; + NativeRenderImpl *strongSelf = weakManager; NSDictionary *viewReg = [strongSelf->_viewRegistry componentsForRootTag:@(rootTag)]; @try { for (NativeRenderRenderUIBlock block in previousPendingUIBlocks) { block(strongSelf, viewReg); + ++cnt; } } @catch (NSException *exception) { } + HP_PERF_LOG("flushUIBlocksOnRootNode on main thread done, block count:%d(random id:%u)", cnt, rand); + } }); } + HP_PERF_LOG("flushUIBlocksOnRootNode End(random id:%u)",rand); + } #pragma mark - diff --git a/renderer/native/ios/renderer/NativeRenderManager.mm b/renderer/native/ios/renderer/NativeRenderManager.mm index d654c274056..123c02bed67 100644 --- a/renderer/native/ios/renderer/NativeRenderManager.mm +++ b/renderer/native/ios/renderer/NativeRenderManager.mm @@ -111,14 +111,21 @@ void NativeRenderManager::EndBatch(std::weak_ptr root_node) { @autoreleasepool { + HP_PERF_LOG("NativeRenderManager::EndBatch"); HPAssert(renderImpl_, @"renderImpl_ is null, did you forget to call Initialize()?"); [renderImpl_ batchOnRootNode:root_node]; + HP_PERF_LOG("NativeRenderManager::EndBatch End"); + } } -void NativeRenderManager::BeforeLayout(std::weak_ptr root_node) {} +void NativeRenderManager::BeforeLayout(std::weak_ptr root_node) { + HP_PERF_LOG("NativeRenderManager::BeforeLayout"); +} -void NativeRenderManager::AfterLayout(std::weak_ptr root_node) {} +void NativeRenderManager::AfterLayout(std::weak_ptr root_node) { + HP_PERF_LOG("NativeRenderManager::AfterLayout"); +} void NativeRenderManager::AddEventListener(std::weak_ptr root_node, std::weak_ptr dom_node,