From 6510475ff12a4d76b76ded89bdb3ee5c2fc037e5 Mon Sep 17 00:00:00 2001 From: dwight Date: Thu, 2 Jun 2011 23:49:49 -0400 Subject: [PATCH] curTimeMillis() was dubious as it rolls over frequently -- so eliminate it. --- db/clientcursor.cpp | 11 +++-------- db/db_10.sln | 3 --- db/instance.cpp | 2 +- db/repl/replset_commands.cpp | 9 +++++++-- dbtests/perftests.cpp | 6 +++--- util/message.cpp | 4 ++-- util/time_support.h | 17 ++++++----------- util/timer.h | 22 ++++++++++++++++++---- 8 files changed, 40 insertions(+), 34 deletions(-) diff --git a/db/clientcursor.cpp b/db/clientcursor.cpp index d9888f05c17..e7c727f12d0 100644 --- a/db/clientcursor.cpp +++ b/db/clientcursor.cpp @@ -484,7 +484,7 @@ namespace mongo { } long long x; - int ctm = (int) curTimeMillis(); + int ctm = (int) curTimeMillis64(); while ( 1 ) { x = (((long long)rand()) << 32); x = x | ctm | 0x80000000; // OR to make sure not zero @@ -580,21 +580,16 @@ namespace mongo { void ClientCursorMonitor::run() { Client::initThread("clientcursormon"); Client& client = cc(); - - unsigned old = curTimeMillis(); - + Timer t; const int Secs = 4; unsigned n = 0; while ( ! inShutdown() ) { - unsigned now = curTimeMillis(); - ClientCursor::idleTimeReport( now - old ); - old = now; + ClientCursor::idleTimeReport( t.millisReset() ); sleepsecs(Secs); if( ++n % (60/4) == 0 /*once a minute*/ ) { sayMemoryStatus(); } } - client.shutdown(); } diff --git a/db/db_10.sln b/db/db_10.sln index d0dd93880b4..12d62a81648 100755 --- a/db/db_10.sln +++ b/db/db_10.sln @@ -7,9 +7,6 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "examples", "examples", "{40 EndProjectSection EndProject Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "tools", "tools", "{2B262D59-9DC7-4BF1-A431-1BD4966899A5}" - ProjectSection(SolutionItems) = preProject - ..\tools\export.cpp = ..\tools\export.cpp - EndProjectSection EndProject Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "unix files", "unix files", "{2F760952-C71B-4865-998F-AABAE96D1373}" ProjectSection(SolutionItems) = preProject diff --git a/db/instance.cpp b/db/instance.cpp index 3ec07428c56..b8939e84a0e 100644 --- a/db/instance.cpp +++ b/db/instance.cpp @@ -297,7 +297,7 @@ namespace mongo { char *p = m.singleData()->_data; int len = strlen(p); if ( len > 400 ) - out() << curTimeMillis() % 10000 << + out() << curTimeMillis64() % 10000 << " long msg received, len:" << len << endl; Message *resp = new Message(); diff --git a/db/repl/replset_commands.cpp b/db/repl/replset_commands.cpp index 6ef221a1f6e..692b082ec09 100644 --- a/db/repl/replset_commands.cpp +++ b/db/repl/replset_commands.cpp @@ -63,7 +63,10 @@ namespace mongo { } } cmdReplSetTest; - /** get rollback id */ + /** get rollback id. used to check if a rollback happened during some interval of time. + as consumed, the rollback id is not in any particular order, it simply changes on each rollback. + @see incRBID() + */ class CmdReplSetGetRBID : public ReplSetCommand { public: /* todo: ideally this should only change on rollbacks NOT on mongod restarts also. fix... */ @@ -72,7 +75,9 @@ namespace mongo { help << "internal"; } CmdReplSetGetRBID() : ReplSetCommand("replSetGetRBID") { - rbid = (int) curTimeMillis(); + // this is ok but micros or combo with some rand() and/or 64 bits might be better -- + // imagine a restart and a clock correction simultaneously (very unlikely but possible...) + rbid = (int) curTimeMillis64(); } virtual bool run(const string& , BSONObj& cmdObj, string& errmsg, BSONObjBuilder& result, bool fromRepl) { if( !check(errmsg, result) ) diff --git a/dbtests/perftests.cpp b/dbtests/perftests.cpp index adfa6210086..e394df7bf32 100644 --- a/dbtests/perftests.cpp +++ b/dbtests/perftests.cpp @@ -420,11 +420,11 @@ namespace PerfTests { class CTM : public B { public: - string name() { return "curTimeMillis"; } - virtual int howLongMillis() { return 1000; } + string name() { return "curTimeMillis64"; } + virtual int howLongMillis() { return 500; } virtual bool showDurStats() { return false; } void timed() { - aaa += curTimeMillis(); + aaa += curTimeMillis64(); } }; diff --git a/util/message.cpp b/util/message.cpp index ddaecee7d6e..7d3df2a3912 100644 --- a/util/message.cpp +++ b/util/message.cpp @@ -702,12 +702,12 @@ again: MSGID NextMsgId; - struct MsgStart { + /*struct MsgStart { MsgStart() { NextMsgId = (((unsigned) time(0)) << 16) ^ curTimeMillis(); assert(MsgDataHeaderSize == 16); } - } msgstart; + } msgstart;*/ MSGID nextMessageId() { MSGID msgid = NextMsgId++; diff --git a/util/time_support.h b/util/time_support.h index dce05b779f8..b6b9c7bf05b 100644 --- a/util/time_support.h +++ b/util/time_support.h @@ -187,20 +187,16 @@ namespace mongo { else return 0; } - - /** curTimeMillis will overflow - use curTimeMicros64 instead if you care about that. */ - inline unsigned curTimeMillis(); /** Date_t is milliseconds since epoch */ inline Date_t jsTime(); /** measures up to 1024 seconds. or, 512 seconds with tdiff that is */ inline unsigned curTimeMicros(); inline unsigned long long curTimeMicros64(); #ifdef _WIN32 // no gettimeofday on windows - inline unsigned curTimeMillis() { + inline unsigned long long curTimeMillis64() { boost::xtime xt; boost::xtime_get(&xt, boost::TIME_UTC); - unsigned t = xt.nsec / 1000000; - return (xt.sec & 0xfffff) * 1000 + t; + return ((unsigned long long)xt.sec) * 1000 + xt.nsec / 1000000; } inline Date_t jsTime() { boost::xtime xt; @@ -213,7 +209,7 @@ namespace mongo { boost::xtime_get(&xt, boost::TIME_UTC); unsigned long long t = xt.nsec / 1000; return (((unsigned long long) xt.sec) * 1000000) + t; - } + } inline unsigned curTimeMicros() { boost::xtime xt; boost::xtime_get(&xt, boost::TIME_UTC); @@ -223,11 +219,11 @@ namespace mongo { } #else # include - inline unsigned curTimeMillis() { + inline unsigned long long curTimeMillis64() { timeval tv; gettimeofday(&tv, NULL); - unsigned t = tv.tv_usec / 1000; - return (tv.tv_sec & 0xfffff) * 1000 + t; + unsigned t = ; + return ((unsigned long long)tv.tv_sec) * 1000 + tv.tv_usec / 1000; } inline Date_t jsTime() { timeval tv; @@ -246,7 +242,6 @@ namespace mongo { unsigned secs = tv.tv_sec % 1024; return secs*1000*1000 + tv.tv_usec; } - #endif } // namespace mongo diff --git a/util/timer.h b/util/timer.h index 05a6396f02b..9db907185dd 100644 --- a/util/timer.h +++ b/util/timer.h @@ -24,12 +24,25 @@ namespace mongo { /** * simple scoped timer */ - class Timer { + class Timer /*copyable*/ { public: Timer() { reset(); } - Timer( unsigned long long start ) { old = start; } + Timer( unsigned long long startMicros ) { old = startMicros; } int seconds() const { return (int)(micros() / 1000000); } - int millis() const { return (long)(micros() / 1000); } + int millis() const { return (int)(micros() / 1000); } + + /** gets time interval and resets at the same time. this way we can call curTimeMicros + once instead of twice if one wanted millis() and then reset(). + @return time in millis + */ + int millisReset() { + unsigned long long now = curTimeMicros64(); + int m = (int)((now-old)/1000); + old = now; + return m; + } + + // note: dubious that the resolution is as anywhere near as high as ethod name implies! unsigned long long micros() const { unsigned long long n = curTimeMicros64(); return n - old; @@ -38,7 +51,8 @@ namespace mongo { n = curTimeMicros64(); return n - old; } - unsigned long long startTime() { return old; } + + unsigned long long startTime() const { return old; } void reset() { old = curTimeMicros64(); } private: unsigned long long old;