Time logging

core/include/tangram/log.h

@@ -66,3 +66,52 @@ do { Tangram::logMsg("ERROR %s:%d: " fmt "\n", __FILENAME__, __LINE__, ## __VA_A
 #define LOG(fmt, ...)
 #define LOGN(fmt, ...)
 #endif
+
+#if 1
+#include <mutex>
+#include <chrono>
+
+extern std::chrono::time_point<std::chrono::system_clock> 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<std::mutex> 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<std::mutex> lock(tangram_log_time_mutex);       \
+        std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
+        std::chrono::duration<double> t1 = now - tangram_log_time_start; \
+        std::chrono::duration<double> 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<std::chrono::system_clock> _time_last, _time_start; \
+    std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
+    std::chrono::duration<double> 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<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
+        std::chrono::duration<double> t0 = now - tangram_log_time_start; \
+        std::chrono::duration<double> t1 = now - _time_start;           \
+        std::chrono::duration<double> 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)
+#else
+#define LOGT(...)
+#define LOGTInit(...)
+#define LOGTOInit()
+#define LOGTO(...)
+#endif

core/src/data/networkDataSource.cpp

@@ -58,13 +58,15 @@ bool NetworkDataSource::loadTileData(std::shared_ptr<TileTask> 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;
         }

core/src/map.cpp

@@ -193,6 +193,7 @@ void Map::Impl::setScene(std::shared_ptr<Scene>& _scene) {
 SceneID Map::loadScene(std::shared_ptr<Scene> scene,
                        const std::vector<SceneUpdate>& _sceneUpdates) {
 
+    LOGTOInit();
     {
         std::unique_lock<std::mutex> lock(impl->sceneMutex);
 
@@ -259,6 +260,7 @@ SceneID Map::loadSceneYamlAsync(const std::string& _yaml, const std::string& _re
 SceneID Map::loadSceneAsync(std::shared_ptr<Scene> nextScene,
                             const std::vector<SceneUpdate>& _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;
 }
 

core/src/platform.cpp

@@ -5,6 +5,11 @@
 #include <string>
 #include <cassert>
 
+#ifdef LOGTIME
+std::chrono::time_point<std::chrono::system_clock> tangram_log_time_start, tangram_log_time_last;
+std::mutex tangram_log_time_mutex;
+#endif
+
 constexpr char const* shutdown_message = "Shutting down";
 constexpr char const* cancel_message = "Request canceled";
 

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();
     }

platforms/android/demo/build.gradle

@@ -1,5 +1,7 @@
 apply plugin: 'com.android.application'
 
+apply from: 'profiling.gradle'
+
 android {
   compileSdkVersion 28
 
@@ -26,7 +28,6 @@ android {
       minifyEnabled true
     }
   }
-
 }
 
 dependencies {

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
+    }
+}
+

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

platforms/android/tangram/build.gradle

@@ -5,6 +5,7 @@ group = GROUP
 version = VERSION_NAME
 
 apply from: 'versioning.gradle'
+apply from: 'profiling.gradle'
 
 android {
   compileSdkVersion 28
@@ -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',

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
+    }
+}
+

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.