Refactor logging code

5 files changed, 34 insertions, 32 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 125d4df370..00559c4e49 100644
--- a/platform/default/default_file_source.cpp
+++ b/platform/default/default_file_source.cpp
@@ -11,10 +11,9 @@
 #include <mbgl/util/url.hpp>
 #include <mbgl/util/thread.hpp>
 #include <mbgl/util/work_request.hpp>
-#include <mbgl/util/logging.hpp>
+#include <mbgl/util/stopwatch.hpp>
 
 #include <cassert>
-#include <chrono>
 
 namespace mbgl {
 
@@ -153,23 +152,16 @@ public:
 
             // Get from the online file source
             if (resource.hasLoadingMethod(Resource::LoadingMethod::Network)) {
-#if MBGL_TILE_TIMING
-                using namespace std::chrono;
-                milliseconds requestBeginAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
-#endif
+                MBGL_TIMING_START(watch);
                 tasks[req] = onlineFileSource.request(resource, [=] (Response onlineResponse) mutable {
                     this->offlineDatabase->put(resource, onlineResponse);
-#if MBGL_TILE_TIMING
-                    milliseconds requestEndAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
                     if (resource.kind == Resource::Kind::Tile) {
-                        Log::Debug(Event::HttpRequest,
-                                   "Tile:%s, Requesting time:%llims, Size:%u",
-                                   resource.url.c_str(),
-                                   requestEndAt - requestBeginAt,
-                                   onlineResponse.data->size()
-                                   );
+                        MBGL_TIMING_FINISH(watch,
+                                           " Action: " << "Requesting" <<
+                                           " URL: " << resource.url.c_str() <<
+                                           " Size: " <<  onlineResponse.data->size() << "B," <<
+                                           " Time")
                     }
-#endif
                     callback(onlineResponse);
                 });
             }
diff --git a/src/mbgl/tile/geometry_tile_worker.cpp b/src/mbgl/tile/geometry_tile_worker.cpp
index ee55b6a162..bcbc3386db 100644
--- a/src/mbgl/tile/geometry_tile_worker.cpp
+++ b/src/mbgl/tile/geometry_tile_worker.cpp
@@ -12,10 +12,9 @@
 #include <mbgl/util/constants.hpp>
 #include <mbgl/util/string.hpp>
 #include <mbgl/util/exception.hpp>
-#include <mbgl/util/logging.hpp>
+#include <mbgl/util/stopwatch.hpp>
 
 #include <unordered_set>
-#include <chrono>
 
 namespace mbgl {
 
@@ -321,10 +320,7 @@ void GeometryTileWorker::parse() {
         return;
     }
 
-#if MBGL_TILE_TIMING
-    using namespace std::chrono;
-    milliseconds parseBeginAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
-#endif
+    MBGL_TIMING_START(watch)
     std::vector<std::string> symbolOrder;
     for (auto it = layers->rbegin(); it != layers->rend(); it++) {
         if ((*it)->type == LayerType::Symbol) {
@@ -409,18 +405,12 @@ 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();
-#if MBGL_TILE_TIMING
-    milliseconds parseEndAt = duration_cast< milliseconds >(system_clock::now().time_since_epoch());
-    Log::Debug(Event::HttpRequest,
-               "Souce ID:%s, Canonical:%d/%d/%d, Requesting time:%llims",
-               sourceID.c_str(),
-               id.canonical.z,
-               id.canonical.x,
-               id.canonical.y,
-               parseEndAt - parseBeginAt
-               );
-#endif
 }
 
 bool GeometryTileWorker::hasPendingSymbolDependencies() const {
@@ -441,6 +431,7 @@ void GeometryTileWorker::performSymbolLayout() {
         return;
     }
     
+    MBGL_TIMING_START(watch)
     optional<AlphaImage> glyphAtlasImage;
     optional<PremultipliedImage> iconAtlasImage;
 
@@ -483,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..0782aa742f 100644
--- a/src/mbgl/util/stopwatch.hpp
+++ b/src/mbgl/util/stopwatch.hpp
@@ -4,9 +4,21 @@
 #include <mbgl/util/chrono.hpp>
 
 #include <string>
+#include <sstream>
 
 namespace mbgl {
 namespace util {
+    
+#ifdef MBGL_TIMING
+#define MBGL_TIMING_START(watch)  std::shared_ptr<util::stopwatch> watch = std::make_unique<util::stopwatch>(Event::Timing);
+#define MBGL_TIMING_FINISH(watch, message) \
+    std::stringstream messageStream;  \
+    messageStream << message; \
+    watch->report(messageStream.str());
+#else
+#define MBGL_TIMING_START(watch)
+#define MBGL_TIMING_FINISH(watch, message)
+#endif
 
 #ifndef DISABLE_STOPWATCH
 class stopwatch {