Factor out slow command log message

4 files changed, 27 insertions, 18 deletions

diff --git a/db/commands.cpp b/db/commands.cpp
index 4d9140dc230..56104b108bb 100644
--- a/db/commands.cpp
+++ b/db/commands.cpp
@@ -152,6 +152,7 @@ namespace mongo {
                 anObjBuilder.append( "help" , help.str() );
             }
             else {
+                c->_timer.reset();
                 ok = c->run( nsToDatabase( ns ) , jsobj, errmsg, anObjBuilder, false);
             }
 
@@ -187,5 +188,12 @@ namespace mongo {
         return c->locktype();
     }
 
+    void Command::logIfSlow( const string& msg ) const {
+        int ms = _timer.millis();
+        if ( ms > cmdLine.slowMS ){
+            out() << msg << " took " << ms << " ms." << endl;
+        }
+    }
+    
     
 } // namespace mongo
diff --git a/db/commands.h b/db/commands.h
index 49a51f55762..6dbb04afa5a 100644
--- a/db/commands.h
+++ b/db/commands.h
@@ -112,10 +112,14 @@ namespace mongo {
             return BSONObj();
         }
 
+        void logIfSlow( const string& msg) const;
+
         static map<string,Command*> * _commands;
         static map<string,Command*> * _commandsByBestName;
         static map<string,Command*> * _webCommands;
 
+        Timer                         _timer;  // started right before calling run
+
     public:
         static const map<string,Command*>* commandsByBestName() { return _commandsByBestName; }
         static const map<string,Command*>* webCommands() { return _webCommands; }
diff --git a/db/dbcommands.cpp b/db/dbcommands.cpp
index 4b5021e180c..284c8f4fe67 100644
--- a/db/dbcommands.cpp
+++ b/db/dbcommands.cpp
@@ -986,7 +986,6 @@ namespace mongo {
             if ( id == 0 )
                 return false;
 
-            Timer t;
             int num = 0;
             NamespaceDetails *d = nsdetails(ns);
             int idxNo = d->idxNo(*id);
@@ -994,10 +993,10 @@ namespace mongo {
             num /= 2;
             BtreeCursor c( d, idxNo, *id, min, max, false, 1 );
             for( ; num; c.advance(), --num );
-            int ms = t.millis();
-            if ( ms > cmdLine.slowMS ) {
-                out() << "Finding median for index: " << keyPattern << " between " << min << " and " << max << " took " << ms << "ms." << endl;
-            }
+
+            ostringstream os;
+            os << "Finding median for index: " << keyPattern << " between " << min << " and " << max;
+            logIfSlow( os.str() );
 
             if ( !c.ok() ) {
                 errmsg = "no index entries in the specified range";
@@ -1048,7 +1047,6 @@ namespace mongo {
             long long maxSize = jsobj["maxSize"].numberLong();
             long long maxObjects = jsobj["maxObjects"].numberLong();
 
-            Timer t;
             long long size = 0;
             long long numObjects = 0;
             while( c->ok() ) {
@@ -1063,18 +1061,17 @@ namespace mongo {
 
                 c->advance();
             }
-            int ms = t.millis();
-            if ( ms > cmdLine.slowMS ) {
-                if ( min.isEmpty() ) {
-                    out() << "Finding size for ns: " << ns << " took " << ms << "ms." << endl;
-                } else {
-                    out() << "Finding size for ns: " << ns << " between " << min << " and " << max << " took " << ms << "ms." << endl;
-                }
+
+            ostringstream os;
+            os <<  "Finding size for ns: " << ns;
+            if ( ! min.isEmpty() ){
+                os << " between " << min << " and " << max;
             }
+            logIfSlow( os.str() );
 
             result.append( "size", (double)size );
             result.append( "numObjects" , (double)numObjects );
-            result.append( "millis" , ms );
+            result.append( "millis" , _timer.millis() );
             return true;
         }
     } cmdDatasize;
diff --git a/util/goodies.h b/util/goodies.h
index 4920e432e56..e7b700932f6 100644
--- a/util/goodies.h
+++ b/util/goodies.h
@@ -281,17 +281,17 @@ namespace mongo {
         Timer( unsigned long long start ) {
             old = start;
         }
-        int seconds(){
+        int seconds() const {
             return (int)(micros() / 1000000);
         }
-        int millis() {
+        int millis() const {
             return (long)(micros() / 1000);
         }
-        unsigned long long micros() {
+        unsigned long long micros() const {
             unsigned long long n = curTimeMicros64();
             return n - old;
         }
-        unsigned long long micros(unsigned long long & n) { // returns cur time in addition to timer result
+        unsigned long long micros(unsigned long long & n) const { // returns cur time in addition to timer result
             n = curTimeMicros64();
             return n - old;
         }