[Android] record performance detail cost (#2769)

android/sdk/src/main/java/com/taobao/weex/WXSDKInstance.java

@@ -816,6 +816,7 @@ private void renderInternal(String pageName,
     }
     mApmForInstance.setPageName(pageName);
     mApmForInstance.onStage(WXInstanceApm.KEY_PAGE_STAGES_RENDER_ORGIGIN);
+    mApmForInstance.doDelayCollectData();
 
     mWXPerformance.pageName = (TextUtils.isEmpty(pageName) ? "defaultBundleUrl":pageName);
     if (TextUtils.isEmpty(mBundleUrl)) {
@@ -1641,7 +1642,7 @@ public void onChangeElement(WXComponent component, boolean isOutOfScreen) {
     if (mHasCreateFinish){
       lazyLoadTime = lastElementChangeTime - mWXPerformance.renderTimeOrigin;
       if (lazyLoadTime > 8000) {
-        //bad case
+        //force record detail performance data
         return;
       }
     }

android/sdk/src/main/java/com/taobao/weex/bridge/WXBridge.java

@@ -122,6 +122,7 @@ public class WXBridge implements IWXBridge {
 
   private native void nativeSetPageArgument(String instanceId, String key, String value);
 
+  public native void nativeOnInteractionTimeUpdate(String instanceId);
 
   /**
    * Update Init Framework Params
@@ -183,6 +184,18 @@ public void execJSWithCallback(String instanceId, String namespace, String funct
             ResultCallbackManager.generateCallbackId(callback));
   }
 
+  @CalledByNative
+  public void onNativePerformanceDataUpdate(String instanceId,Map<String,String> map){
+    if (TextUtils.isEmpty(instanceId) || null == map || map.size() < 1){
+      return;
+    }
+    WXSDKInstance instance = WXSDKManager.getInstance().getAllInstanceMap().get(instanceId);
+    if (null == instance || null == instance.getApmForInstance()){
+      return;
+    }
+    instance.getApmForInstance().updateNativePerformanceData(map);
+  }
+
   // Result from js engine
   @CalledByNative
   public void onReceivedResult(long callbackId, byte[] result) {

android/sdk/src/main/java/com/taobao/weex/bridge/WXBridgeManager.java

@@ -283,6 +283,18 @@ public void setUseSingleProcess(final boolean flag) {
 //      }
     }
   }
+
+  public void onInteractionTimeUpdate(final String instanceId){
+    post(new Runnable() {
+      @Override
+      public void run() {
+        if (mWXBridge instanceof WXBridge ){
+          ((WXBridge)mWXBridge).nativeOnInteractionTimeUpdate(instanceId);
+        }
+      }
+    });
+  }
+
   public boolean jsEngineMultiThreadEnable() {
     return isJsEngineMultiThreadEnable;
   }
@@ -1021,6 +1033,7 @@ public void run() {
         WXSDKInstance instance = WXSDKManager.getInstance().getAllInstanceMap().get(instanceId);
         if (null != instance && instance.isPreInitMode()){
           instance.getApmForInstance().onStage(WXInstanceApm.KEY_PAGE_STAGES_LOAD_BUNDLE_END);
+          instance.getApmForInstance().onStageWithTime(WXInstanceApm.KEY_PAGE_STAGES_END_EXCUTE_BUNDLE,WXUtils.getFixUnixTime()+600);
         }
       }
     });

android/sdk/src/main/java/com/taobao/weex/performance/WXInstanceApm.java

@@ -74,8 +74,10 @@ public class WXInstanceApm {
     public static final String KEY_PAGE_STAGES_CREATE_FINISH= "wxJSBundleCreateFinish";
     public static final String KEY_PAGE_STAGES_FSRENDER = "wxFsRender";
     public static final String KEY_PAGE_STAGES_NEW_FSRENDER = "wxNewFsRender";
+    public static final String KEY_PAGE_STAGES_END_EXCUTE_BUNDLE = "wxEndExecuteBundle";
     public static final String KEY_PAGE_STAGES_INTERACTION = "wxInteraction";
     public static final String KEY_PAGE_STAGES_DESTROY = "wxDestroy";
+
     //Custom preprocessing start, called when activity created or other time. Called by other activity
     public static final String KEY_PAGE_STAGES_CUSTOM_PREPROCESS_START = "wxCustomPreprocessStart";
     //Custom preprocessing end, called when you'are able to start weex render. Called by other activity
@@ -117,6 +119,11 @@ public class WXInstanceApm {
     public static final String KEY_PAGE_STATS_NET_SUCCESS_NUM = "wxNetworkRequestSuccessCount";
     public static final String KEY_PAGE_STATS_NET_FAIL_NUM = "wxNetworkRequestFailCount";
     public static final String KEY_PAGE_STATS_JSLIB_INIT_TIME = "wxJSLibInitTime";
+    public static final String KEY_PAGE_STATS_VIEW_CREATE_COST = "wxViewCost";
+    public static final String KEY_PAGE_STATS_COMPONENT_CREATE_COST = "wxComponentCost";
+    public static final String KEY_PAGE_STATS_EXECUTE_JS_CALLBACK_COST = "wxExecJsCallBack";
+    public static final String KEY_PAGE_STATS_LAYOUT_TIME = "wxLayoutTime";
+
 
     /************** value *****************/
     public static final String VALUE_ERROR_CODE_DEFAULT = "0";
@@ -141,6 +148,18 @@ public class WXInstanceApm {
 
     public Set<String> exceptionRecord = new CopyOnWriteArraySet<String>();
 
+    private double interactionLayoutTime;
+    public long componentCreateTime;
+    private long interactionComponentCreateTime;
+    public long viewCreateTime;
+    private long interactionViewCreateTime;
+    //next version
+    private long wxExecJsCallBackTime;
+    private long interactionJsCallBackTime;
+
+
+    private boolean mHasRecordDetailData = false;
+
     /**
      * send performance value to js
      **/
@@ -367,6 +386,8 @@ public void onEnd() {
         if (null == apmInstance || mEnd) {
             return;
         }
+        new Handler(Looper.getMainLooper()).removeCallbacks(delayCollectDataTask);
+        recordPerformanceDetailData();
         exceptionRecord.clear();
         mUIHandler.removeCallbacks(jsPerformanceCallBack);
         onStage(KEY_PAGE_STAGES_DESTROY);
@@ -379,6 +400,17 @@ public void onEnd() {
         }
     }
 
+    public void doDelayCollectData(){
+        new Handler(Looper.getMainLooper()).postDelayed(delayCollectDataTask,8000);
+    }
+
+    private Runnable delayCollectDataTask = new Runnable() {
+        @Override
+        public void run() {
+            recordPerformanceDetailData();
+        }
+    };
+
 
     private void printLog(){
         Long startDownLoad = stageMap.get(KEY_PAGE_STAGES_DOWN_BUNDLE_START);
@@ -450,6 +482,17 @@ public void arriveInteraction(WXComponent targetComponent) {
         if (forceStopRecordInteraction){
             return;
         }
+        long now = WXUtils.getFixUnixTime();
+        if (now - preUpdateTime > 50){
+            //for performance, reduce jni calls
+            WXBridgeManager.getInstance().onInteractionTimeUpdate(mInstanceId);
+            preUpdateTime = now;
+        }
+
+        interactionComponentCreateTime = componentCreateTime;
+        interactionViewCreateTime = viewCreateTime;
+        Double layoutTime = recordStatsMap.get("wxLayoutTime");
+        interactionLayoutTime = layoutTime ==null? 0:layoutTime;
 
         performanceRecord.interactionTime = curTime - performanceRecord.renderUnixTimeOrigin;
         performanceRecord.interactionRealUnixTime = System.currentTimeMillis();
@@ -463,13 +506,26 @@ public void arriveInteraction(WXComponent targetComponent) {
         }
     }
 
+    private long preUpdateTime = 0;
+
     public void updateFSDiffStats(String name, double diffValue) {
         if (null == apmInstance || isFSEnd) {
             return;
         }
         updateDiffStats(name, diffValue);
     }
 
+    public void recordPerformanceDetailData(){
+        if (mHasRecordDetailData){
+            return;
+        }
+        mHasRecordDetailData = true;
+        addStats(KEY_PAGE_STATS_VIEW_CREATE_COST,interactionViewCreateTime);
+        addStats(KEY_PAGE_STATS_COMPONENT_CREATE_COST,interactionComponentCreateTime);
+        addStats(KEY_PAGE_STATS_EXECUTE_JS_CALLBACK_COST,interactionJsCallBackTime);
+        addStats(KEY_PAGE_STATS_LAYOUT_TIME,interactionLayoutTime);
+    }
+
     public void updateDiffStats(String name, double diffValue) {
         if (null == apmInstance) {
             return;
@@ -608,4 +664,20 @@ public String toPerfString() {
         return builder.toString();
    }
 
+   public void updateNativePerformanceData(Map<String,String> nativePerformanceData){
+        if (null == nativePerformanceData){
+            return;
+        }
+        for (Map.Entry<String,String> entry : nativePerformanceData.entrySet()){
+            double value = -1;
+            try {
+                value = Double.valueOf(entry.getValue());
+            }catch (Exception e){
+                e.printStackTrace();
+            }
+            if (value != -1){
+                recordStatsMap.put(entry.getKey(),value);
+            }
+        }
+   }
  }

android/sdk/src/main/java/com/taobao/weex/ui/action/GraphicActionAddElement.java

@@ -36,6 +36,8 @@
 import com.taobao.weex.ui.component.WXVContainer;
 import com.taobao.weex.utils.WXExceptionUtils;
 import com.taobao.weex.utils.WXLogUtils;
+import com.taobao.weex.utils.WXUtils;
+
 import java.util.Arrays;
 import java.util.Locale;
 import java.util.Map;
@@ -78,10 +80,13 @@ public GraphicActionAddElement(@NonNull WXSDKInstance instance, String ref,
     try {
       parent = (WXVContainer) WXSDKManager.getInstance().getWXRenderManager()
           .getWXComponent(getPageId(), mParentRef);
+      long start = WXUtils.getFixUnixTime();
       BasicComponentData basicComponentData = new BasicComponentData(ref, mComponentType,
           mParentRef);
       child = createComponent(instance, parent, basicComponentData);
       child.setTransition(WXTransition.fromMap(child.getStyles(), child));
+      long diff = WXUtils.getFixUnixTime()-start;
+      instance.getApmForInstance().componentCreateTime += diff;
       if (null != parent && parent.isIgnoreInteraction){
         child.isIgnoreInteraction = true;
       }
@@ -187,6 +192,7 @@ public void executeAction() {
       if (!TextUtils.equals(mComponentType, "video") && !TextUtils.equals(mComponentType, "videoplus"))
         child.mIsAddElementToTree = true;
 
+      long start = WXUtils.getFixUnixTime();
       parent.addChild(child, mIndex);
       parent.createChildViewAt(mIndex);
 
@@ -196,6 +202,11 @@ public void executeAction() {
       }
       child.applyLayoutAndEvent(child);
       child.bindData(child);
+      long diff = WXUtils.getFixUnixTime() - start;
+      if (null != getWXSDKIntance()){
+        getWXSDKIntance().getApmForInstance().viewCreateTime +=diff;
+      }
+
     } catch (Exception e) {
       WXLogUtils.e("add component failed.", e);
     }

weex_core/Source/android/wrap/wx_bridge.cpp

@@ -19,6 +19,7 @@
 
 #include "android/wrap/wx_bridge.h"
 #include <fstream>
+#include <core/render/manager/render_manager.h>
 
 #include "android/wrap/log_utils.h"
 #include "android/base/string/string_utils.h"
@@ -44,6 +45,8 @@
 #include "core/bridge/eagle_bridge.h"
 #include "core/common/view_utils.h"
 #include "third_party/json11/json11.hpp"
+#include "core/moniter/render_performance.h"
+#include "core/render/page/render_page_base.h"
 
 using namespace WeexCore;
 jlongArray jFirstScreenRenderTime = nullptr;
@@ -662,6 +665,38 @@ static jstring ExecJSOnInstance(JNIEnv* env, jobject jcaller,
   return env->NewStringUTF(result->data.get());
 }
 
+static void onInteractionTimeUpdate(JNIEnv* env, jobject jcaller, jstring instanceId) {
+  ScopedJStringUTF8 idChar(env, instanceId);
+
+  RenderPageBase* page = RenderManager::GetInstance()->GetPage(idChar.getChars());
+  if (nullptr == page){
+    return;
+  }
+  auto performance = page->getPerformance();
+  if (nullptr == performance){
+    return;
+  }
+  bool change = performance->onInteractionTimeUpdate();
+
+  if (!change){
+      return;
+  }
+
+  std::map<std::string,std::string> c_performance_data;
+  performance->getPerformanceStringData(c_performance_data);
+
+
+  auto performance_map = std::unique_ptr<WXMap>(new WXMap);
+  if (performance_map == nullptr) {
+      return;
+  }
+  performance_map->Put(env,c_performance_data);
+
+  jobject jni_map_performance =
+          performance_map.get() != nullptr ? performance_map->jni_object() : nullptr;
+  Java_WXBridge_onNativePerformanceDataUpdate(env,jcaller,instanceId,jni_map_performance);
+}
+
 static void FireEventOnDataRenderNode(JNIEnv* env, jobject jcaller,
                                       jstring instanceId, jstring ref,
                                       jstring type, jstring data,

weex_core/Source/base/android/jniprebuild/jniheader/WXBridge_jni.h

@@ -88,6 +88,8 @@ static jstring ExecJSOnInstance(JNIEnv* env, jobject jcaller,
     jstring script,
     jint type);
 
+static void onInteractionTimeUpdate(JNIEnv* env, jobject jcaller, jstring instanceId);
+
 static void FireEventOnDataRenderNode(JNIEnv* env, jobject jcaller,
     jstring instanceId,
     jstring ref,
@@ -1092,6 +1094,31 @@ static void Java_WXBridge_reportNativeInitStatus(JNIEnv* env, jobject obj,
 
 }
 
+static intptr_t g_WXBridge_onNativePerformanceDataUpdate = 0;
+static void Java_WXBridge_onNativePerformanceDataUpdate(JNIEnv* env, jobject obj,
+                                                        jstring id,
+                                                        jobject data) {
+    /* Must call RegisterNativesImpl()  */
+    //CHECK_CLAZZ(env, obj,
+    //    WXBridge_clazz(env));
+    jmethodID method_id =
+            base::android::GetMethod(
+                    env, WXBridge_clazz(env),
+                    base::android::INSTANCE_METHOD,
+                    "onNativePerformanceDataUpdate",
+                    "("
+                    "Ljava/lang/String;"
+                    "Ljava/util/Map;"
+                    ")"
+                    "V",
+                    &g_WXBridge_onNativePerformanceDataUpdate);
+
+    env->CallVoidMethod(obj,
+                        method_id, id, data);
+    base::android::CheckException(env);
+
+}
+
 // Step 3: RegisterNatives.
 
 static const JNINativeMethod kMethodsWXBridge[] = {
@@ -1162,6 +1189,11 @@ static const JNINativeMethod kMethodsWXBridge[] = {
 "I"
 ")"
 "Ljava/lang/String;", reinterpret_cast<void*>(ExecJSOnInstance) },
+    { "nativeOnInteractionTimeUpdate",
+"("
+"Ljava/lang/String;"
+")"
+"V", reinterpret_cast<void*>(onInteractionTimeUpdate) },
 { "nativeFireEventOnDataRenderNode",
     "("
     "Ljava/lang/String;"
@@ -1389,6 +1421,7 @@ static void Java_WXBridge_reset_clazz(JNIEnv* env, const char* className) {
     g_WXBridge_callHasTransitionPros = 0;
     g_WXBridge_getMeasurementFunc = 0;
     g_WXBridge_reportNativeInitStatus = 0;
+    g_WXBridge_onNativePerformanceDataUpdate = 0;
 }
 
 #endif  // com_taobao_weex_bridge_WXBridge_JNI

weex_core/Source/core/moniter/render_performance.cpp

@@ -17,6 +17,7 @@
  * under the License.
  */
 #include <cstdint>
+#include <string>
 #include "render_performance.h"
 
 namespace WeexCore {
@@ -43,4 +44,16 @@ namespace WeexCore {
 
     return ret;
   }
+
+    bool RenderPerformance::onInteractionTimeUpdate() {
+      if (cssLayoutTimeForInteraction == cssLayoutTime){
+          return false;
+      }
+      cssLayoutTimeForInteraction = cssLayoutTime;
+        return true;
+    }
+
+    void RenderPerformance::getPerformanceStringData(std::map<std::string, std::string> &map) {
+        map["wxLayoutTime"] = std::to_string(this->cssLayoutTimeForInteraction);
+    }
 }