From 2dd1c6c8ebe8a212188b5a6c41908ea360dd3286 Mon Sep 17 00:00:00 2001 From: Myk Melez Date: Mon, 11 May 2015 23:05:13 -0700 Subject: [PATCH 1/5] add warm startup profiling mode --- README.md | 20 +++++--------------- main.js | 1 + midp/background.js | 2 ++ midp/gfx.js | 2 +- 4 files changed, 9 insertions(+), 16 deletions(-) diff --git a/README.md b/README.md index d6f5e107..ccbc8876 100644 --- a/README.md +++ b/README.md @@ -190,21 +190,9 @@ To use them, just add calls to `runtimeCounter.count(name, count = 1)`. To view } ``` -The second, more heavy weight profiling tool is Shumway's timeline profiler. The profiler records `enter` / `leave` events in a large circular buffer that can be later displayed visually as a flame chart or saved in a text format. To use it, build j2me.js with `PROFILE=[1|2]`. +The second, more heavy weight profiling tool is Shumway's timeline profiler. The profiler records `enter` / `leave` events in a large circular buffer that can be later displayed visually as a flame chart or saved in a text format. To use it, build j2me.js with `PROFILE=[1|2|3]`. Then wrap code regions that you're interested in measuring with calls to `timeline.enter` / `timeline.leave`. -Next, you will need to wrap code regions that you're interested in measuring with calls to `timeline.enter` / `timeline.leave`. - -If you want to record every Java method call, change the line in `runtime.ts` from: - -``` -if (false && methodTimeline) { -``` -to -``` -if (methodTimeline) { -``` - -This will wrap all methods with calls to `methodTimeline.enter` / `methodTimeline.leave`. The resulting timeline is a very detailed trace of the application's execution. Note that this instrumentation has some overhead, and timing information of very short lived events may not be accurate and can lead to the entire application slowing down. +Java methods are automatically wrapped with calls to `methodTimeline.enter` / `methodTimeline.leave`. The resulting timeline is a very detailed trace of the application's execution. Note that this instrumentation has some overhead, and timing information of very short lived events may not be accurate and can lead to the entire application slowing down. Similar to the way counters work, you can get creative with the timeline profiler. The API looks something like this: @@ -239,7 +227,9 @@ The tooltip displays: - `all total` and `all self`: cumulative total and self times for all events with this name. - the remaining fields show the custom data specified in the `details` object. -If you build with `PROFILE=2` the timeline will be saved to a text file instead of shown in the flame chart. On desktop, you will be prompted to save the file. On the phone, the file will automatically be saved to `/sdcard/downloads/profile.txt` which you can later pull with `adb pull`. Note that no timeline events under 0.1 ms are written to the file output. You can change this in `main.js` if you'd like. +If you build with `PROFILE=2` or `PROFILE=3`, then the timeline will be saved to a text file instead of being shown in the flame chart. On desktop, you will be prompted to save the file. On the phone, the file will automatically be saved to `/sdcard/downloads/profile.txt`, which you can later pull with `adb pull`. Note that no timeline events under 0.1 ms are written to the file output. You can change this in `main.js` if you'd like. + +`PROFILE=1` and `PROFILE=2` automatically profile (most of) cold startup, from *JVM.startIsolate0* to *DisplayDevice.gainedForeground0*; while `PROFILE=3` profiles warm startup, from *BGUtils.maybeWaitUserInteraction* to *DisplayDevice.gainedForeground0*. ## Benchmarks diff --git a/main.js b/main.js index 67923893..fb8d9635 100644 --- a/main.js +++ b/main.js @@ -150,6 +150,7 @@ function toggle(button) { } var bigBang = 0; +var profiling = false; function startTimeline() { jsGlobal.START_TIME = performance.now(); diff --git a/midp/background.js b/midp/background.js index c0f06fca..69526a98 100644 --- a/midp/background.js +++ b/midp/background.js @@ -91,6 +91,7 @@ Native["com/nokia/mid/s40/bg/BGUtils.maybeWaitUserInteraction.(Ljava/lang/String // If the page is visible, just start the FG MIDlet if (!document.hidden) { + profile === 3 && startTimeline(); showSplashScreen(); hideBackgroundScreen(); return; @@ -105,6 +106,7 @@ Native["com/nokia/mid/s40/bg/BGUtils.maybeWaitUserInteraction.(Ljava/lang/String } }, false); }).then(function() { + profile === 3 && startTimeline(); showSplashScreen(); hideBackgroundScreen(); })); diff --git a/midp/gfx.js b/midp/gfx.js index 7f6ad62f..d17708d7 100644 --- a/midp/gfx.js +++ b/midp/gfx.js @@ -72,7 +72,7 @@ var currentlyFocusedTextEditor; asyncImpl("V", emoji.loadData()); - if (profile === 2) { + if (profile === 2 || profile === 3) { // Use setTimeout to make sure our profiling enter/leave stack is not unpaired. setTimeout(function () { stopAndSaveTimeline(); From 93e8fa599f7e524562d924fa0945385446ef53d2 Mon Sep 17 00:00:00 2001 From: Myk Melez Date: Mon, 11 May 2015 23:35:17 -0700 Subject: [PATCH 2/5] add dependency on shumway if profiler enabled --- Makefile | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/Makefile b/Makefile index f6015e6a..e035f127 100644 --- a/Makefile +++ b/Makefile @@ -53,12 +53,15 @@ export JSR_082 JSR_179 ?= 1 export JSR_179 -# Closure optimization level J2ME_OPTIMIZATIONS breaks the profiler somehow, -# so we revert to level SIMPLE if the profiler is enabled. ifeq ($(PROFILE),0) J2ME_JS_OPTIMIZATION_LEVEL = J2ME_OPTIMIZATIONS else + # Closure optimization level J2ME_OPTIMIZATIONS breaks the profiler somehow, + # so we revert to level SIMPLE if the profiler is enabled. J2ME_JS_OPTIMIZATION_LEVEL = SIMPLE + + # Various build targets depend on shumway when the profiler is enabled. + PROFILE_DEP = shumway endif # Closure is really chatty, so we shush it by default to reduce log lines @@ -161,7 +164,7 @@ PREPROCESS = python tools/preprocess-1.1.0/lib/preprocess.py -s \ PREPROCESS_SRCS = $(shell find . -name "*.in" -not -path config/build.js.in) PREPROCESS_DESTS = $(PREPROCESS_SRCS:.in=) -all: config-build java jasmin tests j2me shumway aot benchmarks bld/main-all.js +all: config-build java jasmin tests j2me shumway aot benchmarks bld/main-all.js $(PROFILE_DEP) $(shell mkdir -p build_tools) @@ -314,7 +317,7 @@ img/icon-512.png: $(ICON_512) icon: img/icon-128.png img/icon-512.png # Makes an output/ directory containing the packaged open web app files. -app: config-build java certs j2me aot bld/main-all.js icon $(TESTS_JAR) +app: config-build java certs j2me aot bld/main-all.js icon $(TESTS_JAR) $(PROFILE_DEP) tools/package.sh package: app From 0a99df50605f0cc63ff51a83e666b238b5555cb5 Mon Sep 17 00:00:00 2001 From: Myk Melez Date: Tue, 12 May 2015 09:13:46 -0700 Subject: [PATCH 3/5] dedupe shumway dependency of all target --- Makefile | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/Makefile b/Makefile index e035f127..795cd230 100644 --- a/Makefile +++ b/Makefile @@ -60,7 +60,7 @@ else # so we revert to level SIMPLE if the profiler is enabled. J2ME_JS_OPTIMIZATION_LEVEL = SIMPLE - # Various build targets depend on shumway when the profiler is enabled. + # Add dependency on shumway when the profiler is enabled. PROFILE_DEP = shumway endif @@ -164,7 +164,7 @@ PREPROCESS = python tools/preprocess-1.1.0/lib/preprocess.py -s \ PREPROCESS_SRCS = $(shell find . -name "*.in" -not -path config/build.js.in) PREPROCESS_DESTS = $(PREPROCESS_SRCS:.in=) -all: config-build java jasmin tests j2me shumway aot benchmarks bld/main-all.js $(PROFILE_DEP) +all: config-build java jasmin tests j2me shumway aot benchmarks bld/main-all.js $(shell mkdir -p build_tools) From 16addc27f3338f784d26af4b1a76f8a1fcea791e Mon Sep 17 00:00:00 2001 From: Myk Melez Date: Tue, 12 May 2015 15:24:36 -0700 Subject: [PATCH 4/5] use timeout to imitate warm startup better for profiler --- midp/background.js | 19 +++++++++++++++++-- 1 file changed, 17 insertions(+), 2 deletions(-) diff --git a/midp/background.js b/midp/background.js index 69526a98..f1fb502b 100644 --- a/midp/background.js +++ b/midp/background.js @@ -91,9 +91,24 @@ Native["com/nokia/mid/s40/bg/BGUtils.maybeWaitUserInteraction.(Ljava/lang/String // If the page is visible, just start the FG MIDlet if (!document.hidden) { - profile === 3 && startTimeline(); showSplashScreen(); hideBackgroundScreen(); + + if (profile === 3) { + // Start the "warm startup" profiler after a timeout to better imitate + // what happens in a warm startup. Even with this timeout, the profile + // won't be very accurate, and you should profile warm startup by letting + // the app start in the background, waiting until the background midlet + // settles down, and then opening the app. + console.warn("imitating warm startup time for profiler"); + asyncImpl("V", new Promise(function(resolve, reject) { + setTimeout(function() { + startTimeline(); + resolve(); + }, 0); + })); + } + return; } @@ -106,9 +121,9 @@ Native["com/nokia/mid/s40/bg/BGUtils.maybeWaitUserInteraction.(Ljava/lang/String } }, false); }).then(function() { - profile === 3 && startTimeline(); showSplashScreen(); hideBackgroundScreen(); + profile === 3 && startTimeline(); })); }; From cf72a04fec2090b6e16b19e2493a5d2a39bffa6c Mon Sep 17 00:00:00 2001 From: Myk Melez Date: Tue, 12 May 2015 16:19:49 -0700 Subject: [PATCH 5/5] start profiler after longer timeout to give bg midlet time to settle --- midp/background.js | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/midp/background.js b/midp/background.js index f1fb502b..5e66e2c0 100644 --- a/midp/background.js +++ b/midp/background.js @@ -96,16 +96,12 @@ Native["com/nokia/mid/s40/bg/BGUtils.maybeWaitUserInteraction.(Ljava/lang/String if (profile === 3) { // Start the "warm startup" profiler after a timeout to better imitate - // what happens in a warm startup. Even with this timeout, the profile - // won't be very accurate, and you should profile warm startup by letting - // the app start in the background, waiting until the background midlet - // settles down, and then opening the app. - console.warn("imitating warm startup time for profiler"); + // what happens in a warm startup, where the bg midlet has time to settle. asyncImpl("V", new Promise(function(resolve, reject) { setTimeout(function() { startTimeline(); resolve(); - }, 0); + }, 5000); })); }