[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

5 files changed, 40 insertions, 0 deletions

diff --git a/include/mbgl/util/event.hpp b/include/mbgl/util/event.hpp
index 5fe0baae3c..15583e956d 100644
--- a/include/mbgl/util/event.hpp
+++ b/include/mbgl/util/event.hpp
@@ -28,6 +28,7 @@ enum class Event : uint8_t {
     Android,
     Crash,
     Glyph,
+    Timing
 };
 
 struct EventPermutation {
diff --git a/platform/default/default_file_source.cpp b/platform/default/default_file_source.cpp
index cb602995a4..89aabeb8d3 100644
--- a/platform/default/default_file_source.cpp
+++ b/platform/default/default_file_source.cpp
@@ -11,6 +11,7 @@
 #include <mbgl/util/url.hpp>
 #include <mbgl/util/thread.hpp>
 #include <mbgl/util/work_request.hpp>
+#include <mbgl/util/stopwatch.hpp>
 
 #include <cassert>
 
@@ -151,8 +152,17 @@ public:
 
             // Get from the online file source
             if (resource.hasLoadingMethod(Resource::LoadingMethod::Network)) {
+                MBGL_TIMING_START(watch);
                 tasks[req] = onlineFileSource.request(resource, [=] (Response onlineResponse) mutable {
                     this->offlineDatabase->put(resource, onlineResponse);
+                    if (resource.kind == Resource::Kind::Tile) {
+                        // onlineResponse.data will be null if data not modified
+                        MBGL_TIMING_FINISH(watch,
+                                           " Action: " << "Requesting," <<
+                                           " URL: " << resource.url.c_str() <<
+                                           " Size: " << (onlineResponse.data != nullptr ? onlineResponse.data->size() : 0) << "B," <<
+                                           " Time")
+                    }
                     callback(onlineResponse);
                 });
             }
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 {