[core] Measuring tiles requesting/parsing time using logging (#12152)

* Tile timing

* Refactor logging code

* Keep the scope of `messageStream` constrained

* Make log message more clear

* Fix crash issue if onlineResponse.data is null

3 files changed, 29 insertions, 0 deletions

diff --git a/src/mbgl/tile/geometry_tile_worker.cpp b/src/mbgl/tile/geometry_tile_worker.cpp
index ca20c4b8ab..31f4b89801 100644
--- a/src/mbgl/tile/geometry_tile_worker.cpp
+++ b/src/mbgl/tile/geometry_tile_worker.cpp
@@ -12,6 +12,7 @@
 #include <mbgl/util/constants.hpp>
 #include <mbgl/util/string.hpp>
 #include <mbgl/util/exception.hpp>
+#include <mbgl/util/stopwatch.hpp>
 
 #include <unordered_set>
 
@@ -319,6 +320,7 @@ void GeometryTileWorker::parse() {
         return;
     }
 
+    MBGL_TIMING_START(watch)
     std::vector<std::string> symbolOrder;
     for (auto it = layers->rbegin(); it != layers->rend(); it++) {
         if ((*it)->type == LayerType::Symbol) {
@@ -403,6 +405,11 @@ void GeometryTileWorker::parse() {
     requestNewGlyphs(glyphDependencies);
     requestNewImages(imageDependencies);
 
+    MBGL_TIMING_FINISH(watch,
+                       " Action: " << "Parsing," <<
+                       " SourceID: " << sourceID.c_str() <<
+                       " Canonical: " << static_cast<int>(id.canonical.z) << "/" << id.canonical.x << "/" << id.canonical.y <<
+                       " Time");
     performSymbolLayout();
 }
 
@@ -424,6 +431,7 @@ void GeometryTileWorker::performSymbolLayout() {
         return;
     }
     
+    MBGL_TIMING_START(watch)
     optional<AlphaImage> glyphAtlasImage;
     optional<PremultipliedImage> iconAtlasImage;
 
@@ -466,6 +474,11 @@ void GeometryTileWorker::performSymbolLayout() {
 
     firstLoad = false;
     
+    MBGL_TIMING_FINISH(watch,
+                       " Action: " << "SymbolLayout," <<
+                       " SourceID: " << sourceID.c_str() <<
+                       " Canonical: " << static_cast<int>(id.canonical.z) << "/" << id.canonical.x << "/" << id.canonical.y <<
+                       " Time");
     parent.invoke(&GeometryTile::onLayout, GeometryTile::LayoutResult {
         std::move(buckets),
         std::move(featureIndex),
diff --git a/src/mbgl/util/event.cpp b/src/mbgl/util/event.cpp
index 3a3be20f5c..0c08d72a8c 100644
--- a/src/mbgl/util/event.cpp
+++ b/src/mbgl/util/event.cpp
@@ -28,6 +28,7 @@ MBGL_DEFINE_ENUM(Event, {
     { Event::Android, "Android" },
     { Event::Crash, "Crash" },
     { Event::Glyph, "Glyph" },
+    { Event::Timing, "Timing" },
     { Event(-1), "Unknown" },
 });
 
diff --git a/src/mbgl/util/stopwatch.hpp b/src/mbgl/util/stopwatch.hpp
index 6214dae958..0c91342a57 100644
--- a/src/mbgl/util/stopwatch.hpp
+++ b/src/mbgl/util/stopwatch.hpp
@@ -4,9 +4,24 @@
 #include <mbgl/util/chrono.hpp>
 
 #include <string>
+#include <sstream>
 
 namespace mbgl {
 namespace util {
+    
+#ifdef MBGL_TIMING
+// Declare 'watch' as a shared_ptr so it can be captured by value in a lambda function    
+#define MBGL_TIMING_START(watch)  std::shared_ptr<util::stopwatch> watch = std::make_unique<util::stopwatch>(Event::Timing);
+#define MBGL_TIMING_FINISH(watch, message) \
+    do { \
+        std::stringstream messageStream;  \
+        messageStream << message; \
+        watch->report(messageStream.str()); \
+    } while (0);
+#else
+#define MBGL_TIMING_START(watch)
+#define MBGL_TIMING_FINISH(watch, message)
+#endif
 
 #ifndef DISABLE_STOPWATCH
 class stopwatch {