Tile timing for requesting and parsingupstream/lloyd/tile_timing

13 files changed, 52 insertions, 11 deletions

diff --git a/include/mbgl/storage/response.hpp b/include/mbgl/storage/response.hpp
index 508400141b..10f6c73148 100644
--- a/include/mbgl/storage/response.hpp
+++ b/include/mbgl/storage/response.hpp
@@ -36,6 +36,7 @@ public:
     optional<Timestamp> modified;
     optional<Timestamp> expires;
     optional<std::string> etag;
+    optional<std::string> url;
 
     bool isFresh() const {
         return expires ? *expires > util::now() : !error;
diff --git a/platform/darwin/src/http_file_source.mm b/platform/darwin/src/http_file_source.mm
index 4a16ad82fb..97f748d23d 100644
--- a/platform/darwin/src/http_file_source.mm
+++ b/platform/darwin/src/http_file_source.mm
@@ -5,6 +5,7 @@
 #include <mbgl/util/http_header.hpp>
 #include <mbgl/util/async_task.hpp>
 #include <mbgl/util/version.hpp>
+#include <mbgl/util/logging.hpp>
 
 #import <Foundation/Foundation.h>
 
@@ -199,6 +200,10 @@ uint32_t HTTPFileSource::maximumConcurrentRequests() {
 std::unique_ptr<AsyncRequest> HTTPFileSource::request(const Resource& resource, Callback callback) {
     auto request = std::make_unique<HTTPRequest>(callback);
     auto shared = request->shared; // Explicit copy so that it also gets copied into the completion handler block below.
+#ifndef NDEBUG
+    using namespace std::chrono;
+    milliseconds requestStartedAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
+#endif
 
     @autoreleasepool {
         NSURL* url = [NSURL URLWithString:@(resource.url.c_str())];
@@ -226,8 +231,22 @@ std::unique_ptr<AsyncRequest> HTTPFileSource::request(const Resource& resource,
                 if (error && [error code] == NSURLErrorCancelled) {
                     return;
                 }
-
+#ifndef NDEBUG
+                milliseconds requestEnededAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
+                static std::string EnumKindStrings[] = {
+                    "Unknown", "Style", "Source", "Tile","Glyphs", "SpriteImage", "SpriteJSON", "Image"
+                };
+                Log::Debug(Event::HttpRequest,
+                           "Resource:%s, Type:%s, Requesting time:%llims, Size:%u",
+                           [url.absoluteString UTF8String],
+                           (int)resource.kind >= (int)(sizeof(EnumKindStrings)/sizeof(EnumKindStrings[0])) ?
+                           "Unknown": EnumKindStrings[(int)resource.kind].c_str(),
+                           requestEnededAt - requestStartedAt,
+                           data.length
+                           );
+#endif
                 Response response;
+                response.url = resource.url;
                 using Error = Response::Error;
 
                 if (error) {
diff --git a/src/mbgl/storage/response.cpp b/src/mbgl/storage/response.cpp
index 222f55db84..61e4c41576 100644
--- a/src/mbgl/storage/response.cpp
+++ b/src/mbgl/storage/response.cpp
@@ -19,6 +19,7 @@ Response& Response::operator=(const Response& res) {
     modified = res.modified;
     expires = res.expires;
     etag = res.etag;
+    url = res.url;
     return *this;
 }
 
diff --git a/src/mbgl/tile/geometry_tile.cpp b/src/mbgl/tile/geometry_tile.cpp
index af28fe3963..652124d388 100644
--- a/src/mbgl/tile/geometry_tile.cpp
+++ b/src/mbgl/tile/geometry_tile.cpp
@@ -80,13 +80,14 @@ void GeometryTile::setError(std::exception_ptr err) {
     observer->onTileError(*this, err);
 }
 
-void GeometryTile::setData(std::unique_ptr<const GeometryTileData> data_) {
+uint64_t GeometryTile::setData(std::unique_ptr<const GeometryTileData> data_) {
     // Mark the tile as pending again if it was complete before to prevent signaling a complete
     // state despite pending parse operations.
     pending = true;
 
     ++correlationID;
     worker.invoke(&GeometryTileWorker::setData, std::move(data_), correlationID);
+    return correlationID;
 }
 
 
diff --git a/src/mbgl/tile/geometry_tile.hpp b/src/mbgl/tile/geometry_tile.hpp
index af122474c2..4785d5f37f 100644
--- a/src/mbgl/tile/geometry_tile.hpp
+++ b/src/mbgl/tile/geometry_tile.hpp
@@ -31,7 +31,7 @@ public:
     ~GeometryTile() override;
 
     void setError(std::exception_ptr);
-    void setData(std::unique_ptr<const GeometryTileData>);
+    uint64_t setData(std::unique_ptr<const GeometryTileData>);
 
     void setLayers(const std::vector<Immutable<style::Layer::Impl>>&) override;
     void setShowCollisionBoxes(const bool showCollisionBoxes) override;
diff --git a/src/mbgl/tile/geometry_tile_worker.cpp b/src/mbgl/tile/geometry_tile_worker.cpp
index ca20c4b8ab..314426c10f 100644
--- a/src/mbgl/tile/geometry_tile_worker.cpp
+++ b/src/mbgl/tile/geometry_tile_worker.cpp
@@ -14,6 +14,7 @@
 #include <mbgl/util/exception.hpp>
 
 #include <unordered_set>
+#include <chrono>
 
 namespace mbgl {
 
@@ -318,6 +319,10 @@ void GeometryTileWorker::parse() {
     if (!data || !layers) {
         return;
     }
+#ifndef NDEBUG
+    using namespace std::chrono;
+    milliseconds parseStartedAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
+#endif
 
     std::vector<std::string> symbolOrder;
     for (auto it = layers->rbegin(); it != layers->rend(); it++) {
@@ -399,6 +404,13 @@ void GeometryTileWorker::parse() {
             symbolLayouts.push_back(std::move(it->second));
         }
     }
+#ifndef NDEBUG
+    milliseconds parseEnededAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
+    Log::Debug(Event::ParseTile,
+               "CorrelationID:%lld, Parsing time:%llims",
+               correlationID,
+               parseEnededAt - parseStartedAt);
+#endif
 
     requestNewGlyphs(glyphDependencies);
     requestNewImages(imageDependencies);
diff --git a/src/mbgl/tile/raster_dem_tile.cpp b/src/mbgl/tile/raster_dem_tile.cpp
index 5db298cf4c..6bb78b0962 100644
--- a/src/mbgl/tile/raster_dem_tile.cpp
+++ b/src/mbgl/tile/raster_dem_tile.cpp
@@ -45,10 +45,11 @@ void RasterDEMTile::setMetadata(optional<Timestamp> modified_, optional<Timestam
     expires = expires_;
 }
 
-void RasterDEMTile::setData(std::shared_ptr<const std::string> data) {
+uint64_t RasterDEMTile::setData(std::shared_ptr<const std::string> data) {
     pending = true;
     ++correlationID;
     worker.invoke(&RasterDEMTileWorker::parse, data, correlationID, encoding);
+    return correlationID;
 }
 
 void RasterDEMTile::onParsed(std::unique_ptr<HillshadeBucket> result, const uint64_t resultCorrelationID) {
diff --git a/src/mbgl/tile/raster_dem_tile.hpp b/src/mbgl/tile/raster_dem_tile.hpp
index 0c8dd75961..acb8c85079 100644
--- a/src/mbgl/tile/raster_dem_tile.hpp
+++ b/src/mbgl/tile/raster_dem_tile.hpp
@@ -70,7 +70,7 @@ public:
 
     void setError(std::exception_ptr);
     void setMetadata(optional<Timestamp> modified, optional<Timestamp> expires);
-    void setData(std::shared_ptr<const std::string> data);
+    uint64_t setData(std::shared_ptr<const std::string> data);
 
     void upload(gl::Context&) override;
     Bucket* getBucket(const style::Layer::Impl&) const override;
diff --git a/src/mbgl/tile/raster_tile.cpp b/src/mbgl/tile/raster_tile.cpp
index ff23d4493e..611c956aba 100644
--- a/src/mbgl/tile/raster_tile.cpp
+++ b/src/mbgl/tile/raster_tile.cpp
@@ -34,10 +34,11 @@ void RasterTile::setMetadata(optional<Timestamp> modified_, optional<Timestamp>
     expires = expires_;
 }
 
-void RasterTile::setData(std::shared_ptr<const std::string> data) {
+uint64_t RasterTile::setData(std::shared_ptr<const std::string> data) {
     pending = true;
     ++correlationID;
     worker.invoke(&RasterTileWorker::parse, data, correlationID);
+    return correlationID;
 }
 
 void RasterTile::onParsed(std::unique_ptr<RasterBucket> result, const uint64_t resultCorrelationID) {
diff --git a/src/mbgl/tile/raster_tile.hpp b/src/mbgl/tile/raster_tile.hpp
index e25329119a..9f9790a278 100644
--- a/src/mbgl/tile/raster_tile.hpp
+++ b/src/mbgl/tile/raster_tile.hpp
@@ -26,7 +26,7 @@ public:
 
     void setError(std::exception_ptr);
     void setMetadata(optional<Timestamp> modified, optional<Timestamp> expires);
-    void setData(std::shared_ptr<const std::string> data);
+    uint64_t setData(std::shared_ptr<const std::string> data);
 
     void upload(gl::Context&) override;
     Bucket* getBucket(const style::Layer::Impl&) const override;
diff --git a/src/mbgl/tile/tile_loader_impl.hpp b/src/mbgl/tile/tile_loader_impl.hpp
index 1b29638269..2ab8c4d316 100644
--- a/src/mbgl/tile/tile_loader_impl.hpp
+++ b/src/mbgl/tile/tile_loader_impl.hpp
@@ -4,6 +4,7 @@
 #include <mbgl/storage/file_source.hpp>
 #include <mbgl/renderer/tile_parameters.hpp>
 #include <mbgl/util/tileset.hpp>
+#include <mbgl/util/logging.hpp>
 
 #include <cassert>
 
@@ -106,7 +107,11 @@ void TileLoader<T>::loadedData(const Response& res) {
         resource.priorExpires = res.expires;
         resource.priorEtag = res.etag;
         tile.setMetadata(res.modified, res.expires);
-        tile.setData(res.noContent ? nullptr : res.data);
+        uint64_t correlationID = tile.setData(res.noContent ? nullptr : res.data);
+        Log::Debug(Event::ParseTile,
+                   "CorrelationID:%lld, URL:%s",
+                   correlationID, res.url->c_str()
+                   );
     }
 }
 
diff --git a/src/mbgl/tile/vector_tile.cpp b/src/mbgl/tile/vector_tile.cpp
index 0756d3e526..97e9c3981a 100644
--- a/src/mbgl/tile/vector_tile.cpp
+++ b/src/mbgl/tile/vector_tile.cpp
@@ -21,8 +21,8 @@ void VectorTile::setMetadata(optional<Timestamp> modified_, optional<Timestamp>
     expires = expires_;
 }
 
-void VectorTile::setData(std::shared_ptr<const std::string> data_) {
-    GeometryTile::setData(data_ ? std::make_unique<VectorTileData>(data_) : nullptr);
+uint64_t VectorTile::setData(std::shared_ptr<const std::string> data_) {
+    return GeometryTile::setData(data_ ? std::make_unique<VectorTileData>(data_) : nullptr);
 }
 
 } // namespace mbgl
diff --git a/src/mbgl/tile/vector_tile.hpp b/src/mbgl/tile/vector_tile.hpp
index 7dae414fef..285b81c367 100644
--- a/src/mbgl/tile/vector_tile.hpp
+++ b/src/mbgl/tile/vector_tile.hpp
@@ -17,7 +17,7 @@ public:
 
     void setNecessity(TileNecessity) final;
     void setMetadata(optional<Timestamp> modified, optional<Timestamp> expires);
-    void setData(std::shared_ptr<const std::string> data);
+    uint64_t setData(std::shared_ptr<const std::string> data);
 
 private:
     TileLoader<VectorTile> loader;