Merge branch 'time-logging' into scene-refactor-base

tangrams · Dec 19, 2018 · 0e5eb01 · 0e5eb01
2 parents b50a6aa + 01cf8a5
commit 0e5eb01
Show file tree

Hide file tree

Showing 6 changed files with 63 additions and 6 deletions.
diff --git 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 <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)
diff --git a/core/src/data/networkDataSource.cpp b/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;
         }

diff --git a/core/src/map.cpp b/core/src/map.cpp
@@ -184,6 +184,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);
 
@@ -250,6 +251,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](){
@@ -392,6 +394,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;
     }
 
@@ -467,6 +471,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
@@ -4,6 +4,9 @@
 #include <fstream>
 #include <string>
 
+std::chrono::time_point<std::chrono::system_clock> 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
@@ -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/common/urlClient.cpp b/platforms/common/urlClient.cpp
@@ -168,7 +168,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.
@@ -184,9 +184,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.