Merge branch 'feature/time'

vzaccaria · Jan 15, 2015 · 1c4e603 · 1c4e603
2 parents cfa97ac + 25e565a
commit 1c4e603
Show file tree

Hide file tree

Showing 9 changed files with 142 additions and 20 deletions.
diff --git a/Readme.md b/Readme.md
@@ -88,6 +88,41 @@ then:
  test/test3.cpp:10 this is main
 ```
 
+## Time output
+
+To enable time measurements between debug messages associated with
+the same namespace (or the same line of code when using `debugm`), use `DEBUG_TIME=yes`:
+
+```c++
+/* example.cpp */
+#include <iostream>
+#include "debug.hxx"
+#include <unistd.h>
+
+using namespace std;
+
+int main(int argc, char const *argv[])
+{
+    for(int i=0; i<4; i++) {
+        debugm("debug printed.");
+        sleep(1);
+    }
+        return 0;
+}
+```
+
+Run it with: 
+
+```
+> DEBUG_COLORS=no DEBUG=* DEBUG_TIME=yes $srcdir/../bin/test6
+
+ test/test6.cpp:10 debug printed. +0ms
+ test/test6.cpp:10 debug printed. +1002ms
+ test/test6.cpp:10 debug printed. +2003ms
+ test/test6.cpp:10 debug printed. +3005ms
+```
+
+
 
 ## Conventions
 

diff --git a/debug.hxx b/debug.hxx
@@ -30,6 +30,9 @@ THE SOFTWARE.
 #include <regex>
 #include <functional>
 #include <vector>
+#include <ctime>
+#include <iomanip>
+#include <chrono>
 
 static std::vector<std::string> words(std::string str, std::string delim = " ") {
 	std::vector<std::string> res;
@@ -58,20 +61,39 @@ static auto Debug = [](std::string moduleName) {
 
 	auto h = 0;
     auto debug_colors = std::getenv("DEBUG_COLORS");
+    auto debug_time = std::getenv("DEBUG_TIME");
 
 	bool use_colors;
+	bool use_time;
 
 	auto name_to_be_hashed = moduleName;
 
-	if (debug_colors == NULL || (
-		std::string(debug_colors) != "false" &&
-		std::string(debug_colors) != "no" &&
-		std::string(debug_colors) != "disabled")) {
-		use_colors = true;
-	}
-	else {
-		use_colors = false;
-	}
+	auto getBool = [](const char *e, bool def) -> bool {
+		if(def == true) {
+			if (e == NULL || (
+				std::string(e) != "false" &&
+				std::string(e) != "no" &&
+				std::string(e) != "disabled")) {
+				return true;
+			}
+			else {
+				return false;
+			}
+		} else {
+			if(e != NULL && (
+				std::string(e) == "true" ||
+				std::string(e) == "yes" ||
+				std::string(e) == "enabled")) {
+				return true;
+			} else {
+				return false;
+			}
+		}
+	};
+
+	use_colors = getBool(debug_colors, true);
+	use_time = getBool(debug_time, false);
+
 
 	if(use_colors) {
 		std::hash<std::string> hash_fn;
@@ -100,13 +122,42 @@ static auto Debug = [](std::string moduleName) {
 		shouldDebug = std::regex_search(moduleName, re);
 	}
 	return [=](std::string message) {
+
+		std::string time_suffix = "";
+		int diff = 0;
+
+		if(use_time) {
+			auto get_ms = []() -> int {
+				using namespace std::chrono;
+				return duration_cast< milliseconds >(high_resolution_clock::now().time_since_epoch()).count();
+			};
+			static auto prev = get_ms();
+			auto curr = get_ms();
+			diff = curr - prev;
+			prev = curr;
+		}
+
+#define _col_light(c, m) 	("\u001b[9" + std::to_string(c) + "m" + m + " \u001b[0m" )
+#define _col_light_ms(c, m) 	("\u001b[9" + std::to_string(c) + "m" + m + "ms \u001b[0m" )
+
+
 		if (!shouldDebug) { return false; }
+
 		if (!use_colors) {
 			std::cerr << " " << moduleName;
-			std::cerr << " " << message << std::endl;	
+			std::cerr << " " << message;	
+		} else {
+			std::cerr << _col_light(colors[h], moduleName);
+			std::cerr << message;
+		}
+		if(use_time) {
+			if(use_colors) {
+				std::cerr << " +" << _col_light_ms(colors[h], std::to_string((diff))) << std::endl;
+			} else {
+				std::cerr << " +" << std::to_string((diff)) << "ms" << std::endl;
+			}
 		} else {
-			std::cerr << " \u001b[9" << colors[h] << "m" << moduleName;
-			std::cerr << " \u001b[0m" << message << "\u001b[3" << h << "m" << std::endl;
+			std::cerr << std::endl;
 		}
 		return true;
 	};

diff --git a/makefile.ls b/makefile.ls
@@ -34,6 +34,12 @@ parse ->
                          @clang 'deps/*/**.cpp', 'deps/*/**.{hxx}'
                          @clang 'test/test5.cpp', '*.hxx'
                          ]
+
+        @dest "./bin/test6", ->
+            @link ->  [
+                         @clang 'deps/*/**.cpp', 'deps/*/**.{hxx}'
+                         @clang 'test/test6.cpp', '*.hxx'
+                         ]
         ]
 
     @collect "all", ->

diff --git a/test/out1c.ref b/test/out1c.ref
@@ -1 +1 @@
- [95mmain [0mthis is main[34m
+[95mmain [0mthis is main
diff --git a/test/out6.ref b/test/out6.ref
@@ -0,0 +1,4 @@
+ test/test6.cpp:10 debug printed. +0ms
+ test/test6.cpp:10 debug printed. +1000ms
+ test/test6.cpp:10 debug printed. +1000ms
+ test/test6.cpp:10 debug printed. +1000ms
diff --git a/test/out6.tmp b/test/out6.tmp
@@ -0,0 +1,4 @@
+ test/test6.cpp:10 debug printed. +0ms
+ test/test6.cpp:10 debug printed. +1000ms
+ test/test6.cpp:10 debug printed. +1000ms
+ test/test6.cpp:10 debug printed. +1000ms
diff --git a/test/out6.tmp.t b/test/out6.tmp.t
@@ -0,0 +1,4 @@
+ test/test6.cpp:10 debug printed. +0ms
+ test/test6.cpp:10 debug printed. +1001ms
+ test/test6.cpp:10 debug printed. +1001ms
+ test/test6.cpp:10 debug printed. +1001ms
diff --git a/test/test.sh b/test/test.sh
@@ -3,13 +3,16 @@ srcdir=`dirname $0`
 srcdir=`cd $srcdir; pwd`
 dstdir=`pwd`
 
-DEBUG_COLORS=no $srcdir/../bin/test &> $srcdir/out0.tmp 
-DEBUG_COLORS=no DEBUG=main $srcdir/../bin/test &> $srcdir/out1.tmp 
-DEBUG=main $srcdir/../bin/test &> $srcdir/out1c.tmp 
-DEBUG_COLORS=no DEBUG=* $srcdir/../bin/test &> $srcdir/out2.tmp 
-DEBUG_COLORS=no DEBUG=* $srcdir/../bin/test2 &> $srcdir/out3.tmp 
-DEBUG_COLORS=no $srcdir/../bin/test4 &> $srcdir/out4.tmp
-DEBUG_COLORS=no DEBUG=main* $srcdir/../bin/test5  &> $srcdir/out5.tmp
+DEBUG_COLORS=no 						$srcdir/../bin/test   &> $srcdir/out0.tmp 
+DEBUG_COLORS=no DEBUG=main 				$srcdir/../bin/test   &> $srcdir/out1.tmp 
+DEBUG=main 								$srcdir/../bin/test   &> $srcdir/out1c.tmp 
+DEBUG_COLORS=no DEBUG=* 				$srcdir/../bin/test   &> $srcdir/out2.tmp 
+DEBUG_COLORS=no DEBUG=* 				$srcdir/../bin/test2  &> $srcdir/out3.tmp 
+DEBUG_COLORS=no 						$srcdir/../bin/test4  &> $srcdir/out4.tmp
+DEBUG_COLORS=no DEBUG=main* 			$srcdir/../bin/test5  &> $srcdir/out5.tmp
+
+DEBUG_COLORS=no DEBUG=* DEBUG_TIME=yes 	$srcdir/../bin/test6  &> $srcdir/out6.tmp.t
+cat $srcdir/out6.tmp.t | sed 's/.ms/0ms/g' > $srcdir/out6.tmp
 
 function check {
 	m=$1
@@ -30,5 +33,6 @@ check '4' $srcdir/out3.tmp $srcdir/out3.ref
 check '5' $srcdir/out1c.tmp $srcdir/out1c.ref
 check '6' $srcdir/out4.tmp $srcdir/out4.ref
 check '7' $srcdir/out5.tmp $srcdir/out5.ref
+check '8' $srcdir/out6.tmp $srcdir/out6.ref
 
 
diff --git a/test/test6.cpp b/test/test6.cpp
@@ -0,0 +1,14 @@
+#include <iostream>
+#include "debug.hxx"
+#include <unistd.h>
+
+using namespace std;
+
+int main(int argc, char const *argv[])
+{
+    for(int i=0; i<4; i++) {
+        debugm("debug printed.");
+        sleep(1);
+    }
+	return 0;
+}
Original file line number	Diff line number	Diff line change
		@@ -1 +1 @@
		[95mmain [0mthis is main[34m
		[95mmain [0mthis is main