[Box Backup-commit] COMMIT r2005 - in box/chris/general: infrastructure lib/common
boxbackup-dev@fluffy.co.uk
boxbackup-dev@fluffy.co.uk
Sat, 15 Dec 2007 22:20:37 +0000 (UTC)
Author: chris
Date: 2007-12-15 22:20:37 +0000 (Sat, 15 Dec 2007)
New Revision: 2005
Modified:
box/chris/general/infrastructure/buildenv-testmain-template.cpp
box/chris/general/lib/common/Logging.cpp
box/chris/general/lib/common/Logging.h
box/chris/general/lib/common/Test.h
box/chris/general/lib/common/Timer.cpp
Log:
Allow logging with microsecond timestamps.
Add -U option to enable logging microsecond timestamps
Don't log our own timestamp now that Logging can do it for us with
microsecond precision.
Log sleep time and resleeps in safe_sleep (only used in tests).
(merges [2001] [2002] [2003] [2004])
Modified: box/chris/general/infrastructure/buildenv-testmain-template.cpp
===================================================================
--- box/chris/general/infrastructure/buildenv-testmain-template.cpp 2007-12-15 20:07:04 UTC (rev 2004)
+++ box/chris/general/infrastructure/buildenv-testmain-template.cpp 2007-12-15 22:20:37 UTC (rev 2005)
@@ -174,7 +174,7 @@
int ch;
- while ((ch = getopt_long(argc, argv, "c:s:t:T", longopts, NULL))
+ while ((ch = getopt_long(argc, argv, "c:s:t:TU", longopts, NULL))
!= -1)
{
switch(ch)
@@ -208,6 +208,13 @@
}
break;
+ case 'U':
+ {
+ Console::SetShowTime(true);
+ Console::SetShowTimeMicros(true);
+ }
+ break;
+
case '?':
{
fprintf(stderr, "Unknown option: %s\n",
Modified: box/chris/general/lib/common/Logging.cpp
===================================================================
--- box/chris/general/lib/common/Logging.cpp 2007-12-15 20:07:04 UTC (rev 2004)
+++ box/chris/general/lib/common/Logging.cpp 2007-12-15 22:20:37 UTC (rev 2005)
@@ -20,6 +20,8 @@
#include <iomanip>
+#include "BoxTime.h"
+
bool Logging::sLogToSyslog = false;
bool Logging::sLogToConsole = false;
bool Logging::sContextSet = false;
@@ -178,7 +180,8 @@
}
bool Console::sShowTime = false;
-bool Console::sShowTag = false;
+bool Console::sShowTimeMicros = false;
+bool Console::sShowTag = false;
std::string Console::sTag;
void Console::SetTag(const std::string& rTag)
@@ -192,6 +195,11 @@
sShowTime = enabled;
}
+void Console::SetShowTimeMicros(bool enabled)
+{
+ sShowTimeMicros = enabled;
+}
+
bool Console::Log(Log::Level level, const std::string& rFile,
int line, std::string& rMessage)
{
@@ -211,25 +219,31 @@
if (sShowTime)
{
- struct tm time_now, *tm_ptr = &time_now;
- time_t time_t_now = time(NULL);
+ box_time_t time_now = GetCurrentBoxTime();
+ time_t seconds = BoxTimeToSeconds(time_now);
+ int micros = BoxTimeToMicroSeconds(time_now) % MICRO_SEC_IN_SEC;
- if (time_t_now == ((time_t)-1))
- {
- msg += strerror(errno);
- msg += " ";
- }
+ struct tm tm_now, *tm_ptr = &tm_now;
+
#ifdef WIN32
- else if ((tm_ptr = localtime(&time_t_now)) != NULL)
+ if ((tm_ptr = localtime(&seconds)) != NULL)
#else
- else if (localtime_r(&time_t_now, &time_now) != NULL)
+ if (localtime_r(&seconds, &tm_now) != NULL)
#endif
{
std::ostringstream buf;
+
buf << std::setfill('0') <<
std::setw(2) << tm_ptr->tm_hour << ":" <<
std::setw(2) << tm_ptr->tm_min << ":" <<
- std::setw(2) << tm_ptr->tm_sec << " ";
+ std::setw(2) << tm_ptr->tm_sec;
+
+ if (sShowTimeMicros)
+ {
+ buf << "." << std::setw(6) << micros;
+ }
+
+ buf << " ";
msg += buf.str();
}
else
Modified: box/chris/general/lib/common/Logging.h
===================================================================
--- box/chris/general/lib/common/Logging.h 2007-12-15 20:07:04 UTC (rev 2004)
+++ box/chris/general/lib/common/Logging.h 2007-12-15 22:20:37 UTC (rev 2005)
@@ -118,6 +118,7 @@
{
private:
static bool sShowTime;
+ static bool sShowTimeMicros;
static bool sShowTag;
static std::string sTag;
@@ -129,6 +130,7 @@
static void SetTag(const std::string& rTag);
static void SetShowTime(bool enabled);
+ static void SetShowTimeMicros(bool enabled);
};
// --------------------------------------------------------------------------
Modified: box/chris/general/lib/common/Test.h
===================================================================
--- box/chris/general/lib/common/Test.h 2007-12-15 20:07:04 UTC (rev 2004)
+++ box/chris/general/lib/common/Test.h 2007-12-15 22:20:37 UTC (rev 2005)
@@ -437,10 +437,17 @@
Sleep(seconds * 1000);
#else
struct timespec ts;
+ memset(&ts, 0, sizeof(ts));
ts.tv_sec = seconds;
ts.tv_nsec = 0;
+ BOX_TRACE("sleeping for " << seconds << " seconds");
while (nanosleep(&ts, &ts) == -1 && errno == EINTR)
- { /* sleep again */ }
+ {
+ BOX_TRACE("safe_sleep interrupted with " <<
+ ts.tv_sec << "." << ts.tv_nsec <<
+ " secs remaining, sleeping again");
+ /* sleep again */
+ }
#endif
}
Modified: box/chris/general/lib/common/Timer.cpp
===================================================================
--- box/chris/general/lib/common/Timer.cpp 2007-12-15 20:07:04 UTC (rev 2004)
+++ box/chris/general/lib/common/Timer.cpp 2007-12-15 22:20:37 UTC (rev 2005)
@@ -149,10 +149,6 @@
Reschedule();
}
-#define FORMAT_BOX_TIME(t) \
- (BoxTimeToSeconds(t)) << "." << \
- (BoxTimeToMicroSeconds(t) % MICRO_SEC_IN_SEC)
-
#define FORMAT_MICROSECONDS(t) \
(int)(t / 1000000) << "." << \
(int)(t % 1000000)
@@ -185,8 +181,10 @@
if (oldact.sa_handler != Timers::SignalHandler)
{
- printf("Signal handler was %p, expected %p\n",
- oldact.sa_handler, Timers::SignalHandler);
+ BOX_ERROR("Signal handler was " <<
+ (void *)oldact.sa_handler <<
+ ", expected " <<
+ (void *)Timers::SignalHandler);
THROW_EXCEPTION(CommonException, Internal)
}
#endif
@@ -214,8 +212,7 @@
if (timeToExpiry <= 0)
{
- BOX_TRACE(FORMAT_MICROSECONDS(timeNow) <<
- ": timer " << *i << " has expired, "
+ BOX_TRACE("timer " << *i << " has expired, "
"triggering it");
rTimer.OnExpire();
spTimers->erase(i);
@@ -224,8 +221,7 @@
}
else
{
- BOX_TRACE(FORMAT_MICROSECONDS(timeNow) <<
- ": timer " << *i << " has not "
+ BOX_TRACE("timer " << *i << " has not "
"expired, triggering in " <<
FORMAT_MICROSECONDS(timeToExpiry) <<
" seconds");
@@ -294,17 +290,14 @@
mExpired(false)
{
#ifndef NDEBUG
- box_time_t timeNow = GetCurrentBoxTime();
if (timeoutSecs == 0)
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised for " <<
+ BOX_TRACE("timer " << this << " initialised for " <<
timeoutSecs << " secs, will not fire");
}
else
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised for " <<
+ BOX_TRACE("timer " << this << " initialised for " <<
timeoutSecs << " secs, to fire at " <<
FORMAT_MICROSECONDS(mExpires));
}
@@ -323,9 +316,7 @@
Timer::~Timer()
{
#ifndef NDEBUG
- box_time_t timeNow = GetCurrentBoxTime();
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " destroyed");
+ BOX_TRACE("timer " << this << " destroyed");
#endif
Timers::Remove(*this);
@@ -336,23 +327,19 @@
mExpired(rToCopy.mExpired)
{
#ifndef NDEBUG
- box_time_t timeNow = GetCurrentBoxTime();
if (mExpired)
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised from timer " <<
+ BOX_TRACE("timer " << this << " initialised from timer " <<
&rToCopy << ", already expired, will not fire");
}
else if (mExpires == 0)
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised from timer " <<
+ BOX_TRACE("timer " << this << " initialised from timer " <<
&rToCopy << ", no expiry, will not fire");
}
else
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised from timer " <<
+ BOX_TRACE("timer " << this << " initialised from timer " <<
&rToCopy << " to fire at " <<
(int)(mExpires / 1000000) << "." <<
(int)(mExpires % 1000000));
@@ -368,23 +355,19 @@
Timer& Timer::operator=(const Timer& rToCopy)
{
#ifndef NDEBUG
- box_time_t timeNow = GetCurrentBoxTime();
if (rToCopy.mExpired)
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised from timer " <<
+ BOX_TRACE("timer " << this << " initialised from timer " <<
&rToCopy << ", already expired, will not fire");
}
else if (rToCopy.mExpires == 0)
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised from timer " <<
+ BOX_TRACE("timer " << this << " initialised from timer " <<
&rToCopy << ", no expiry, will not fire");
}
else
{
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) <<
- ": timer " << this << " initialised from timer " <<
+ BOX_TRACE("timer " << this << " initialised from timer " <<
&rToCopy << " to fire at " <<
(int)(rToCopy.mExpires / 1000000) << "." <<
(int)(rToCopy.mExpires % 1000000));
@@ -404,8 +387,7 @@
void Timer::OnExpire()
{
#ifndef NDEBUG
- box_time_t timeNow = GetCurrentBoxTime();
- BOX_TRACE(FORMAT_BOX_TIME(timeNow) << ": timer " << this << " fired");
+ BOX_TRACE("timer " << this << " fired");
#endif
mExpired = true;