QPID-3236 - Add high-resolution timestamps to log files for debug situations. Windows impl has a stub only.

git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk@1098554 13f79535-47bb-0310-9956-ffa450edef68

7 files changed, 33 insertions, 5 deletions

diff --git a/qpid/cpp/include/qpid/log/Logger.h b/qpid/cpp/include/qpid/log/Logger.h
index 783ab7bdb9..7606436e56 100644
--- a/qpid/cpp/include/qpid/log/Logger.h
+++ b/qpid/cpp/include/qpid/log/Logger.h
@@ -36,7 +36,7 @@ namespace log {
 class Logger : private boost::noncopyable {
   public:
     /** Flags indicating what to include in the log output */
-    enum FormatFlag { FILE=1, LINE=2, FUNCTION=4, LEVEL=8, TIME=16, THREAD=32};
+    enum FormatFlag { FILE=1, LINE=2, FUNCTION=4, LEVEL=8, TIME=16, THREAD=32, HIRES=64};
 
     /**
      * Logging output sink.
diff --git a/qpid/cpp/include/qpid/log/Options.h b/qpid/cpp/include/qpid/log/Options.h
index bbc47b47d3..17cbfde9bc 100644
--- a/qpid/cpp/include/qpid/log/Options.h
+++ b/qpid/cpp/include/qpid/log/Options.h
@@ -39,7 +39,7 @@ struct Options : public qpid::Options {
     std::string argv0;
     std::string name;
     std::vector<std::string> selectors;
-    bool time, level, thread, source, function;
+    bool time, level, thread, source, function, hiresTs;
     bool trace;
     std::string prefix;
     std::auto_ptr<SinkOptions> sinkOptions;
diff --git a/qpid/cpp/include/qpid/sys/Time.h b/qpid/cpp/include/qpid/sys/Time.h
index d3ab832229..154a068d83 100644
--- a/qpid/cpp/include/qpid/sys/Time.h
+++ b/qpid/cpp/include/qpid/sys/Time.h
@@ -167,6 +167,9 @@ QPID_COMMON_EXTERN void usleep(uint64_t usecs);
 /** Output formatted date/time for now*/
 void outputFormattedNow(std::ostream&);
 
+/** Output unformatted nanosecond-resolution time for now */
+void outputHiresNow(std::ostream&);
+
 }}
 
 #endif  /*!_sys_Time_h*/
diff --git a/qpid/cpp/src/qpid/log/Logger.cpp b/qpid/cpp/src/qpid/log/Logger.cpp
index 2339a62114..1600822142 100644
--- a/qpid/cpp/src/qpid/log/Logger.cpp
+++ b/qpid/cpp/src/qpid/log/Logger.cpp
@@ -79,8 +79,12 @@ void Logger::log(const Statement& s, const std::string& msg) {
     std::ostringstream os;
     if (!prefix.empty())
         os << prefix << ": ";
-    if (flags&TIME)
-		qpid::sys::outputFormattedNow(os);
+    if (flags&TIME) {
+        if (flags&HIRES)
+            qpid::sys::outputHiresNow(os);
+        else
+		    qpid::sys::outputFormattedNow(os);
+    }
     if (flags&LEVEL)
         os << LevelTraits::name(s.level) << " ";
     if (flags&THREAD)
@@ -129,7 +133,8 @@ int Logger::format(const Options& opts) {
         bitIf(opts.time, TIME) |
         bitIf(opts.source, (FILE|LINE)) |
         bitIf(opts.function, FUNCTION) |
-        bitIf(opts.thread, THREAD);
+        bitIf(opts.thread, THREAD) |
+        bitIf(opts.hiresTs, HIRES);
     format(flags);
     return flags;
 }
diff --git a/qpid/cpp/src/qpid/log/Options.cpp b/qpid/cpp/src/qpid/log/Options.cpp
index 24ef413cbc..0001d00bdf 100644
--- a/qpid/cpp/src/qpid/log/Options.cpp
+++ b/qpid/cpp/src/qpid/log/Options.cpp
@@ -38,6 +38,7 @@ Options::Options(const std::string& argv0_, const std::string& name_) :
     thread(false),
     source(false),
     function(false),
+    hiresTs(false),
     trace(false),
     sinkOptions (SinkOptions::create(argv0_))
 {
@@ -65,6 +66,7 @@ Options::Options(const std::string& argv0_, const std::string& name_) :
         ("log-source", optValue(source,"yes|no"), "Include source file:line in log messages")
         ("log-thread", optValue(thread,"yes|no"), "Include thread ID in log messages")
         ("log-function", optValue(function,"yes|no"), "Include function signature in log messages")
+        ("log-hires-timestamp", optValue(hiresTs,"yes|no"), "Use unformatted hi-res timestamp in log messages")
         ("log-prefix", optValue(prefix,"STRING"), "Prefix to append to all log messages")
         ;
     add(*sinkOptions);
@@ -80,6 +82,7 @@ Options::Options(const Options &o) :
     thread(o.thread),
     source(o.source),
     function(o.function),
+    hiresTs(o.hiresTs),
     trace(o.trace),
     prefix(o.prefix),
     sinkOptions (SinkOptions::create(o.argv0))
@@ -97,6 +100,7 @@ Options& Options::operator=(const Options& x) {
         thread = x.thread;
         source = x.source;
         function = x.function;
+        hiresTs = x.hiresTs;
         trace = x.trace;
         prefix = x.prefix;
         *sinkOptions = *x.sinkOptions;
diff --git a/qpid/cpp/src/qpid/sys/posix/Time.cpp b/qpid/cpp/src/qpid/sys/posix/Time.cpp
index b3858279b4..9661f0c5e8 100644
--- a/qpid/cpp/src/qpid/sys/posix/Time.cpp
+++ b/qpid/cpp/src/qpid/sys/posix/Time.cpp
@@ -27,6 +27,7 @@
 #include <stdio.h>
 #include <sys/time.h>
 #include <unistd.h>
+#include <iomanip>
 
 namespace {
 int64_t max_abstime() { return std::numeric_limits<int64_t>::max(); }
@@ -103,6 +104,12 @@ void outputFormattedNow(std::ostream& o) {
     o << " ";
 }
 
+void outputHiresNow(std::ostream& o) {
+    ::timespec time;
+    ::clock_gettime(CLOCK_REALTIME, &time);
+    o << time.tv_sec << "." << std::setw(9) << std::setfill('0') << time.tv_nsec << "s ";
+}
+
 void sleep(int secs) {
     ::sleep(secs);
 }
diff --git a/qpid/cpp/src/qpid/sys/windows/Time.cpp b/qpid/cpp/src/qpid/sys/windows/Time.cpp
index 16d09fcdc0..56eade651a 100644
--- a/qpid/cpp/src/qpid/sys/windows/Time.cpp
+++ b/qpid/cpp/src/qpid/sys/windows/Time.cpp
@@ -97,4 +97,13 @@ void outputFormattedNow(std::ostream& o) {
                &timeinfo);
     o << time_string << " ";
 }
+
+void outputHiresNow(std::ostream& o) {
+// TODO: This is a stub - replace with windows code that will do the equivalent
+// of the Linux code commented out below.  (kpvdr)
+//    ::timespec time;
+//    ::clock_gettime(CLOCK_REALTIME, &time);
+//    o << time.tv_sec << "." << std::setw(9) << std::setfill('0') << time.tv_nsec << "s ";
+    o << "XXXXXXXXX.XXXXXXXXXs ";
+}
 }}