Add Profile log

Change-Id: I6671e750ac16a0fff40a196a23cb030e1b941b7d

diff --git a/src/bundle/extension_client.cc b/src/bundle/extension_client.cc
index 7082d4b..497286f 100755 (executable)
--- a/src/bundle/extension_client.cc
+++ b/src/bundle/extension_client.cc
@@ -100,6 +100,7 @@ std::string ExtensionClient::SendSyncMessageToNative(
 }
 
 bool ExtensionClient::Initialize(const std::string& uuid) {
+  STEP_PROFILE_START("Connect ExtensionServer");
   // Retry connecting to ExtensionServer
   // ExtensionServer can not be ready at this time yet.
   const int retry_max = 20;
@@ -112,6 +113,7 @@ bool ExtensionClient::Initialize(const std::string& uuid) {
                  << (i+1) << "/" << retry_max;
     usleep(50*1000);
   }
+  STEP_PROFILE_END("Connect ExtensionServer");
 
   if (!connected) {
     LOGGER(ERROR) << "Failed to connect to the dbus server for Extension.";

diff --git a/src/bundle/extension_renderer_controller.cc b/src/bundle/extension_renderer_controller.cc
index a78a5c3..10d1959 100755 (executable)
--- a/src/bundle/extension_renderer_controller.cc
+++ b/src/bundle/extension_renderer_controller.cc
@@ -27,6 +27,7 @@
 #include "bundle/xwalk_v8tools_module.h"
 #include "bundle/widget_module.h"
 #include "bundle/object_tools_module.h"
+#include "common/profiler.h"
 
 
 namespace wrt {
@@ -35,6 +36,7 @@ namespace {
 
 void CreateExtensionModules(ExtensionClient* client,
                             ModuleSystem* module_system) {
+  SCOPE_PROFILE();
   const ExtensionClient::ExtensionAPIMap& extensions =
       client->extension_apis();
   auto it = extensions.begin();
@@ -66,6 +68,7 @@ ExtensionRendererController::~ExtensionRendererController() {
 
 void ExtensionRendererController::DidCreateScriptContext(
     v8::Handle<v8::Context> context) {
+  SCOPE_PROFILE();
   ModuleSystem* module_system = new ModuleSystem(context);
   ModuleSystem::SetModuleSystemInContext(
       std::unique_ptr<ModuleSystem>(module_system), context);

diff --git a/src/bundle/injected_bundle.cc b/src/bundle/injected_bundle.cc
index d19313c..ca7abfd 100755 (executable)
--- a/src/bundle/injected_bundle.cc
+++ b/src/bundle/injected_bundle.cc
@@ -29,6 +29,7 @@
 #include "bundle/runtime_ipc_client.h"
 #include "bundle/extension_renderer_controller.h"
 #include "bundle/widget_module.h"
+#include "common/profiler.h"
 
 namespace wrt {
 class BundleGlobalData {
@@ -71,6 +72,7 @@ class BundleGlobalData {
 }  //  namespace wrt
 
 extern "C" void DynamicSetWidgetInfo(const char* tizen_id) {
+  SCOPE_PROFILE();
   LOGGER(DEBUG) << "InjectedBundle::DynamicSetWidgetInfo !!" << tizen_id;
   ecore_init();
   wrt::BundleGlobalData::GetInstance()->Initialize(tizen_id);
@@ -83,20 +85,26 @@ extern "C" void DynamicPluginStartSession(const char* tizen_id,
                                           const char* uuid,
                                           const char* /*theme*/,
                                           const char* base_url) {
+  SCOPE_PROFILE();
   LOGGER(DEBUG) << "InjectedBundle::DynamicPluginStartSession !!" << tizen_id;
   if (base_url == NULL || wrt::utils::StartsWith(base_url, "http")) {
     LOGGER(ERROR) << "External url not allowed plugin loading.";
     return;
   }
 
+  STEP_PROFILE_START("Initialize RuntimeIPCClient");
   // Initialize RuntimeIPCClient
   wrt::RuntimeIPCClient* rc = wrt::RuntimeIPCClient::GetInstance();
   rc->set_routing_id(routing_handle);
+  STEP_PROFILE_END("Initialize RuntimeIPCClient");
 
+  STEP_PROFILE_START("Initialize ExtensionRendererController");
   // Initialize ExtensionRendererController
   wrt::ExtensionRendererController& controller =
       wrt::ExtensionRendererController::GetInstance();
   controller.InitializeExtensions(uuid);
+  STEP_PROFILE_END("Initialize ExtensionRendererController");
+
   controller.DidCreateScriptContext(context);
 }
 

diff --git a/src/common/application_data.cc b/src/common/application_data.cc
index eb52a5f..bdfd54b 100755 (executable)
--- a/src/common/application_data.cc
+++ b/src/common/application_data.cc
@@ -25,6 +25,7 @@
 
 #include "common/logger.h"
 #include "common/file_utils.h"
+#include "common/profiler.h"
 
 namespace wrt {
 
@@ -150,6 +151,7 @@ std::shared_ptr<const wgt::parse::CSPInfo>
 
 
 bool ApplicationData::LoadManifestData() {
+  SCOPE_PROFILE();
   std::string config_xml_path(application_path_ + kConfigXml);
   if (!utils::Exists(config_xml_path)) {
     LOGGER(ERROR) << "Failed to load manifest data : No such file '"

diff --git a/src/common/profiler.cc b/src/common/profiler.cc
index cd90f29..bc10c9c 100755 (executable)
--- a/src/common/profiler.cc
+++ b/src/common/profiler.cc
@@ -16,14 +16,68 @@
 
 #include "common/profiler.h"
 
+#include <math.h>
+
 #include "common/logger.h"
 #include "common/string_utils.h"
 
 namespace wrt {
 
+namespace {
+void PrintProfileTime(const char* step, const struct timespec& start) {
+  struct timespec end;
+  clock_gettime(CLOCK_REALTIME, &end);
+  int64_t diff_in_milli = (end.tv_sec - start.tv_sec) * 1000
+                       + round((end.tv_nsec - start.tv_nsec) * 0.000001);
+  std::ostringstream ss;
+  ss << "END (" << diff_in_milli << "ms)";
+  PrintProfileLog(step, ss.str().c_str());
+}
+
+}  //  namespace
+
 void PrintProfileLog(const char* func, const char* tag) {
   LOGGER(DEBUG) << "[PROF] [" << utils::GetCurrentMilliSeconds() << "] "
                 << func << ":" << tag;
 }
 
+ScopeProfile::ScopeProfile(const char* step) : step_(step), expired_(false) {
+  clock_gettime(CLOCK_REALTIME, &start_);
+  PrintProfileLog(step, "START");
+}
+
+ScopeProfile::~ScopeProfile() {
+  if (!expired_)
+    PrintProfileTime(step_.c_str(), start_);
+}
+
+void ScopeProfile::Reset() {
+  clock_gettime(CLOCK_REALTIME, &start_);
+  PrintProfileLog(step_.c_str(), "START-updated");
+}
+
+void ScopeProfile::End() {
+  expired_ = true;
+  PrintProfileTime(step_.c_str(), start_);
+}
+
+StepProfile* StepProfile::GetInstance() {
+  static StepProfile instance;
+  return &instance;
+}
+
+StepProfile::StepProfile() {
+}
+
+StepProfile::~StepProfile() {
+}
+
+void StepProfile::Start(const char* step) {
+  map_[step].reset(new ScopeProfile(step));
+}
+
+void StepProfile::End(const char* step) {
+  map_[step].reset();
+}
+
 }  // namespace wrt

diff --git a/src/common/profiler.h b/src/common/profiler.h
index 29e4d57..7da1033 100755 (executable)
--- a/src/common/profiler.h
+++ b/src/common/profiler.h
@@ -17,6 +17,12 @@
 #ifndef WRT_COMMON_PROFILER_H_
 #define WRT_COMMON_PROFILER_H_
 
+#include <time.h>
+
+#include <string>
+#include <memory>
+#include <map>
+
 namespace wrt {
 
 #define PROFILE_START() PrintProfileLog(__FUNCTION__, "START");
@@ -25,6 +31,41 @@ namespace wrt {
 
 void PrintProfileLog(const char* func, const char* tag);
 
+class ScopeProfile {
+ public:
+  explicit ScopeProfile(const char* step);
+  ~ScopeProfile();
+  void Reset();
+  void End();
+ private:
+  std::string step_;
+  struct timespec start_;
+  bool expired_;
+};
+
+class StepProfile {
+ public:
+  static StepProfile* GetInstance();
+  void Start(const char* step);
+  void End(const char* step);
+ private:
+  StepProfile();
+  ~StepProfile();
+  typedef std::map<const std::string,
+                   std::unique_ptr<ScopeProfile> > ProfileMapT;
+  ProfileMapT map_;
+};
+
 }  // namespace wrt
 
+#define SCOPE_PROFILE() \
+  wrt::ScopeProfile __profile(__FUNCTION__);
+
+#define STEP_PROFILE_START(x) \
+  wrt::StepProfile::GetInstance()->Start(x)
+
+#define STEP_PROFILE_END(x) \
+  wrt::StepProfile::GetInstance()->End(x)
+
+
 #endif  // WRT_COMMON_PROFILER_H_

diff --git a/src/common/string_utils.cc b/src/common/string_utils.cc
index cdab154..fda06f6 100755 (executable)
--- a/src/common/string_utils.cc
+++ b/src/common/string_utils.cc
@@ -61,7 +61,7 @@ std::string GetCurrentMilliSeconds() {
   std::ostringstream ss;
   struct timespec spec;
   clock_gettime(CLOCK_REALTIME, &spec);
-  ss << spec.tv_sec << "." <<
+  ss << (spec.tv_sec%10000) << "." <<
      std::setw(3) << std::setfill('0') << (round(spec.tv_nsec / 1.0e6));
   return ss.str();
 }

diff --git a/src/runtime/main.cc b/src/runtime/main.cc
index 529c841..a8d74b7 100755 (executable)
--- a/src/runtime/main.cc
+++ b/src/runtime/main.cc
@@ -21,8 +21,11 @@
 #include "common/command_line.h"
 #include "runtime/runtime.h"
 #include "extension/extension_server.h"
+#include "common/profiler.h"
 
 int main(int argc, char* argv[]) {
+  STEP_PROFILE_START("Start -> Launch Completed");
+  STEP_PROFILE_START("Start -> OnCreate");
   // Parse commandline.
   wrt::CommandLine::Init(argc, argv);
 

diff --git a/src/runtime/runtime.cc b/src/runtime/runtime.cc
index ff989f1..8e01e13 100755 (executable)
--- a/src/runtime/runtime.cc
+++ b/src/runtime/runtime.cc
@@ -26,6 +26,7 @@
 #include "common/app_control.h"
 #include "common/application_data.h"
 #include "runtime/native_app_window.h"
+#include "common/profiler.h"
 
 namespace wrt {
 
@@ -35,6 +36,7 @@ const char* kTextLocalePath = "/usr/share/locale";
 const char* kTextDomainWrt = "wrt";
 
 static NativeWindow* CreateNativeWindow() {
+  SCOPE_PROFILE();
   // TODO(wy80.choi) : consider other type of native window.
   NativeWindow* window = new NativeAppWindow();
   window->Initialize();
@@ -58,6 +60,10 @@ Runtime::~Runtime() {
 }
 
 bool Runtime::OnCreate() {
+  STEP_PROFILE_END("ui_app_main -> OnCreate");
+  STEP_PROFILE_END("Start -> OnCreate");
+  STEP_PROFILE_START("OnCreate -> URL Set");
+
   std::string appid = CommandLine::ForCurrentProcess()->appid();
 
   // Process First Launch
@@ -67,7 +73,9 @@ bool Runtime::OnCreate() {
   }
 
   native_window_ = CreateNativeWindow();
+  STEP_PROFILE_START("WebApplication Create");
   application_ = new WebApplication(native_window_, std::move(appdata));
+  STEP_PROFILE_END("WebApplication Create");
   application_->set_terminator([](){ ui_app_exit(); });
 
   setlocale(LC_ALL, "");
@@ -92,6 +100,7 @@ void Runtime::OnResume() {
 }
 
 void Runtime::OnAppControl(app_control_h app_control) {
+  SCOPE_PROFILE();
   std::unique_ptr<AppControl> appcontrol(new AppControl(app_control));
   if (application_->launched()) {
     application_->AppControl(std::move(appcontrol));
@@ -189,7 +198,7 @@ int Runtime::Exec(int argc, char* argv[]) {
                            APP_EVENT_LOW_MEMORY,
                            low_memory,
                            this);
-
+  STEP_PROFILE_START("ui_app_main -> OnCreate");
   return ui_app_main(argc, argv, &ops, this);
 }
 

diff --git a/src/runtime/web_application.cc b/src/runtime/web_application.cc
index 826ef3d..5303dbf 100755 (executable)
--- a/src/runtime/web_application.cc
+++ b/src/runtime/web_application.cc
@@ -41,6 +41,7 @@
 #include "runtime/notification_manager.h"
 #include "runtime/popup.h"
 #include "runtime/popup_string.h"
+#include "common/profiler.h"
 
 #ifndef INJECTED_BUNDLE_PATH
   #error INJECTED_BUNDLE_PATH is not set.
@@ -241,6 +242,7 @@ WebApplication::~WebApplication() {
 }
 
 bool WebApplication::Initialize() {
+  SCOPE_PROFILE();
   // ewk setting
   ewk_context_cache_model_set(ewk_context_, EWK_CACHE_MODEL_DOCUMENT_BROWSER);
 
@@ -366,6 +368,7 @@ bool WebApplication::Initialize() {
 }
 
 void WebApplication::Launch(std::unique_ptr<wrt::AppControl> appcontrol) {
+  STEP_PROFILE_START("ExtensionServer Init");
   // Start DBus Server for Runtime
   // TODO(wy80.choi): Should I add PeerCredentials checker?
   using std::placeholders::_1;
@@ -385,6 +388,7 @@ void WebApplication::Launch(std::unique_ptr<wrt::AppControl> appcontrol) {
 
   // Execute ExtensionProcess
   ExecExtensionProcess(app_uuid_);
+  STEP_PROFILE_END("ExtensionServer Init");
 
   // Setup View
   WebView* view = new WebView(window_, ewk_context_);
@@ -401,6 +405,10 @@ void WebApplication::Launch(std::unique_ptr<wrt::AppControl> appcontrol) {
   std::unique_ptr<ResourceManager::Resource> res =
     resource_manager_->GetStartResource(appcontrol.get());
   view->SetDefaultEncoding(res->encoding());
+
+  STEP_PROFILE_END("OnCreate -> URL Set");
+  STEP_PROFILE_START("URL Set -> Rendered");
+
   view->LoadUrl(res->uri(), res->mime());
   view_stack_.push_front(view);
   window_->SetContent(view->evas_object());
@@ -678,6 +686,8 @@ void WebApplication::OnLoadFinished(WebView* /*view*/) {
   LOGGER(DEBUG) << "LoadFinished";
 }
 void WebApplication::OnRendered(WebView* /*view*/) {
+  STEP_PROFILE_END("URL Set -> Rendered");
+  STEP_PROFILE_END("Start -> Launch Completed");
   LOGGER(DEBUG) << "Rendered";
 }
 

diff --git a/src/runtime/web_view_impl.cc b/src/runtime/web_view_impl.cc
index ea31bf3..df8a5b9 100755 (executable)
--- a/src/runtime/web_view_impl.cc
+++ b/src/runtime/web_view_impl.cc
@@ -24,7 +24,7 @@
 #include "runtime/native_window.h"
 #include "common/logger.h"
 #include "common/file_utils.h"
-
+#include "common/profiler.h"
 namespace wrt {
 
 namespace {
@@ -90,6 +90,7 @@ WebViewImpl::~WebViewImpl() {
 }
 
 void WebViewImpl::LoadUrl(const std::string& url, const std::string& mime) {
+  SCOPE_PROFILE();
   if (!mime.empty()) {
     mime_ = mime;
     auto mime_override_cb = [](const char* url, const char* mime,