Merge branch 'alex85k-patch-timing' into develop

Contractor/EdgeBasedGraphFactory.cpp

@@ -276,10 +276,10 @@ void EdgeBasedGraphFactory::Run(const std::string &original_edge_data_filename,
     m_geometry_compressor.SerializeInternalVector(geometry_filename);
 
     SimpleLogger().Write() << "Timing statistics for edge-expanded graph:";
-    SimpleLogger().Write() << "Geometry compression: " << TIMER_MSEC(geometry)*0.001 << "s";
+    SimpleLogger().Write() << "Geometry compression: " << TIMER_SEC(geometry) << "s";
-    SimpleLogger().Write() << "Renumbering edges: " << TIMER_MSEC(renumber)*0.001 << "s";
+    SimpleLogger().Write() << "Renumbering edges: " << TIMER_SEC(renumber) << "s";
-    SimpleLogger().Write() << "Generating nodes: " << TIMER_MSEC(generate_nodes)*0.001 << "s";
+    SimpleLogger().Write() << "Generating nodes: " << TIMER_SEC(generate_nodes) << "s";
-    SimpleLogger().Write() << "Generating edges: " << TIMER_MSEC(generate_edges)*0.001 << "s";
+    SimpleLogger().Write() << "Generating edges: " << TIMER_SEC(generate_edges) << "s";
 }
 
 void EdgeBasedGraphFactory::CompressGeometry()

DataStructures/StaticRTree.h

@@ -424,7 +424,7 @@ class StaticRTree
         tree_node_file.close();
 
         TIMER_STOP(construction);
-        SimpleLogger().Write() << "finished r-tree construction in " << TIMER_MSEC(construction)/1000. << " seconds";
+        SimpleLogger().Write() << "finished r-tree construction in " << TIMER_SEC(construction) << " seconds";
     }
 
     // Read-only operation for queries

Extractor/ExtractionContainers.cpp

@@ -29,6 +29,7 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 #include "ExtractionWay.h"
 #include "../Util/OSRMException.h"
 #include "../Util/SimpleLogger.h"
+#include "../Util/TimingUtil.h"
 
 #include <boost/assert.hpp>
 #include <boost/filesystem.hpp>
@@ -63,49 +64,45 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
     {
         unsigned number_of_used_nodes = 0;
         unsigned number_of_used_edges = 0;
-        std::chrono::time_point<std::chrono::steady_clock> time1 = std::chrono::steady_clock::now();
-
         std::cout << "[extractor] Sorting used nodes        ... " << std::flush;
+        TIMER_START(sorting_used_nodes);
         stxxl::sort(used_node_id_list.begin(), used_node_id_list.end(), Cmp(), stxxl_memory);
-        std::chrono::time_point<std::chrono::steady_clock> time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(sorting_used_nodes);
-        std::chrono::duration<double> elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(sorting_used_nodes) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
-        time1 = std::chrono::steady_clock::now();
         std::cout << "[extractor] Erasing duplicate nodes   ... " << std::flush;
+        TIMER_START(erasing_dups);
         auto new_end = std::unique(used_node_id_list.begin(), used_node_id_list.end());
         used_node_id_list.resize(new_end - used_node_id_list.begin());
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(erasing_dups);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(erasing_dups) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
-        time1 = std::chrono::steady_clock::now();
 
         std::cout << "[extractor] Sorting all nodes         ... " << std::flush;
+        TIMER_START(sorting_nodes);
         stxxl::sort(all_nodes_list.begin(), all_nodes_list.end(), CmpNodeByID(), stxxl_memory);
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(sorting_nodes);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(sorting_nodes) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
-        time1 = std::chrono::steady_clock::now();
 
         std::cout << "[extractor] Sorting used ways         ... " << std::flush;
+        TIMER_START(sort_ways);
         stxxl::sort(
             way_start_end_id_list.begin(), way_start_end_id_list.end(), CmpWayByID(), stxxl_memory);
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(sort_ways);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(sort_ways) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
         std::cout << "[extractor] Sorting restrictions. by from... " << std::flush;
+        TIMER_START(sort_restrictions);
         stxxl::sort(restrictions_list.begin(),
                     restrictions_list.end(),
                     CmpRestrictionContainerByFrom(),
                     stxxl_memory);
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(sort_restrictions);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(sort_restrictions) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
         std::cout << "[extractor] Fixing restriction starts ... " << std::flush;
+        TIMER_START(fix_restriction_starts);
         auto restrictions_iterator = restrictions_list.begin();
         auto way_start_and_end_iterator = way_start_end_id_list.begin();
 
@@ -149,24 +146,21 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
             ++restrictions_iterator;
         }
 
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(fix_restriction_starts);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(fix_restriction_starts) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
-
-        time1 = std::chrono::steady_clock::now();
 
         std::cout << "[extractor] Sorting restrictions. by to  ... " << std::flush;
+        TIMER_START(sort_restrictions_to);
         stxxl::sort(restrictions_list.begin(),
                     restrictions_list.end(),
                     CmpRestrictionContainerByTo(),
                     stxxl_memory);
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(sort_restrictions_to);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(sort_restrictions_to) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
-        time1 = std::chrono::steady_clock::now();
         unsigned number_of_useable_restrictions = 0;
         std::cout << "[extractor] Fixing restriction ends   ... " << std::flush;
+        TIMER_START(fix_restriction_ends);
         restrictions_iterator = restrictions_list.begin();
         way_start_and_end_iterator = way_start_end_id_list.begin();
         while (way_start_and_end_iterator != way_start_end_id_list.end() &&
@@ -207,9 +201,8 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
             }
             ++restrictions_iterator;
         }
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(fix_restriction_ends);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(fix_restriction_ends) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
         SimpleLogger().Write() << "usable restrictions: " << number_of_useable_restrictions;
         // serialize restrictions
@@ -235,9 +228,8 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
         file_out_stream.open(output_file_name.c_str(), std::ios::binary);
         file_out_stream.write((char *)&fingerprint, sizeof(FingerPrint));
         file_out_stream.write((char *)&number_of_used_nodes, sizeof(unsigned));
-        time1 = std::chrono::steady_clock::now();
         std::cout << "[extractor] Confirming/Writing used nodes     ... " << std::flush;
-
+        TIMER_START(write_nodes);
         // identify all used nodes by a merging step of two sorted lists
         auto node_iterator = all_nodes_list.begin();
         auto node_id_iterator = used_node_id_list.begin();
@@ -262,9 +254,8 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
             ++node_iterator;
         }
 
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(write_nodes);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(write_nodes) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
         std::cout << "[extractor] setting number of nodes   ... " << std::flush;
         std::ios::pos_type previous_file_position = file_out_stream.tellp();
@@ -273,18 +264,17 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
         file_out_stream.seekp(previous_file_position);
 
         std::cout << "ok" << std::endl;
-        time1 = std::chrono::steady_clock::now();
 
         // Sort edges by start.
         std::cout << "[extractor] Sorting edges by start    ... " << std::flush;
+        TIMER_START(sort_edges_by_start);
         stxxl::sort(all_edges_list.begin(), all_edges_list.end(), CmpEdgeByStartID(), stxxl_memory);
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(sort_edges_by_start);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(sort_edges_by_start) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
-        time1 = std::chrono::steady_clock::now();
 
         std::cout << "[extractor] Setting start coords      ... " << std::flush;
+        TIMER_START(set_start_coords);
         file_out_stream.write((char *)&number_of_used_edges, sizeof(unsigned));
         // Traverse list of edges and nodes in parallel and set start coord
         node_iterator = all_nodes_list.begin();
@@ -307,20 +297,18 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
             edge_iterator->source_coordinate.lon = node_iterator->lon;
             ++edge_iterator;
         }
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(set_start_coords);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(set_start_coords) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
-        time1 = std::chrono::steady_clock::now();
         // Sort Edges by target
         std::cout << "[extractor] Sorting edges by target   ... " << std::flush;
+        TIMER_START(sort_edges_by_target);
         stxxl::sort(all_edges_list.begin(), all_edges_list.end(), CmpEdgeByTargetID(), stxxl_memory);
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(sort_edges_by_target);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(sort_edges_by_target) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
-        time1 = std::chrono::steady_clock::now();
         std::cout << "[extractor] Setting target coords     ... " << std::flush;
+        TIMER_START(set_target_coords);
         // Traverse list of edges and nodes in parallel and set target coord
         node_iterator = all_nodes_list.begin();
         edge_iterator = all_edges_list.begin();
@@ -394,9 +382,8 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
             }
             ++edge_iterator;
         }
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(set_target_coords);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(set_target_coords) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
         std::cout << "[extractor] setting number of edges   ... " << std::flush;
 
@@ -404,9 +391,9 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
         file_out_stream.write((char *)&number_of_used_edges, sizeof(unsigned));
         file_out_stream.close();
         std::cout << "ok" << std::endl;
-        time1 = std::chrono::steady_clock::now();
 
         std::cout << "[extractor] writing street name index ... " << std::flush;
+        TIMER_START(write_name_index);
         std::string name_file_streamName = (output_file_name + ".names");
         boost::filesystem::ofstream name_file_stream(name_file_streamName, std::ios::binary);
 
@@ -440,9 +427,8 @@ void ExtractionContainers::PrepareData(const std::string &output_file_name,
         }
 
         name_file_stream.close();
-        time2 = std::chrono::steady_clock::now();
+        TIMER_STOP(write_name_index);
-        elapsed_seconds = time2 - time1;
+        std::cout << "ok, after " << TIMER_SEC(write_name_index) << "s" << std::endl;
-        std::cout << "ok, after " << elapsed_seconds.count() << "s" << std::endl;
 
         SimpleLogger().Write() << "Processed " << number_of_used_nodes << " nodes and "
                                << number_of_used_edges << " edges";

Tools/io-benchmark.cpp

@@ -28,6 +28,7 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 #include "../Util/GitDescription.h"
 #include "../Util/OSRMException.h"
 #include "../Util/SimpleLogger.h"
+#include "../Util/TimingUtil.h"
 
 #include <boost/filesystem.hpp>
 #include <boost/filesystem/fstream.hpp>
@@ -100,17 +101,15 @@ int main(int argc, char *argv[])
                 throw OSRMException("Data file already exists");
             }
 
-            std::chrono::time_point<std::chrono::steady_clock> time1, time2;
             int *random_array = new int[number_of_elements];
             std::generate(random_array, random_array + number_of_elements, std::rand);
 #ifdef __APPLE__
             FILE *fd = fopen(test_path.string().c_str(), "w");
             fcntl(fileno(fd), F_NOCACHE, 1);
             fcntl(fileno(fd), F_RDAHEAD, 0);
-            time1 = std::chrono::steady_clock::now();
+            TIMER_START(write_1gb);
             write(fileno(fd), (char *)random_array, number_of_elements * sizeof(unsigned));
-            time2 = std::chrono::steady_clock::now();
+            TIMER_STOP(write_1gb);
-            ;
             fclose(fd);
 #endif
 #ifdef __linux__
@@ -120,21 +119,20 @@ int main(int argc, char *argv[])
             {
                 throw OSRMException("Could not open random data file");
             }
-            time1 = std::chrono::steady_clock::now();
+            TIMER_START(write_1gb);
             int ret = write(f, random_array, number_of_elements * sizeof(unsigned));
             if (0 > ret)
             {
                 throw OSRMException("could not write random data file");
             }
-            time2 = std::chrono::steady_clock::now();
+            TIMER_STOP(write_1gb);
             close(f);
 #endif
-            std::chrono::duration<double> elapsed_seconds = time2 - time1;
             delete[] random_array;
-            SimpleLogger().Write(logDEBUG) << "writing raw 1GB took " << elapsed_seconds.count()
+            SimpleLogger().Write(logDEBUG) << "writing raw 1GB took " << TIMER_SEC(write_1gb)
-                                           << "ms";
+                                           << "s";
             SimpleLogger().Write() << "raw write performance: " << std::setprecision(5)
-                                   << std::fixed << 1024 * 1024 / (elapsed_seconds.count())
+                                   << std::fixed << 1024 * 1024 / TIMER_SEC(write_1gb)
                                    << "MB/sec";
 
             SimpleLogger().Write(logDEBUG)
@@ -148,7 +146,6 @@ int main(int argc, char *argv[])
                 throw OSRMException("data file does not exist");
             }
 
-            std::chrono::time_point<std::chrono::steady_clock> time1, time2;
             // volatiles do not get optimized
             Statistics stats;
 
@@ -170,7 +167,7 @@ int main(int argc, char *argv[])
             }
             char *raw_array = (char *)memalign(512, number_of_elements * sizeof(unsigned));
 #endif
-            time1 = std::chrono::steady_clock::now();
+            TIMER_START(read_1gb);
 #ifdef __APPLE__
             read(fileno(fd), raw_array, number_of_elements * sizeof(unsigned));
             close(fileno(fd));
@@ -184,13 +181,12 @@ int main(int argc, char *argv[])
             f = open(test_path.string().c_str(), O_RDONLY | O_DIRECT | O_SYNC);
             SimpleLogger().Write(logDEBUG) << "opened, error: " << strerror(errno);
 #endif
-            time2 = std::chrono::steady_clock::now();
+            TIMER_STOP(read_1gb);
 
-            std::chrono::duration<double> elapsed_seconds = time2 - time1;
+            SimpleLogger().Write(logDEBUG) << "reading raw 1GB took " << TIMER_SEC(read_1gb)
-            SimpleLogger().Write(logDEBUG) << "reading raw 1GB took " << elapsed_seconds.count()
+                                           << "s";
-                                           << "ms";
             SimpleLogger().Write() << "raw read performance: " << std::setprecision(5) << std::fixed
-                                   << 1024 * 1024 / (elapsed_seconds.count()) << "MB/sec";
+                                   << 1024 * 1024 / TIMER_SEC(read_1gb) << "MB/sec";
 
             std::vector<double> timing_results_raw_random;
             SimpleLogger().Write(logDEBUG) << "running 1000 random I/Os of 4KB";
@@ -207,7 +203,7 @@ int main(int argc, char *argv[])
             {
                 unsigned block_to_read = std::rand() % number_of_blocks;
                 off_t current_offset = block_to_read * 4096;
-                time1 = std::chrono::steady_clock::now();
+                TIMER_START(random_access);
 #ifdef __APPLE__
                 int ret1 = fseek(fd, current_offset, SEEK_SET);
                 int ret2 = read(fileno(fd), (char *)&single_block[0], 4096);
@@ -222,7 +218,7 @@ int main(int argc, char *argv[])
                 int ret1 = lseek(f, current_offset, SEEK_SET);
                 int ret2 = read(f, (char *)single_block, 4096);
 #endif
-                time2 = std::chrono::steady_clock::now();
+                TIMER_STOP(random_access);
                 if (((off_t) - 1) == ret1)
                 {
                     SimpleLogger().Write(logWARNING) << "offset: " << current_offset;
@@ -235,7 +231,7 @@ int main(int argc, char *argv[])
                     SimpleLogger().Write(logWARNING) << "read error " << strerror(errno);
                     throw OSRMException("read error");
                 }
-                timing_results_raw_random.push_back(elapsed_seconds.count());
+                timing_results_raw_random.push_back(TIMER_SEC(random_access));
             }
 
             // Do statistics
@@ -267,7 +263,7 @@ int main(int argc, char *argv[])
             for (unsigned i = 0; i < 1000; ++i)
             {
                 off_t current_offset = i * 4096;
-                time1 = std::chrono::steady_clock::now();
+                TIMER_START(read_every_100);
 #ifdef __APPLE__
                 int ret1 = fseek(fd, current_offset, SEEK_SET);
                 int ret2 = read(fileno(fd), (char *)&single_block, 4096);
@@ -283,7 +279,7 @@ int main(int argc, char *argv[])
 
                 int ret2 = read(f, (char *)single_block, 4096);
 #endif
-                time2 = std::chrono::steady_clock::now();
+                TIMER_STOP(read_every_100);
                 if (((off_t) - 1) == ret1)
                 {
                     SimpleLogger().Write(logWARNING) << "offset: " << current_offset;
@@ -296,7 +292,7 @@ int main(int argc, char *argv[])
                     SimpleLogger().Write(logWARNING) << "read error " << strerror(errno);
                     throw OSRMException("read error");
                 }
-                timing_results_raw_seq.push_back(elapsed_seconds.count());
+                timing_results_raw_seq.push_back(TIMER_SEC(read_every_100));
             }
 #ifdef __APPLE__
             fclose(fd);

Util/TimingUtil.h

@@ -30,10 +30,10 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 #include <chrono>
 
-#define TIMER_START(_X) std::chrono::time_point<std::chrono::steady_clock> _X##_start, _X##_stop; _X##_start = std::chrono::steady_clock::now()
+#define TIMER_START(_X) auto _X##_start = std::chrono::steady_clock::now(), _X##_stop = _X##_start
 #define TIMER_STOP(_X) _X##_stop = std::chrono::steady_clock::now()
 #define TIMER_MSEC(_X) std::chrono::duration_cast<std::chrono::milliseconds>(_X##_stop - _X##_start).count()
-#define TIMER_SEC(_X) std::chrono::duration_cast<std::chrono::seconds>(_X##_stop - _X##_start).count()
+#define TIMER_SEC(_X) (0.001*std::chrono::duration_cast<std::chrono::milliseconds>(_X##_stop - _X##_start).count())
 #define TIMER_MIN(_X) std::chrono::duration_cast<std::chrono::minutes>(_X##_stop - _X##_start).count()
 
 #endif // TIMINGUTIL_H

extractor.cpp

@@ -30,13 +30,14 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 #include "Extractor/ScriptingEnvironment.h"
 #include "Extractor/PBFParser.h"
 #include "Extractor/XMLParser.h"
+#include "Util/FingerPrint.h"
 #include "Util/GitDescription.h"
 #include "Util/MachineInfo.h"
 #include "Util/OSRMException.h"
 #include "Util/ProgramOptions.h"
 #include "Util/SimpleLogger.h"
 #include "Util/StringUtil.h"
-#include "Util/FingerPrint.h"
+#include "Util/TimingUtil.h"
 #include "typedefs.h"
 
 #include <cstdlib>
@@ -58,8 +59,8 @@ int main(int argc, char *argv[])
     try
     {
         LogPolicy::GetInstance().Unmute();
-        std::chrono::time_point<std::chrono::steady_clock> startup_time =
+
-            std::chrono::steady_clock::now();
+        TIMER_START(extracting);
 
         boost::filesystem::path config_file_path, input_path, profile_path;
         unsigned requested_num_threads;
@@ -240,16 +241,14 @@ int main(int argc, char *argv[])
             throw OSRMException("Parser not initialized!");
         }
         SimpleLogger().Write() << "Parsing in progress..";
-        std::chrono::time_point<std::chrono::steady_clock> parsing_start_time =
+        TIMER_START(parsing);
-            std::chrono::steady_clock::now();
 
         parser->Parse();
         delete parser;
         delete extractor_callbacks;
 
-        std::chrono::duration<double> parsing_duration =
+        TIMER_STOP(parsing);
-            std::chrono::steady_clock::now() - parsing_start_time;
+        SimpleLogger().Write() << "Parsing finished after " << TIMER_SEC(parsing)
-        SimpleLogger().Write() << "Parsing finished after " << parsing_duration.count()
                                << " seconds";
 
         if (extraction_containers.all_edges_list.empty())
@@ -260,9 +259,8 @@ int main(int argc, char *argv[])
 
         extraction_containers.PrepareData(output_file_name, restriction_fileName);
 
-        std::chrono::duration<double> extraction_duration =
+        TIMER_STOP(extracting);
-            std::chrono::steady_clock::now() - startup_time;
+        SimpleLogger().Write() << "extraction finished after " << TIMER_SEC(extracting)
-        SimpleLogger().Write() << "extraction finished after " << extraction_duration.count()
                                << "s";
         SimpleLogger().Write() << "To prepare the data for routing, run: "
                                << "./osrm-prepare " << output_file_name << std::endl;

prepare.cpp

@@ -41,6 +41,7 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 
 #include "Util/SimpleLogger.h"
 #include "Util/StringUtil.h"
+#include "Util/TimingUtil.h"
 #include "typedefs.h"
 
 #include <boost/filesystem.hpp>
@@ -72,8 +73,8 @@ int main(int argc, char *argv[])
     try
     {
         LogPolicy::GetInstance().Unmute();
-        std::chrono::time_point<std::chrono::steady_clock> startup_time =
+        TIMER_START(preparing);
-            std::chrono::steady_clock::now();
+        TIMER_START(expansion);
 
         boost::filesystem::path config_file_path, input_path, restrictions_path, profile_path;
         unsigned int requested_num_threads;
@@ -321,8 +322,7 @@ int main(int argc, char *argv[])
         // TODO actually use scoping: Split this up in subfunctions
         node_based_graph.reset();
 
-        std::chrono::duration<double> end_of_expansion_time =
+        TIMER_STOP(expansion);
-            std::chrono::steady_clock::now() - startup_time;
 
         // Building grid-like nearest-neighbor data structure
         SimpleLogger().Write() << "building r-tree ...";
@@ -359,13 +359,12 @@ int main(int argc, char *argv[])
 
         SimpleLogger().Write() << "initializing contractor";
         Contractor *contractor = new Contractor(number_of_edge_based_nodes, edgeBasedEdgeList);
-        std::chrono::time_point<std::chrono::steady_clock> contraction_start_timestamp =
-            std::chrono::steady_clock::now();
 
+        TIMER_START(contraction);
         contractor->Run();
-        std::chrono::duration<double> contraction_duration =
+        TIMER_STOP(contraction);
-            std::chrono::steady_clock::now() - contraction_start_timestamp;
+
-        SimpleLogger().Write() << "Contraction took " << contraction_duration.count() << " sec";
+        SimpleLogger().Write() << "Contraction took " << TIMER_SEC(contraction) << " sec";
 
         DeallocatingVector<QueryEdge> contracted_edge_list;
         contractor->GetEdges(contracted_edge_list);
@@ -468,20 +467,19 @@ int main(int argc, char *argv[])
         }
         hsgr_output_stream.close();
 
-        std::chrono::duration<double> entire_duration =
+        TIMER_STOP(preparing);
-            std::chrono::steady_clock::now() - startup_time;
 
-        SimpleLogger().Write() << "Preprocessing : " << entire_duration.count() << " seconds";
+        SimpleLogger().Write() << "Preprocessing : " << TIMER_SEC(preparing) << " seconds";
         SimpleLogger().Write() << "Expansion  : "
-                               << (number_of_node_based_nodes / end_of_expansion_time.count())
+                               << (number_of_node_based_nodes / TIMER_SEC(expansion))
                                << " nodes/sec and "
-                               << (number_of_edge_based_nodes / end_of_expansion_time.count())
+                               << (number_of_edge_based_nodes / TIMER_SEC(expansion))
                                << " edges/sec";
 
         SimpleLogger().Write() << "Contraction: "
-                               << (number_of_edge_based_nodes / contraction_duration.count())
+                               << (number_of_edge_based_nodes / TIMER_SEC(contraction))
                                << " nodes/sec and "
-                               << number_of_used_edges / contraction_duration.count()
+                               << number_of_used_edges / TIMER_SEC(contraction)
                                << " edges/sec";
 
         node_array.clear();