Skip to content

Commit a3db120

Browse files
hjanetzekhjanetzek
committed
Merge branch 'time-logging' into scene-refactor-base
2 parents 2d4c33c + ef9b15c commit a3db120

File tree

6 files changed

+63
-6
lines changed

6 files changed

+63
-6
lines changed

‎core/include/tangram/log.h

+42
Original file line numberDiff line numberDiff line change
@@ -66,3 +66,45 @@ do { Tangram::logMsg("ERROR %s:%d: " fmt "\n", __FILENAME__, __LINE__, ## __VA_A
6666
#define LOG(fmt, ...)
6767
#define LOGN(fmt, ...)
6868
#endif
69+
70+
#include <mutex>
71+
#include <chrono>
72+
73+
extern std::chrono::time_point<std::chrono::system_clock> tangram_log_time_start, tangram_log_time_last;
74+
extern std::mutex tangram_log_time_mutex;
75+
76+
#define LOGTIME(fmt, ...) do { \
77+
int l = strlen( __FILENAME__); \
78+
Tangram::logMsg("TIME %-18.*s " fmt "\n", \
79+
l > 4 ? l-4 : l, __FILENAME__, ##__VA_ARGS__); } while (0)
80+
81+
// Overall timing init/reset
82+
#define LOGTOInit() do { \
83+
std::lock_guard<std::mutex> lock(tangram_log_time_mutex); \
84+
tangram_log_time_last = tangram_log_time_start = std::chrono::system_clock::now(); } while(0)
85+
86+
// Overall timing
87+
#define LOGTO(fmt, ...) do { \
88+
std::lock_guard<std::mutex> lock(tangram_log_time_mutex); \
89+
std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
90+
std::chrono::duration<double> t1 = now - tangram_log_time_start; \
91+
std::chrono::duration<double> t2 = now - tangram_log_time_last; \
92+
tangram_log_time_last = now; \
93+
LOGTIME("%7.2f %7.2f " fmt, t1.count()*1000.f, t2.count()*1000.f, ## __VA_ARGS__); } while(0)
94+
95+
// Local timing init
96+
#define LOGTInit(fmt, ...) \
97+
std::chrono::time_point<std::chrono::system_clock> _time_last, _time_start; \
98+
std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
99+
std::chrono::duration<double> t0 = now - tangram_log_time_start; \
100+
_time_start = _time_last = now; \
101+
LOGTIME("%7.2f " fmt, t0.count()*1000.f, ## __VA_ARGS__)
102+
103+
// Local timing
104+
#define LOGT(fmt, ...) do { \
105+
std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
106+
std::chrono::duration<double> t0 = now - tangram_log_time_start; \
107+
std::chrono::duration<double> t1 = now - _time_start; \
108+
std::chrono::duration<double> t2 = now - _time_last; \
109+
_time_last = now; \
110+
LOGTIME("%7.2f %7.2f %7.2f " fmt, t0.count()*1000.f, t1.count()*1000.f, t2.count()*1000.f, ## __VA_ARGS__); } while(0)

‎core/src/data/networkDataSource.cpp

+4-2
Original file line numberDiff line numberDiff line change
@@ -58,13 +58,15 @@ bool NetworkDataSource::loadTileData(std::shared_ptr<TileTask> task, TileTaskCb
5858
m_urlSubdomainIndex = (m_urlSubdomainIndex + 1) % m_urlSubdomains.size();
5959
}
6060

61-
UrlCallback onRequestFinish = [callback, task, url](UrlResponse&& response) {
62-
61+
LOGTInit(">>> %s", task->tileId().toString().c_str());
62+
UrlCallback onRequestFinish = [=](UrlResponse&& response) mutable {
6363
auto source = task->source();
6464
if (!source) {
6565
LOGW("URL Callback for deleted TileSource '%s'", url.string().c_str());
6666
return;
6767
}
68+
LOGT("<<< %s -- canceled:%d", task->tileId().toString().c_str(), task->isCanceled());
69+
6870
if (task->isCanceled()) {
6971
return;
7072
}

‎core/src/map.cpp

+8
Original file line numberDiff line numberDiff line change
@@ -184,6 +184,7 @@ void Map::Impl::setScene(std::shared_ptr<Scene>& _scene) {
184184
SceneID Map::loadScene(std::shared_ptr<Scene> scene,
185185
const std::vector<SceneUpdate>& _sceneUpdates) {
186186

187+
LOGTOInit();
187188
{
188189
std::unique_lock<std::mutex> lock(impl->sceneMutex);
189190

@@ -250,6 +251,7 @@ SceneID Map::loadSceneYamlAsync(const std::string& _yaml, const std::string& _re
250251
SceneID Map::loadSceneAsync(std::shared_ptr<Scene> nextScene,
251252
const std::vector<SceneUpdate>& _sceneUpdates) {
252253

254+
LOGTOInit();
253255
impl->sceneLoadBegin();
254256

255257
runAsyncTask([nextScene, _sceneUpdates, this](){
@@ -392,6 +394,8 @@ bool Map::update(float _dt) {
392394
// Wait until font and texture resources are fully loaded
393395
if (impl->scene->pendingFonts > 0 || impl->scene->pendingTextures > 0) {
394396
platform->requestRender();
397+
LOGTO("Waiting for Scene fonts:%d textures:%d",
398+
impl->scene->pendingFonts.load(), impl->scene->pendingTextures.load());
395399
return false;
396400
}
397401

@@ -467,6 +471,10 @@ bool Map::update(float _dt) {
467471
platform->requestRender();
468472
}
469473

474+
LOGTO("View complete:%d vc:%d tl:%d tc:%d easing:%d label:%d maker:%d ",
475+
viewComplete, viewChanged, tilesLoading, tilesChanged,
476+
impl->isCameraEasing, labelsNeedUpdate, markersNeedUpdate);
477+
470478
return viewComplete;
471479
}
472480

‎core/src/platform.cpp

+3
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,9 @@
44
#include <fstream>
55
#include <string>
66

7+
std::chrono::time_point<std::chrono::system_clock> tangram_log_time_start, tangram_log_time_last;
8+
std::mutex tangram_log_time_mutex;
9+
710
namespace Tangram {
811

912
Platform::Platform() : m_continuousRendering(false) {}

‎core/src/tile/tileWorker.cpp

+3-2
Original file line numberDiff line numberDiff line change
@@ -48,7 +48,7 @@ void TileWorker::run(Worker* instance) {
4848

4949
if (instance->tileBuilder) {
5050
builder = std::move(instance->tileBuilder);
51-
LOG("Passed new TileBuilder to TileWorker");
51+
LOGTO("Passed new TileBuilder to TileWorker");
5252
}
5353

5454
// Check if thread should stop
@@ -90,8 +90,9 @@ void TileWorker::run(Worker* instance) {
9090
if (task->isCanceled()) {
9191
continue;
9292
}
93-
93+
LOGTInit(">>> %s", task->tileId().toString().c_str());
9494
task->process(*builder);
95+
LOGT("<<< %s", task->tileId().toString().c_str());
9596

9697
m_platform->requestRender();
9798
}

‎platforms/common/urlClient.cpp

+3-2
Original file line numberDiff line numberDiff line change
@@ -168,7 +168,7 @@ void UrlClient::curlLoop(uint32_t index) {
168168
// Configure the easy handle.
169169
const char* url = task.request.url.data();
170170
curl_easy_setopt(handle, CURLOPT_URL, url);
171-
LOGD("curlLoop %u starting request for url: %s", index, url);
171+
LOGTInit("[%u] Starting request: %s", index, url);
172172
// Perform the request.
173173
auto result = curl_easy_perform(handle);
174174
// Handle success or error.
@@ -184,9 +184,10 @@ void UrlClient::curlLoop(uint32_t index) {
184184
}
185185
// If a callback is given, always run it regardless of request result.
186186
if (task.request.callback) {
187-
LOGD("curlLoop %u performing request callback", index);
187+
LOGT("[%u] Finished request", index);
188188
response.content = task.content;
189189
task.request.callback(std::move(response));
190+
LOGT("[%u] Ran callback", index);
190191
}
191192
}
192193
// Reset the task.

0 commit comments

Comments
 (0)