From 33e4387c4327dffb94c8037798aa99f305f7edc2 Mon Sep 17 00:00:00 2001 From: Hannes Janetzek Date: Wed, 21 Nov 2018 14:14:41 +0100 Subject: [PATCH 1/2] Time logger functions --- core/include/tangram/log.h | 42 ++++++++++++++++++++++++++++++++++++++ core/src/platform.cpp | 3 +++ 2 files changed, 45 insertions(+) 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/platform.cpp b/core/src/platform.cpp index a0b84d3f01..fb9d6cbd78 100644 --- a/core/src/platform.cpp +++ b/core/src/platform.cpp @@ -4,6 +4,9 @@ #include #include +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) {} From 01cf8a5f422d3ca429a261ee8b7c0b9b0d4c24c3 Mon Sep 17 00:00:00 2001 From: Hannes Janetzek Date: Wed, 21 Nov 2018 14:17:25 +0100 Subject: [PATCH 2/2] Timing from scene load to complete view --- core/src/data/networkDataSource.cpp | 6 ++++-- core/src/map.cpp | 8 ++++++++ core/src/tile/tileWorker.cpp | 5 +++-- platforms/common/urlClient.cpp | 5 +++-- 4 files changed, 18 insertions(+), 6 deletions(-) diff --git a/core/src/data/networkDataSource.cpp b/core/src/data/networkDataSource.cpp index ffeab7213d..c01c3bd2b0 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 e40879b78e..1241ebaa1a 100644 --- a/core/src/map.cpp +++ b/core/src/map.cpp @@ -184,6 +184,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); @@ -250,6 +251,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](){ @@ -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/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/common/urlClient.cpp b/platforms/common/urlClient.cpp index 724ba8100d..c8fb814e29 100644 --- 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.