diff --git a/core/include/tangram/log.h b/core/include/tangram/log.h index be7c148234..8e1f531eed 100644 --- a/core/include/tangram/log.h +++ b/core/include/tangram/log.h @@ -66,3 +66,45 @@ do { Tangram::logMsg("ERROR %s:%d: " fmt "\n", __FILENAME__, __LINE__, ## __VA_A #define LOG(fmt, ...) #define LOGN(fmt, ...) #endif + +#include +#include + +extern std::chrono::time_point tangram_log_time_start, tangram_log_time_last; +extern std::mutex tangram_log_time_mutex; + +#define LOGTIME(fmt, ...) do { \ + int l = strlen( __FILENAME__); \ + Tangram::logMsg("TIME %-18.*s " fmt "\n", \ + l > 4 ? l-4 : l, __FILENAME__, ##__VA_ARGS__); } while (0) + +// Overall timing init/reset +#define LOGTOInit() do { \ + std::lock_guard lock(tangram_log_time_mutex); \ + tangram_log_time_last = tangram_log_time_start = std::chrono::system_clock::now(); } while(0) + +// Overall timing +#define LOGTO(fmt, ...) do { \ + std::lock_guard lock(tangram_log_time_mutex); \ + std::chrono::time_point now = std::chrono::system_clock::now(); \ + std::chrono::duration t1 = now - tangram_log_time_start; \ + std::chrono::duration t2 = now - tangram_log_time_last; \ + tangram_log_time_last = now; \ + LOGTIME("%7.2f %7.2f " fmt, t1.count()*1000.f, t2.count()*1000.f, ## __VA_ARGS__); } while(0) + +// Local timing init +#define LOGTInit(fmt, ...) \ + std::chrono::time_point _time_last, _time_start; \ + std::chrono::time_point now = std::chrono::system_clock::now(); \ + std::chrono::duration t0 = now - tangram_log_time_start; \ + _time_start = _time_last = now; \ + LOGTIME("%7.2f " fmt, t0.count()*1000.f, ## __VA_ARGS__) + +// Local timing +#define LOGT(fmt, ...) do { \ + std::chrono::time_point now = std::chrono::system_clock::now(); \ + std::chrono::duration t0 = now - tangram_log_time_start; \ + std::chrono::duration t1 = now - _time_start; \ + std::chrono::duration t2 = now - _time_last; \ + _time_last = now; \ + LOGTIME("%7.2f %7.2f %7.2f " fmt, t0.count()*1000.f, t1.count()*1000.f, t2.count()*1000.f, ## __VA_ARGS__); } while(0) diff --git a/core/src/data/networkDataSource.cpp b/core/src/data/networkDataSource.cpp index eba3498929..3feece3124 100644 --- a/core/src/data/networkDataSource.cpp +++ b/core/src/data/networkDataSource.cpp @@ -58,13 +58,15 @@ bool NetworkDataSource::loadTileData(std::shared_ptr task, TileTaskCb m_urlSubdomainIndex = (m_urlSubdomainIndex + 1) % m_urlSubdomains.size(); } - UrlCallback onRequestFinish = [callback, task, url](UrlResponse&& response) { - + LOGTInit(">>> %s", task->tileId().toString().c_str()); + UrlCallback onRequestFinish = [=](UrlResponse&& response) mutable { auto source = task->source(); if (!source) { LOGW("URL Callback for deleted TileSource '%s'", url.string().c_str()); return; } + LOGT("<<< %s -- canceled:%d", task->tileId().toString().c_str(), task->isCanceled()); + if (task->isCanceled()) { return; } diff --git a/core/src/map.cpp b/core/src/map.cpp index bc09ed6ea6..d6578931a8 100644 --- a/core/src/map.cpp +++ b/core/src/map.cpp @@ -193,6 +193,7 @@ void Map::Impl::setScene(std::shared_ptr& _scene) { SceneID Map::loadScene(std::shared_ptr scene, const std::vector& _sceneUpdates) { + LOGTOInit(); { std::unique_lock lock(impl->sceneMutex); @@ -259,6 +260,7 @@ SceneID Map::loadSceneYamlAsync(const std::string& _yaml, const std::string& _re SceneID Map::loadSceneAsync(std::shared_ptr nextScene, const std::vector& _sceneUpdates) { + LOGTOInit(); impl->sceneLoadBegin(); runAsyncTask([nextScene, _sceneUpdates, this](){ @@ -401,6 +403,8 @@ bool Map::update(float _dt) { // Wait until font and texture resources are fully loaded if (impl->scene->pendingFonts > 0 || impl->scene->pendingTextures > 0) { platform->requestRender(); + LOGTO("Waiting for Scene fonts:%d textures:%d", + impl->scene->pendingFonts.load(), impl->scene->pendingTextures.load()); return false; } @@ -476,6 +480,10 @@ bool Map::update(float _dt) { platform->requestRender(); } + LOGTO("View complete:%d vc:%d tl:%d tc:%d easing:%d label:%d maker:%d ", + viewComplete, viewChanged, tilesLoading, tilesChanged, + impl->isCameraEasing, labelsNeedUpdate, markersNeedUpdate); + return viewComplete; } diff --git a/core/src/platform.cpp b/core/src/platform.cpp index 51f55f3de9..2af5bf4859 100644 --- a/core/src/platform.cpp +++ b/core/src/platform.cpp @@ -8,6 +8,9 @@ constexpr char const* shutdown_message = "Shutting down"; constexpr char const* cancel_message = "Request canceled"; +std::chrono::time_point tangram_log_time_start, tangram_log_time_last; +std::mutex tangram_log_time_mutex; + namespace Tangram { Platform::Platform() : m_continuousRendering(false) {} diff --git a/core/src/tile/tileWorker.cpp b/core/src/tile/tileWorker.cpp index 83d5bedeb1..18391125a9 100644 --- a/core/src/tile/tileWorker.cpp +++ b/core/src/tile/tileWorker.cpp @@ -48,7 +48,7 @@ void TileWorker::run(Worker* instance) { if (instance->tileBuilder) { builder = std::move(instance->tileBuilder); - LOG("Passed new TileBuilder to TileWorker"); + LOGTO("Passed new TileBuilder to TileWorker"); } // Check if thread should stop @@ -90,8 +90,9 @@ void TileWorker::run(Worker* instance) { if (task->isCanceled()) { continue; } - + LOGTInit(">>> %s", task->tileId().toString().c_str()); task->process(*builder); + LOGT("<<< %s", task->tileId().toString().c_str()); m_platform->requestRender(); } diff --git a/platforms/android/demo/build.gradle b/platforms/android/demo/build.gradle index 3a59dd1e9d..e7e68f24d1 100644 --- a/platforms/android/demo/build.gradle +++ b/platforms/android/demo/build.gradle @@ -1,5 +1,7 @@ apply plugin: 'com.android.application' +apply from: 'profiling.gradle' + android { compileSdkVersion 27 @@ -26,7 +28,6 @@ android { minifyEnabled true } } - } dependencies { diff --git a/platforms/android/demo/profiling.gradle b/platforms/android/demo/profiling.gradle new file mode 100644 index 0000000000..f4c05d19c7 --- /dev/null +++ b/platforms/android/demo/profiling.gradle @@ -0,0 +1,57 @@ + +// Set when building only part of the abis in the apk. +def abiFiltersForWrapScript = [] + +android { + buildTypes { + profiling { + initWith debug + externalNativeBuild { + cmake { + // cmake Debug build type uses -O0, which makes the code slow. + arguments "-DCMAKE_BUILD_TYPE=Release" + } + } + packagingOptions { + // Exclude wrap.sh for architectures not built. + if (abiFiltersForWrapScript) { + def exclude_abis = ["armeabi", "armeabi-v7a", "arm64-v8a", + "x86", "x86_64", "mips", "mips64"] + .findAll{ !(it in abiFiltersForWrapScript) } + .collect{ "**/" + it + "/wrap.sh" } + excludes += exclude_abis + } + } + + // Add lib/xxx/wrap.sh in the apk. This is to enable java profiling on Android O + // devices. + sourceSets { + profiling { + resources { + srcDir { + "profiling_apk_add_dir" + } + } + } + } + } + } +} + +def writeWrapScriptToFullyCompileJavaApp(wrapFile) { + wrapFile.withWriter { writer -> + writer.write('#!/system/bin/sh\n') + writer.write('\$@\n') + } +} + +task createProfilingApkAddDir { + for (String abi : ["armeabi", "armeabi-v7a", "arm64-v8a", "x86", "x86_64", "mips", "mips64"]) { + def dir = new File("app/profiling_apk_add_dir/lib/" + abi) + dir.mkdirs() + def wrapFile = new File(dir, "wrap.sh") + writeWrapScriptToFullyCompileJavaApp(wrapFile) + println "write file " + wrapFile.path + } +} + diff --git a/platforms/android/profiling.md b/platforms/android/profiling.md new file mode 100644 index 0000000000..a3e2dc4ea2 --- /dev/null +++ b/platforms/android/profiling.md @@ -0,0 +1,12 @@ +# Android + +- https://android.googlesource.com/platform/system/extras/+/master/simpleperf/doc/ +- https://android.googlesource.com/platform/system/extras/+/master/simpleperf/demo/README.md#profiling-javac-application + +## Studio + +- Run 'Profile selected configuration' +- Click CPU row +- Select 'Sampled (Native)' +- Click 'Record a method trace', right next to it +- Select thread of interest to show Call-/Flame-chart diff --git a/platforms/android/tangram/build.gradle b/platforms/android/tangram/build.gradle index eaeca58fd2..78ef38e44e 100644 --- a/platforms/android/tangram/build.gradle +++ b/platforms/android/tangram/build.gradle @@ -5,6 +5,7 @@ group = GROUP version = VERSION_NAME apply from: 'versioning.gradle' +apply from: 'profiling.gradle' android { compileSdkVersion 27 @@ -27,7 +28,8 @@ android { cmake { targets 'tangram' arguments '-DTANGRAM_PLATFORM=android', - '-DANDROID_STL=c++_shared' + '-DANDROID_STL=c++_shared', + '-DCMAKE_BUILD_TYPE=Release' cppFlags '-std=c++14', '-fvisibility=hidden', // export only JNIEXPORT '-pedantic', diff --git a/platforms/android/tangram/profiling.gradle b/platforms/android/tangram/profiling.gradle new file mode 100644 index 0000000000..c215362491 --- /dev/null +++ b/platforms/android/tangram/profiling.gradle @@ -0,0 +1,58 @@ + +// Set when building only part of the abis in the apk. +def abiFiltersForWrapScript = [] + +android { + buildTypes { + profiling { + initWith debug + externalNativeBuild { + cmake { + // cmake Debug build type uses -O0, which makes the code slow. + arguments "-DCMAKE_BUILD_TYPE=Release" + cppFlags '-fno-omit-frame-pointer' + } + } + packagingOptions { + // Exclude wrap.sh for architectures not built. + if (abiFiltersForWrapScript) { + def exclude_abis = ["armeabi", "armeabi-v7a", "arm64-v8a", + "x86", "x86_64", "mips", "mips64"] + .findAll{ !(it in abiFiltersForWrapScript) } + .collect{ "**/" + it + "/wrap.sh" } + excludes += exclude_abis + } + } + + // Add lib/xxx/wrap.sh in the apk. This is to enable java profiling on Android O + // devices. + sourceSets { + profiling { + resources { + srcDir { + "profiling_apk_add_dir" + } + } + } + } + } + } +} + +def writeWrapScriptToFullyCompileJavaApp(wrapFile) { + wrapFile.withWriter { writer -> + writer.write('#!/system/bin/sh\n') + writer.write('\$@\n') + } +} + +task createProfilingApkAddDir { + for (String abi : ["armeabi", "armeabi-v7a", "arm64-v8a", "x86", "x86_64", "mips", "mips64"]) { + def dir = new File("app/profiling_apk_add_dir/lib/" + abi) + dir.mkdirs() + def wrapFile = new File(dir, "wrap.sh") + writeWrapScriptToFullyCompileJavaApp(wrapFile) + println "write file " + wrapFile.path + } +} + diff --git a/platforms/common/urlClient.cpp b/platforms/common/urlClient.cpp index a5b197fd04..16c56e2618 100644 --- a/platforms/common/urlClient.cpp +++ b/platforms/common/urlClient.cpp @@ -170,7 +170,7 @@ void UrlClient::curlLoop(uint32_t index) { // Configure the easy handle. const char* url = task.request.url.data(); curl_easy_setopt(handle, CURLOPT_URL, url); - LOGD("curlLoop %u starting request for url: %s", index, url); + LOGTInit("[%u] Starting request: %s", index, url); // Perform the request. auto result = curl_easy_perform(handle); // Handle success or error. @@ -186,9 +186,10 @@ void UrlClient::curlLoop(uint32_t index) { } // If a callback is given, always run it regardless of request result. if (task.request.callback) { - LOGD("curlLoop %u performing request callback", index); + LOGT("[%u] Finished request", index); response.content = task.content; task.request.callback(std::move(response)); + LOGT("[%u] Ran callback", index); } } // Reset the task.