From 5ef6e8d173d9b69aeb7469aef700e209007e0760 Mon Sep 17 00:00:00 2001 From: Panayot Cankov Date: Mon, 29 May 2017 15:23:42 +0300 Subject: [PATCH 1/2] This commits adds profiling in several places, showing some instances where the runtime block the JavaScript thread Log all c++ frames, log some key methods in Java Add package.json "profiling": "timeline" option to enable the logging of the manual instrumentation profiling --- .../java/com/tns/NativeScriptApplication.java | 13 +- .../src/main/java/com/tns/RuntimeHelper.java | 261 ++++++++++-------- runtime/src/main/java/com/tns/AppConfig.java | 79 +++--- runtime/src/main/java/com/tns/GcListener.java | 9 +- .../java/com/tns/ManualInstrumentation.java | 145 ++++++++++ runtime/src/main/java/com/tns/Runtime.java | 112 +++++--- .../src/main/jni/ManualInstrumentation.cpp | 8 + runtime/src/main/jni/ManualInstrumentation.h | 66 +++++ runtime/src/main/jni/MetadataNode.cpp | 22 ++ runtime/src/main/jni/ModuleInternal.cpp | 19 ++ runtime/src/main/jni/ObjectManager.cpp | 23 +- runtime/src/main/jni/Runtime.cpp | 7 + runtime/src/main/jni/Runtime.h | 2 + runtime/src/main/jni/com_tns_Runtime.cpp | 9 + .../java/com/tns/NativeScriptApplication.java | 13 +- .../src/main/java/com/tns/RuntimeHelper.java | 261 ++++++++++-------- 16 files changed, 721 insertions(+), 328 deletions(-) create mode 100644 runtime/src/main/java/com/tns/ManualInstrumentation.java create mode 100644 runtime/src/main/jni/ManualInstrumentation.cpp create mode 100644 runtime/src/main/jni/ManualInstrumentation.h diff --git a/build-artifacts/project-template-gradle/src/main/java/com/tns/NativeScriptApplication.java b/build-artifacts/project-template-gradle/src/main/java/com/tns/NativeScriptApplication.java index 6746023b9..d8a648753 100644 --- a/build-artifacts/project-template-gradle/src/main/java/com/tns/NativeScriptApplication.java +++ b/build-artifacts/project-template-gradle/src/main/java/com/tns/NativeScriptApplication.java @@ -11,10 +11,15 @@ public NativeScriptApplication() { } public void onCreate() { - super.onCreate(); - com.tns.Runtime runtime = RuntimeHelper.initRuntime(this); - if (runtime !=null) { - runtime.run(); + ManualInstrumentation.Frame frame = ManualInstrumentation.start("NaitveScriptApplication.onCreate"); + try { + super.onCreate(); + com.tns.Runtime runtime = RuntimeHelper.initRuntime(this); + if (runtime != null) { + runtime.run(); + } + } finally { + frame.close(); } } diff --git a/build-artifacts/project-template-gradle/src/main/java/com/tns/RuntimeHelper.java b/build-artifacts/project-template-gradle/src/main/java/com/tns/RuntimeHelper.java index 3e0cee066..4e3b30a82 100644 --- a/build-artifacts/project-template-gradle/src/main/java/com/tns/RuntimeHelper.java +++ b/build-artifacts/project-template-gradle/src/main/java/com/tns/RuntimeHelper.java @@ -53,157 +53,180 @@ public static Runtime initRuntime(Application app) { return Runtime.getCurrentRuntime(); } - System.loadLibrary("NativeScript"); - - Logger logger = new LogcatLogger(app); + ManualInstrumentation.Frame frame = ManualInstrumentation.start("RuntimeHelper.initRuntime"); + try { + ManualInstrumentation.Frame loadLibraryFrame = ManualInstrumentation.start("loadLibrary NativeScript"); + try { + System.loadLibrary("NativeScript"); + } finally { + loadLibraryFrame.close(); + } - Runtime runtime = null; - boolean showErrorIntent = hasErrorIntent(app); - if (!showErrorIntent) { - NativeScriptUncaughtExceptionHandler exHandler = new NativeScriptUncaughtExceptionHandler(logger, app); + Logger logger = new LogcatLogger(app); - Thread.setDefaultUncaughtExceptionHandler(exHandler); + Runtime runtime = null; + boolean showErrorIntent = hasErrorIntent(app); + if (!showErrorIntent) { + NativeScriptUncaughtExceptionHandler exHandler = new NativeScriptUncaughtExceptionHandler(logger, app); - DefaultExtractPolicy extractPolicy = new DefaultExtractPolicy(logger); - boolean skipAssetExtraction = Util.runPlugin(logger, app); + Thread.setDefaultUncaughtExceptionHandler(exHandler); - String appName = app.getPackageName(); - File rootDir = new File(app.getApplicationInfo().dataDir); - File appDir = app.getFilesDir(); + DefaultExtractPolicy extractPolicy = new DefaultExtractPolicy(logger); + boolean skipAssetExtraction = Util.runPlugin(logger, app); - try { - appDir = appDir.getCanonicalFile(); - } catch (IOException e1) { - } + String appName = app.getPackageName(); + File rootDir = new File(app.getApplicationInfo().dataDir); + File appDir = app.getFilesDir(); - if (!skipAssetExtraction) { - if (logger.isEnabled()) { - logger.write("Extracting assets..."); + try { + appDir = appDir.getCanonicalFile(); + } catch (IOException e1) { } - AssetExtractor aE = new AssetExtractor(null, logger); + if (!skipAssetExtraction) { + ManualInstrumentation.Frame extractionFrame = ManualInstrumentation.start("Extracting assets"); + try { + if (logger.isEnabled()) { + logger.write("Extracting assets..."); + } - String outputDir = app.getFilesDir().getPath() + File.separator; + AssetExtractor aE = new AssetExtractor(null, logger); - // will force deletion of previously extracted files in app/files directories - // see https://github.com/NativeScript/NativeScript/issues/4137 for reference - boolean removePreviouslyInstalledAssets = true; - aE.extractAssets(app, "app", outputDir, extractPolicy, removePreviouslyInstalledAssets); - aE.extractAssets(app, "internal", outputDir, extractPolicy, removePreviouslyInstalledAssets); - aE.extractAssets(app, "metadata", outputDir, extractPolicy, false); + String outputDir = app.getFilesDir().getPath() + File.separator; - boolean shouldExtractSnapshots = true; + // will force deletion of previously extracted files in app/files directories + // see https://github.com/NativeScript/NativeScript/issues/4137 for reference + boolean removePreviouslyInstalledAssets = true; + aE.extractAssets(app, "app", outputDir, extractPolicy, removePreviouslyInstalledAssets); + aE.extractAssets(app, "internal", outputDir, extractPolicy, removePreviouslyInstalledAssets); + aE.extractAssets(app, "metadata", outputDir, extractPolicy, false); - // will extract snapshot of the device appropriate architecture - if (shouldExtractSnapshots) { - if (logger.isEnabled()) { - logger.write("Extracting snapshot blob"); - } + boolean shouldExtractSnapshots = true; - aE.extractAssets(app, "snapshots/" + Build.CPU_ABI, outputDir, extractPolicy, removePreviouslyInstalledAssets); - } + // will extract snapshot of the device appropriate architecture + if (shouldExtractSnapshots) { + if (logger.isEnabled()) { + logger.write("Extracting snapshot blob"); + } - extractPolicy.setAssetsThumb(app); - } + aE.extractAssets(app, "snapshots/" + Build.CPU_ABI, outputDir, extractPolicy, removePreviouslyInstalledAssets); + } - AppConfig appConfig = new AppConfig(appDir); - - ClassLoader classLoader = app.getClassLoader(); - File dexDir = new File(rootDir, "code_cache/secondary-dexes"); - String dexThumb = null; - try { - dexThumb = Util.getDexThumb(app); - } catch (NameNotFoundException e) { - if (logger.isEnabled()) { - logger.write("Error while getting current proxy thumb"); + extractPolicy.setAssetsThumb(app); + } finally { + extractionFrame.close(); + } } - e.printStackTrace(); - } - - String nativeLibDir = null; - try { - nativeLibDir = app.getPackageManager().getApplicationInfo(appName, 0).nativeLibraryDir; - } catch (android.content.pm.PackageManager.NameNotFoundException e) { - e.printStackTrace(); - } - boolean isDebuggable = Util.isDebuggableApp(app); - StaticConfiguration config = new StaticConfiguration(logger, appName, nativeLibDir, rootDir, - appDir, classLoader, dexDir, dexThumb, appConfig, isDebuggable); + AppConfig appConfig = new AppConfig(appDir); + switch (appConfig.getProfilingMode()) { + case "timeline": + ManualInstrumentation.setMode(ManualInstrumentation.Mode.Timeline); + break; + default: + ManualInstrumentation.setMode(ManualInstrumentation.Mode.Disabled); + } + Runtime.SetManualInstrumentationMode(appConfig.getProfilingMode()); - runtime = Runtime.initializeRuntimeWithConfiguration(config); - if (isDebuggable) { + ClassLoader classLoader = app.getClassLoader(); + File dexDir = new File(rootDir, "code_cache/secondary-dexes"); + String dexThumb = null; try { - v8Inspector = new AndroidJsV8Inspector(app.getFilesDir().getAbsolutePath(), app.getPackageName()); - v8Inspector.start(); - - // the following snippet is used as means to notify the VSCode extension - // debugger that the debugger agent has started - File debuggerStartedFile = new File("/data/local/tmp", app.getPackageName() + "-debugger-started"); - if (debuggerStartedFile.exists() && !debuggerStartedFile.isDirectory() && debuggerStartedFile.length() == 0) { - java.io.FileWriter fileWriter = new java.io.FileWriter(debuggerStartedFile); - fileWriter.write("started"); - fileWriter.close(); - } - - // check if --debug-brk flag has been set. If positive: - // write to the file to invalidate the flag - // inform the v8Inspector to pause the main thread - File debugBreakFile = new File("/data/local/tmp", app.getPackageName() + "-debugbreak"); - boolean shouldBreak = false; - if (debugBreakFile.exists() && !debugBreakFile.isDirectory() && debugBreakFile.length() == 0) { - java.io.FileWriter fileWriter = new java.io.FileWriter(debugBreakFile); - fileWriter.write("started"); - fileWriter.close(); - - shouldBreak = true; + dexThumb = Util.getDexThumb(app); + } catch (NameNotFoundException e) { + if (logger.isEnabled()) { + logger.write("Error while getting current proxy thumb"); } + e.printStackTrace(); + } - v8Inspector.waitForDebugger(shouldBreak); - } catch (IOException e) { + String nativeLibDir = null; + try { + nativeLibDir = app.getPackageManager().getApplicationInfo(appName, 0).nativeLibraryDir; + } catch (android.content.pm.PackageManager.NameNotFoundException e) { e.printStackTrace(); } - } - // runtime needs to be initialized before the NativeScriptSyncService is enabled because it uses runtime.runScript(...) - if (NativeScriptSyncService.isSyncEnabled(app)) { - NativeScriptSyncService syncService = new NativeScriptSyncService(runtime, logger, app); - - syncService.sync(); - syncService.startServer(); - - // preserve this instance as strong reference - // do not preserve in NativeScriptApplication field inorder to - // make the code more portable - // @@@ - // Runtime.getOrCreateJavaObjectID(syncService); - } else { - if (logger.isEnabled()) { - logger.write("NativeScript LiveSync is not enabled."); + boolean isDebuggable = Util.isDebuggableApp(app); + StaticConfiguration config = new StaticConfiguration(logger, appName, nativeLibDir, rootDir, + appDir, classLoader, dexDir, dexThumb, appConfig, isDebuggable); + + runtime = Runtime.initializeRuntimeWithConfiguration(config); + if (isDebuggable) { + try { + v8Inspector = new AndroidJsV8Inspector(app.getFilesDir().getAbsolutePath(), app.getPackageName()); + v8Inspector.start(); + + // the following snippet is used as means to notify the VSCode extension + // debugger that the debugger agent has started + File debuggerStartedFile = new File("/data/local/tmp", app.getPackageName() + "-debugger-started"); + if (debuggerStartedFile.exists() && !debuggerStartedFile.isDirectory() && debuggerStartedFile.length() == 0) { + java.io.FileWriter fileWriter = new java.io.FileWriter(debuggerStartedFile); + fileWriter.write("started"); + fileWriter.close(); + } + + // check if --debug-brk flag has been set. If positive: + // write to the file to invalidate the flag + // inform the v8Inspector to pause the main thread + File debugBreakFile = new File("/data/local/tmp", app.getPackageName() + "-debugbreak"); + boolean shouldBreak = false; + if (debugBreakFile.exists() && !debugBreakFile.isDirectory() && debugBreakFile.length() == 0) { + java.io.FileWriter fileWriter = new java.io.FileWriter(debugBreakFile); + fileWriter.write("started"); + fileWriter.close(); + + shouldBreak = true; + } + + v8Inspector.waitForDebugger(shouldBreak); + } catch (IOException e) { + e.printStackTrace(); + } } - } - runtime.runScript(new File(appDir, "internal/ts_helpers.js")); + // runtime needs to be initialized before the NativeScriptSyncService is enabled because it uses runtime.runScript(...) + if (NativeScriptSyncService.isSyncEnabled(app)) { + NativeScriptSyncService syncService = new NativeScriptSyncService(runtime, logger, app); - File javaClassesModule = new File(appDir, "app/tns-java-classes.js"); - if (javaClassesModule.exists()) { - runtime.runModule(javaClassesModule); - } + syncService.sync(); + syncService.startServer(); - try { - // put this call in a try/catch block because with the latest changes in the modules it is not granted that NativeScriptApplication is extended through JavaScript. - JavaScriptImplementation jsImpl = app.getClass().getAnnotation(JavaScriptImplementation.class); - if (jsImpl != null) { - Runtime.initInstance(app); + // preserve this instance as strong reference + // do not preserve in NativeScriptApplication field inorder to + // make the code more portable + // @@@ + // Runtime.getOrCreateJavaObjectID(syncService); + } else { + if (logger.isEnabled()) { + logger.write("NativeScript LiveSync is not enabled."); + } } - } catch (Exception e) { - if (logger.isEnabled()) { - logger.write("Cannot initialize application instance."); + + runtime.runScript(new File(appDir, "internal/ts_helpers.js")); + + File javaClassesModule = new File(appDir, "app/tns-java-classes.js"); + if (javaClassesModule.exists()) { + runtime.runModule(javaClassesModule); + } + + try { + // put this call in a try/catch block because with the latest changes in the modules it is not granted that NativeScriptApplication is extended through JavaScript. + JavaScriptImplementation jsImpl = app.getClass().getAnnotation(JavaScriptImplementation.class); + if (jsImpl != null) { + Runtime.initInstance(app); + } + } catch (Exception e) { + if (logger.isEnabled()) { + logger.write("Cannot initialize application instance."); + } + e.printStackTrace(); } - e.printStackTrace(); } + return runtime; + } finally { + frame.close(); } - return runtime; } private static final String logTag = "MyApp"; diff --git a/runtime/src/main/java/com/tns/AppConfig.java b/runtime/src/main/java/com/tns/AppConfig.java index 8c9c40f8c..3dad082f6 100644 --- a/runtime/src/main/java/com/tns/AppConfig.java +++ b/runtime/src/main/java/com/tns/AppConfig.java @@ -5,6 +5,7 @@ import org.json.JSONObject; import android.os.Build; +import android.util.Log; class AppConfig { private enum KnownKeys { @@ -15,7 +16,8 @@ private enum KnownKeys { ProfilerOutputDirKey("profilerOutputDir", ""), GcThrottleTime("gcThrottleTime", 0), MemoryCheckInterval("memoryCheckInterval", 0), - FreeMemoryRatio("freeMemoryRatio", 0.0); + FreeMemoryRatio("freeMemoryRatio", 0.0), + Profiling("profiling", ""); public static final KnownKeys[] asArray = { V8FlagsKey, @@ -25,7 +27,8 @@ private enum KnownKeys { ProfilerOutputDirKey, GcThrottleTime, MemoryCheckInterval, - FreeMemoryRatio + FreeMemoryRatio, + Profiling }; private final String name; @@ -69,39 +72,45 @@ public AppConfig(File appDir) { JSONObject rootObject; try { rootObject = FileSystem.readJSONFile(packageInfo); - if (rootObject != null && rootObject.has(AndroidKey)) { - JSONObject androidObject = rootObject.getJSONObject(AndroidKey); - if (androidObject.has(KnownKeys.V8FlagsKey.getName())) { - values[KnownKeys.V8FlagsKey.getIndex()] = androidObject.getString(KnownKeys.V8FlagsKey.getName()); + if (rootObject != null) { + if (rootObject.has(KnownKeys.Profiling.getName())) { + String profiling = rootObject.getString(KnownKeys.Profiling.getName()); + values[KnownKeys.Profiling.getIndex()] = profiling; } - if (androidObject.has(KnownKeys.CodeCacheKey.getName())) { - values[KnownKeys.CodeCacheKey.getIndex()] = androidObject.getBoolean(KnownKeys.CodeCacheKey.getName()); - } - if (androidObject.has(KnownKeys.HeapSnapshotScriptKey.getName())) { - String value = androidObject.getString(KnownKeys.HeapSnapshotScriptKey.getName()); - values[KnownKeys.HeapSnapshotScriptKey.getIndex()] = FileSystem.resolveRelativePath(appDir.getPath(), value, appDir + "/app/"); - } - if (androidObject.has(HeapSnapshotBlobKey)) { - String value = androidObject.getString(HeapSnapshotBlobKey); - String path = FileSystem.resolveRelativePath(appDir.getPath(), value, appDir + "/app/"); - File dir = new File(path); - if (dir.exists() && dir.isDirectory()) { - // this path is expected to be a directory, containing three sub-directories: armeabi-v7a, x86 and arm64-v8a - path = path + "/" + Build.CPU_ABI + "/" + KnownKeys.SnapshotFile.getName(); - values[KnownKeys.SnapshotFile.getIndex()] = path; + if (rootObject.has(AndroidKey)) { + JSONObject androidObject = rootObject.getJSONObject(AndroidKey); + if (androidObject.has(KnownKeys.V8FlagsKey.getName())) { + values[KnownKeys.V8FlagsKey.getIndex()] = androidObject.getString(KnownKeys.V8FlagsKey.getName()); + } + if (androidObject.has(KnownKeys.CodeCacheKey.getName())) { + values[KnownKeys.CodeCacheKey.getIndex()] = androidObject.getBoolean(KnownKeys.CodeCacheKey.getName()); + } + if (androidObject.has(KnownKeys.HeapSnapshotScriptKey.getName())) { + String value = androidObject.getString(KnownKeys.HeapSnapshotScriptKey.getName()); + values[KnownKeys.HeapSnapshotScriptKey.getIndex()] = FileSystem.resolveRelativePath(appDir.getPath(), value, appDir + "/app/"); + } + if (androidObject.has(HeapSnapshotBlobKey)) { + String value = androidObject.getString(HeapSnapshotBlobKey); + String path = FileSystem.resolveRelativePath(appDir.getPath(), value, appDir + "/app/"); + File dir = new File(path); + if (dir.exists() && dir.isDirectory()) { + // this path is expected to be a directory, containing three sub-directories: armeabi-v7a, x86 and arm64-v8a + path = path + "/" + Build.CPU_ABI + "/" + KnownKeys.SnapshotFile.getName(); + values[KnownKeys.SnapshotFile.getIndex()] = path; + } + } + if (androidObject.has(KnownKeys.ProfilerOutputDirKey.getName())) { + values[KnownKeys.ProfilerOutputDirKey.getIndex()] = androidObject.getString(KnownKeys.ProfilerOutputDirKey.getName()); + } + if (androidObject.has(KnownKeys.GcThrottleTime.getName())) { + values[KnownKeys.GcThrottleTime.getIndex()] = androidObject.getInt(KnownKeys.GcThrottleTime.getName()); + } + if (androidObject.has(KnownKeys.MemoryCheckInterval.getName())) { + values[KnownKeys.MemoryCheckInterval.getIndex()] = androidObject.getInt(KnownKeys.MemoryCheckInterval.getName()); + } + if (androidObject.has(KnownKeys.FreeMemoryRatio.getName())) { + values[KnownKeys.FreeMemoryRatio.getIndex()] = androidObject.getDouble(KnownKeys.FreeMemoryRatio.getName()); } - } - if (androidObject.has(KnownKeys.ProfilerOutputDirKey.getName())) { - values[KnownKeys.ProfilerOutputDirKey.getIndex()] = androidObject.getString(KnownKeys.ProfilerOutputDirKey.getName()); - } - if (androidObject.has(KnownKeys.GcThrottleTime.getName())) { - values[KnownKeys.GcThrottleTime.getIndex()] = androidObject.getInt(KnownKeys.GcThrottleTime.getName()); - } - if (androidObject.has(KnownKeys.MemoryCheckInterval.getName())) { - values[KnownKeys.MemoryCheckInterval.getIndex()] = androidObject.getInt(KnownKeys.MemoryCheckInterval.getName()); - } - if (androidObject.has(KnownKeys.FreeMemoryRatio.getName())) { - values[KnownKeys.FreeMemoryRatio.getIndex()] = androidObject.getDouble(KnownKeys.FreeMemoryRatio.getName()); } } } catch (Exception e) { @@ -133,4 +142,8 @@ public int getMemoryCheckInterval() { public double getFreeMemoryRatio() { return (double)values[KnownKeys.FreeMemoryRatio.getIndex()]; } + + public String getProfilingMode() { + return (String)values[KnownKeys.Profiling.getIndex()]; + } } diff --git a/runtime/src/main/java/com/tns/GcListener.java b/runtime/src/main/java/com/tns/GcListener.java index 62a831e22..85b10834a 100644 --- a/runtime/src/main/java/com/tns/GcListener.java +++ b/runtime/src/main/java/com/tns/GcListener.java @@ -143,8 +143,13 @@ private void start() { private void notifyGc() { synchronized (instance) { - for (Runtime runtime: subscribers.keySet()) { - runtime.notifyGc(); + ManualInstrumentation.Frame frame = ManualInstrumentation.start("GcListener.notifyGc"); + try { + for (Runtime runtime : subscribers.keySet()) { + runtime.notifyGc(); + } + } finally { + frame.close(); } } } diff --git a/runtime/src/main/java/com/tns/ManualInstrumentation.java b/runtime/src/main/java/com/tns/ManualInstrumentation.java new file mode 100644 index 000000000..1d615d3cd --- /dev/null +++ b/runtime/src/main/java/com/tns/ManualInstrumentation.java @@ -0,0 +1,145 @@ +package com.tns; + +import android.util.Log; + +import java.util.Stack; + +/** + * Created by cankov on 01/06/2017. + */ +public class ManualInstrumentation { + private static Mode mode = Mode.Pending; + + public static void setMode(Mode mode) { + if (ManualInstrumentation.mode == Mode.Pending) { + switch(mode) { + case Timeline: + Mode.PendingFrame.printPending(); + break; + case Disabled: + Mode.PendingFrame.discardPending(); + break; + } + } + ManualInstrumentation.mode = mode; + } + + public interface Frame { + void close(); + } + + public static Frame start(String name) { + return mode.start(name); + } + + public enum Mode { + /** + * This mode is used to collect inital frames in pre package.json parsing. + */ + Pending { + protected Frame start(String name) { + return new PendingFrame(name); + } + }, + /** + * This mode will provide void frame implementation for fast performance in release builds. + */ + Disabled { + protected Frame start(String name) { + return DisabledFrame.instance; + } + }, + /** + * This mode creates frames that when closed will simply log in the android log frames that consume time longer than reasonable threshold. + */ + Timeline { + protected Frame start(String name) { + LogFrame frame = LogFrame.frames.isEmpty() ? new LogFrame() : LogFrame.frames.pop(); + frame.start = System.currentTimeMillis(); + frame.name = name; + return frame; + } + }; + + protected abstract Frame start(String name); + + private static class DisabledFrame implements Frame { + static DisabledFrame instance = new DisabledFrame(); + public void close() {} + } + + private static class LogFrame implements Frame { + private static Stack frames = new Stack(); + + private long start; + private StringBuilder builder = new StringBuilder(); + private String name; + + public void close() { + try { + long end = System.currentTimeMillis(); + if ((end - start) >= 16) { + builder.append("Timeline: Runtime: "); + builder.append(name); + builder.append(" ("); + builder.append(start); + builder.append("ms. - "); + builder.append(end); + builder.append("ms.)"); + Log.v("JS", builder.toString()); + builder.setLength(0); // Recycle the builder + } + } finally { + frames.push(this); // Recycle the frame + } + } + } + + private static class PendingFrame implements Frame { + private static Stack pendingFrames = new Stack(); + + private long start; + private long end; + private String name; + + private PendingFrame(String name) { + this.name = name; + start = System.currentTimeMillis(); + } + + public void close() { + end = System.currentTimeMillis(); + if (end - start > 16) { + if (mode == Timeline) { + print(); + } else if (mode == Pending) { + pendingFrames.add(this); + } + } + } + + private void print() { + StringBuilder builder = new StringBuilder(); + builder.append("Timeline: Runtime: "); + builder.append(name); + builder.append(" ("); + builder.append(start); + builder.append("ms. - "); + builder.append(end); + builder.append("ms.)"); + Log.v("JS", builder.toString()); + } + + public static void printPending() { + for (PendingFrame f : pendingFrames) { + f.print(); + } + pendingFrames.clear(); + } + + public static void discardPending() { + pendingFrames.clear(); + } + } + } +} diff --git a/runtime/src/main/java/com/tns/Runtime.java b/runtime/src/main/java/com/tns/Runtime.java index 4bfa1d4e4..d5d7792bc 100644 --- a/runtime/src/main/java/com/tns/Runtime.java +++ b/runtime/src/main/java/com/tns/Runtime.java @@ -53,6 +53,8 @@ public class Runtime { public static native int getPointerSize(); + public static native void SetManualInstrumentationMode(String mode); + private static native void WorkerGlobalOnMessageCallback(int runtimeId, String message); private static native void WorkerObjectOnMessageCallback(int runtimeId, int workerId, String message); @@ -144,26 +146,31 @@ public int compare(Method lhs, Method rhs) { public Runtime(StaticConfiguration config, DynamicConfiguration dynamicConfiguration) { synchronized (Runtime.currentRuntime) { - Runtime existingRuntime = currentRuntime.get(); - if (existingRuntime != null) { - throw new NativeScriptException("There is an existing runtime on this thread with id=" + existingRuntime.getRuntimeId()); - } + ManualInstrumentation.Frame frame = ManualInstrumentation.start("new Runtime"); + try { + Runtime existingRuntime = currentRuntime.get(); + if (existingRuntime != null) { + throw new NativeScriptException("There is an existing runtime on this thread with id=" + existingRuntime.getRuntimeId()); + } - this.runtimeId = nextRuntimeId.getAndIncrement(); - this.config = config; - this.dynamicConfig = dynamicConfiguration; - this.threadScheduler = dynamicConfiguration.myThreadScheduler; - this.workerId = dynamicConfiguration.workerId; - if (dynamicConfiguration.mainThreadScheduler != null) { - this.mainThreadHandler = dynamicConfiguration.mainThreadScheduler.getHandler(); - } + this.runtimeId = nextRuntimeId.getAndIncrement(); + this.config = config; + this.dynamicConfig = dynamicConfiguration; + this.threadScheduler = dynamicConfiguration.myThreadScheduler; + this.workerId = dynamicConfiguration.workerId; + if (dynamicConfiguration.mainThreadScheduler != null) { + this.mainThreadHandler = dynamicConfiguration.mainThreadScheduler.getHandler(); + } - classResolver = new ClassResolver(this); - currentRuntime.set(this); + classResolver = new ClassResolver(this); + currentRuntime.set(this); - runtimeCache.put(this.runtimeId, this); + runtimeCache.put(this.runtimeId, this); - gcListener = GcListener.getInstance(config.appConfig.getGcThrottleTime(), config.appConfig.getMemoryCheckInterval(), config.appConfig.getFreeMemoryRatio()); + gcListener = GcListener.getInstance(config.appConfig.getGcThrottleTime(), config.appConfig.getMemoryCheckInterval(), config.appConfig.getFreeMemoryRatio()); + } finally { + frame.close(); + } } } @@ -449,35 +456,40 @@ private void init(Logger logger, String appName, String nativeLibDir, File rootD throw new RuntimeException("NativeScriptApplication already initialized"); } - this.logger = logger; + ManualInstrumentation.Frame frame = ManualInstrumentation.start("Runtime.init"); + try { + this.logger = logger; - this.dexFactory = new DexFactory(logger, classLoader, dexDir, dexThumb); + this.dexFactory = new DexFactory(logger, classLoader, dexDir, dexThumb); - if (logger.isEnabled()) { - logger.write("Initializing NativeScript JAVA"); - } + if (logger.isEnabled()) { + logger.write("Initializing NativeScript JAVA"); + } - try { - Module.init(logger, rootDir, appDir); - } catch (IOException ex) { - throw new RuntimeException("Fail to initialize Require class", ex); - } + try { + Module.init(logger, rootDir, appDir); + } catch (IOException ex) { + throw new RuntimeException("Fail to initialize Require class", ex); + } - initNativeScript(getRuntimeId(), Module.getApplicationFilesPath(), nativeLibDir, logger.isEnabled(), isDebuggable, appName, appConfig.getAsArray(), callingJsDir); + initNativeScript(getRuntimeId(), Module.getApplicationFilesPath(), nativeLibDir, logger.isEnabled(), isDebuggable, appName, appConfig.getAsArray(), callingJsDir); - clearStartupData(getRuntimeId()); // It's safe to delete the data after the V8 debugger is initialized + clearStartupData(getRuntimeId()); // It's safe to delete the data after the V8 debugger is initialized - if (logger.isEnabled()) { - Date d = new Date(); - int pid = android.os.Process.myPid(); - File f = new File("/proc/" + pid); - Date lastModDate = new Date(f.lastModified()); - logger.write("init time=" + (d.getTime() - lastModDate.getTime())); - } + if (logger.isEnabled()) { + Date d = new Date(); + int pid = android.os.Process.myPid(); + File f = new File("/proc/" + pid); + Date lastModDate = new Date(f.lastModified()); + logger.write("init time=" + (d.getTime() - lastModDate.getTime())); + } - gcListener.subscribe(this); + gcListener.subscribe(this); - initialized = true; + initialized = true; + } finally { + frame.close(); + } } @RuntimeCallable @@ -495,8 +507,13 @@ public void disableVerboseLogging() { } public void run() throws NativeScriptException { - String mainModule = Module.bootstrapApp(); - runModule(new File(mainModule)); + ManualInstrumentation.Frame frame = ManualInstrumentation.start("Runtime.run"); + try { + String mainModule = Module.bootstrapApp(); + runModule(new File(mainModule)); + } finally { + frame.close(); + } } public void runModule(File jsFile) throws NativeScriptException { @@ -568,14 +585,19 @@ public void notifyGc() { } public static void initInstance(Object instance) { - Runtime runtime = Runtime.getCurrentRuntime(); + ManualInstrumentation.Frame frame = ManualInstrumentation.start("Runtime.initInstance"); + try { + Runtime runtime = Runtime.getCurrentRuntime(); - int objectId = runtime.currentObjectId; + int objectId = runtime.currentObjectId; - if (objectId != -1) { - runtime.makeInstanceStrong(instance, objectId); - } else { - runtime.createJSInstance(instance); + if (objectId != -1) { + runtime.makeInstanceStrong(instance, objectId); + } else { + runtime.createJSInstance(instance); + } + } finally { + frame.close(); } } diff --git a/runtime/src/main/jni/ManualInstrumentation.cpp b/runtime/src/main/jni/ManualInstrumentation.cpp new file mode 100644 index 000000000..9486dd325 --- /dev/null +++ b/runtime/src/main/jni/ManualInstrumentation.cpp @@ -0,0 +1,8 @@ +// +// Created by Panayot Cankov on 26/05/2017. +// + +#include "ManualInstrumentation.h" + +bool tns::instrumentation::Frame::disabled = true; +const std::chrono::steady_clock::time_point tns::instrumentation::Frame::disabled_time = std::chrono::steady_clock::now(); diff --git a/runtime/src/main/jni/ManualInstrumentation.h b/runtime/src/main/jni/ManualInstrumentation.h new file mode 100644 index 000000000..51667dc28 --- /dev/null +++ b/runtime/src/main/jni/ManualInstrumentation.h @@ -0,0 +1,66 @@ +// +// Created by Panayot Cankov on 26/05/2017. +// + +#ifndef TEST_APP_MANUALINSTRUMENTATION_H +#define TEST_APP_MANUALINSTRUMENTATION_H + +#include "v8.h" +#import +#import + +namespace tns { + namespace instrumentation { + class Frame { + public: + inline Frame() : Frame(nullptr) { } + inline Frame(const char *name) : name(name), start(disabled ? disabled_time : std::chrono::steady_clock::now()) {} + + inline ~Frame() { + if (name && check()) { + log(name); + } + } + + inline bool check() { + if (disabled) { + return false; + } + std::chrono::steady_clock::time_point end = std::chrono::steady_clock::now(); + auto duration = std::chrono::duration_cast(std::chrono::operator-(end, start)).count(); + return duration >= 16000; + } + + inline void log(const char * message) { + if (disabled) { + return; + } + std::chrono::steady_clock::time_point end = std::chrono::steady_clock::now(); + auto duration = std::chrono::duration_cast(std::chrono::operator-(end, start)).count(); + auto startMilis = std::chrono::time_point_cast(start).time_since_epoch().count() / 1000.0; + auto endMilis = std::chrono::time_point_cast(end).time_since_epoch().count() / 1000.0; + __android_log_print(ANDROID_LOG_DEBUG, "JS", "Timeline: %.3fms: Runtime: %s (%.3fms - %.3fms)", duration / 1000.0, message, startMilis, endMilis); + } + + static inline void enable() { disabled = false; } + static inline void disable() { disabled = true; } + + private: + static bool disabled; + static const std::chrono::steady_clock::time_point disabled_time; // Couldn't find reasonable constant + + const std::chrono::steady_clock::time_point start; + const char *name; + + Frame(const Frame &) = delete; + Frame &operator=(const Frame &) = delete; + }; + }; +}; + +/** + * Place at the start of a method. Will log to android using the "JS" tag methods that execute relatively slow. + */ +#define TNSPERF() tns::instrumentation::Frame __tns_manual_instrumentation(__func__) + +#endif //TEST_APP_MANUALINSTRUMENTATION_H diff --git a/runtime/src/main/jni/MetadataNode.cpp b/runtime/src/main/jni/MetadataNode.cpp index cd530a484..0a6f28125 100644 --- a/runtime/src/main/jni/MetadataNode.cpp +++ b/runtime/src/main/jni/MetadataNode.cpp @@ -11,6 +11,7 @@ #include "Runtime.h" #include #include +#include "ManualInstrumentation.h" #include "v8.h" @@ -681,6 +682,7 @@ Local MetadataNode::GetConstructorFunctionTemplate(Isolate* is Local MetadataNode::GetConstructorFunctionTemplate(Isolate* isolate, MetadataTreeNode* treeNode, vector& instanceMethodsCallbackData) { SET_PROFILER_FRAME(); + tns::instrumentation::Frame frame; //try get cached "ctorFuncTemplate" Local ctorFuncTemplate; @@ -753,6 +755,11 @@ Local MetadataNode::GetConstructorFunctionTemplate(Isolate* is SetTypeMetadata(isolate, wrappedCtorFunc, new TypeMetadata(s_metadataReader.ReadTypeName(treeNode))); + if (frame.check()) { + std::string log = "Materizlizing class: " + node->m_name; + frame.log(log.c_str()); + } + return ctorFuncTemplate; } @@ -807,6 +814,7 @@ void MetadataNode::SetInstanceMetadata(Isolate* isolate, Local object, M } void MetadataNode::ExtendedClassConstructorCallback(const v8::FunctionCallbackInfo& info) { + TNSPERF(); try { SET_PROFILER_FRAME(); @@ -843,6 +851,7 @@ void MetadataNode::ExtendedClassConstructorCallback(const v8::FunctionCallbackIn } void MetadataNode::InterfaceConstructorCallback(const v8::FunctionCallbackInfo& info) { + tns::instrumentation::Frame frame; try { SET_PROFILER_FRAME(); @@ -885,6 +894,11 @@ void MetadataNode::InterfaceConstructorCallback(const v8::FunctionCallbackInfom_name; + frame.log(msg.c_str()); + } } catch (NativeScriptException& e) { e.ReThrowToV8(); } catch (std::exception e) { @@ -899,6 +913,7 @@ void MetadataNode::InterfaceConstructorCallback(const v8::FunctionCallbackInfo& info) { + TNSPERF(); try { SET_PROFILER_FRAME(); @@ -1041,6 +1056,7 @@ void MetadataNode::ArrayIndexedPropertySetterCallback(uint32_t index, Local MetadataNode::GetImplementationObject(Isolate* isolate, const Local& object) { + TNSPERF(); DEBUG_WRITE("GetImplementationObject called on object:%d", object->GetIdentityHash()); auto target = object; @@ -1247,6 +1263,7 @@ string MetadataNode::CreateFullClassName(const std::string& className, const std } void MetadataNode::ExtendMethodCallback(const v8::FunctionCallbackInfo& info) { + tns::instrumentation::Frame frame; try { if (info.IsConstructCall()) { string exMsg("Can't call 'extend' as constructor"); @@ -1358,6 +1375,11 @@ void MetadataNode::ExtendMethodCallback(const v8::FunctionCallbackInfoExtendedCtorFuncCache.insert(make_pair(fullExtendedName, cacheData)); + + if (frame.check()) { + std::string msg = "Extending: " + node->m_name; + frame.log(msg.c_str()); + } } catch (NativeScriptException& e) { e.ReThrowToV8(); } catch (std::exception e) { diff --git a/runtime/src/main/jni/ModuleInternal.cpp b/runtime/src/main/jni/ModuleInternal.cpp index 63e2dfe5e..6860beab2 100644 --- a/runtime/src/main/jni/ModuleInternal.cpp +++ b/runtime/src/main/jni/ModuleInternal.cpp @@ -16,6 +16,7 @@ #include "SimpleProfiler.h" #include "include/v8.h" #include "CallbackHandlers.h" +#include "ManualInstrumentation.h" #include #include #include @@ -92,6 +93,7 @@ void ModuleInternal::Init(Isolate* isolate, const string& baseDir) { } Local ModuleInternal::GetRequireFunction(Isolate* isolate, const string& dirName) { + TNSPERF(); Local requireFunc; auto itFound = m_requireCache.find(dirName); @@ -155,6 +157,8 @@ void ModuleInternal::RequireCallbackImpl(const v8::FunctionCallbackInfo()); + string frameName("RequireCallback " + moduleName); + tns::instrumentation::Frame frame(frameName.c_str()); string callingModuleDirName = ArgConverter::ConvertToString(args[1].As()); auto isData = false; @@ -174,12 +178,14 @@ void ModuleInternal::RequireCallbackImpl(const v8::FunctionCallbackInfo& args) { + TNSPERF(); auto ext = args.Data().As(); auto funcPtr = reinterpret_cast(ext->Value()); funcPtr(args); } void ModuleInternal::Load(const string& path) { + TNSPERF(); auto isolate = m_isolate; auto context = isolate->GetCurrentContext(); auto globalObject = context->Global(); @@ -189,6 +195,7 @@ void ModuleInternal::Load(const string& path) { } void ModuleInternal::LoadWorker(const string& path) { + TNSPERF(); auto isolate = m_isolate; TryCatch tc; @@ -257,6 +264,8 @@ Local ModuleInternal::LoadImpl(Isolate* isolate, const string& moduleNam } Local ModuleInternal::LoadModule(Isolate* isolate, const string& modulePath, const string& moduleCacheKey) { + string frameName("LoadModule " + modulePath); + tns::instrumentation::Frame frame(frameName.c_str()); Local result; auto moduleObj = Object::New(isolate); @@ -341,6 +350,8 @@ Local ModuleInternal::LoadModule(Isolate* isolate, const string& moduleP } Local