fix timing so starts when enter lock

5 files changed, 49 insertions, 25 deletions

diff --git a/db/client.cpp b/db/client.cpp
index a800e9070fe..c62e5490d0e 100644
--- a/db/client.cpp
+++ b/db/client.cpp
@@ -34,13 +34,12 @@ namespace mongo {
     boost::thread_specific_ptr<Client> currentClient;
 
     Client::Client(const char *desc) : 
-      _curOp(new CurOp()),
       _context(0),
-      //_database(0), _ns("")/*, _nsstr("")*/ 
       _shutdown(false),
       _desc(desc),
       _god(0)
     {
+        _curOp = new CurOp( this );
         boostlock bl(clientsMutex);
         clients.insert(this);
     }
diff --git a/db/client.h b/db/client.h
index ec282261660..420293348a7 100644
--- a/db/client.h
+++ b/db/client.h
@@ -155,7 +155,7 @@ namespace mongo {
         };
         
     private:
-        CurOp * const _curOp;
+        CurOp * _curOp;
         Context * _context;
         bool _shutdown;
         list<string> _tempCollections;
@@ -195,6 +195,8 @@ namespace mongo {
         bool shutdown();
 
         bool isGod() const { return _god; }
+
+        friend class CurOp;
     };
     
     inline Client& cc() { 
diff --git a/db/curop.h b/db/curop.h
index 478b2808409..57d2a947286 100644
--- a/db/curop.h
+++ b/db/curop.h
@@ -24,6 +24,9 @@ namespace mongo {
         static AtomicUInt _nextOpNum;
         static BSONObj _tooBig; // { $msg : "query not recording (too large)" }
         
+        Client * _client;
+        CurOp * _wrapped;
+
         unsigned long long _start;
         unsigned long long _checkpoint;
         unsigned long long _end;
@@ -34,7 +37,7 @@ namespace mongo {
         int _dbprofile; // 0=off, 1=slow, 2=all
         AtomicUInt _opNum;
         char _ns[Namespace::MaxNsLen+2];
-        struct sockaddr_in _client;
+        struct sockaddr_in _remote;
         
         char _queryBuf[256];
         bool haveQuery() const { return *((int *) _queryBuf) != 0; }
@@ -60,7 +63,12 @@ namespace mongo {
         }
 
     public:
+        void ensureStarted(){
+            if ( _start == 0 )
+                _start = _checkpoint = curTimeMicros64();            
+        }
         void enter( Client::Context * context ){
+            ensureStarted();
             setNS( context->ns() );
             if ( context->_db && context->_db->profile > _dbprofile )
                 _dbprofile = context->_db->profile;
@@ -72,16 +80,15 @@ namespace mongo {
             _checkpoint = now;
         }
         
-        void reset( const sockaddr_in & client, int op ) { 
+        void reset( const sockaddr_in & remote, int op ) { 
             _reset();
-            _start = curTimeMicros64();
-            _checkpoint = _start;
+            _start = _checkpoint = 0;
             _active = true;
             _opNum = _nextOpNum++;
             _ns[0] = '?'; // just in case not set later
             _debug.reset();
             resetQuery();
-            _client = client;
+            _remote = remote;
             _op = op;
         }
 
@@ -115,7 +122,8 @@ namespace mongo {
         bool active() const { return _active; }
 
         /** micros */
-        unsigned long long startTime(){
+        unsigned long long startTime() const {
+            assert(_start);
             return _start;
         }
 
@@ -126,16 +134,20 @@ namespace mongo {
         
         unsigned long long totalTimeMicros() const {
             massert( 12601 , "CurOp not marked done yet" , ! _active );
-            return _end - _start;
+            return _end - startTime();
         }
 
         int totalTimeMillis() const {
             return (int) (totalTimeMicros() / 1000);
         }
 
+        int elapsedMillis() const {
+            unsigned long long total = curTimeMicros64() - startTime();
+            return (int) (total / 1000);
+        }
+
         int elapsedSeconds() const {
-            unsigned long long total = curTimeMicros64() - _start;
-            return (int) (total / 1000000);
+            return elapsedMillis() / 1000;
         }
 
         void setQuery(const BSONObj& query) { 
@@ -146,8 +158,13 @@ namespace mongo {
             memcpy(_queryBuf, query.objdata(), query.objsize());
         }
 
-        CurOp() { 
-            _start = _checkpoint = curTimeMicros64();
+        CurOp( Client * client , CurOp * wrapped = 0 ) { 
+            _client = client;
+            _wrapped = wrapped;
+            if ( _wrapped ){
+                _client->_curOp = this;
+            }
+            _start = _checkpoint = 0;
             _active = false;
             _reset();
             _op = 0;
@@ -157,6 +174,11 @@ namespace mongo {
             memset(_ns, 0, sizeof(_ns));
             memset(_queryBuf, 0, sizeof(_queryBuf));
         }
+        
+        ~CurOp(){
+            if ( _wrapped )
+                _client->_curOp = _wrapped;
+        }
 
         BSONObj info() { 
             if( ! cc().getAuthenticationInfo()->isAuthorized("admin") ) { 
@@ -192,7 +214,7 @@ namespace mongo {
             }
             // b.append("inLock",  ??
             stringstream clientStr;
-            clientStr << inet_ntoa( _client.sin_addr ) << ":" << ntohs( _client.sin_port );
+            clientStr << inet_ntoa( _remote.sin_addr ) << ":" << ntohs( _remote.sin_port );
             b.append("client", clientStr.str());
             return b.obj();
         }
diff --git a/db/instance.cpp b/db/instance.cpp
index f8bf54f97c8..d2f0261eab2 100644
--- a/db/instance.cpp
+++ b/db/instance.cpp
@@ -277,7 +277,7 @@ namespace mongo {
         auto_ptr<CurOp> nestedOp;
         CurOp* currentOpP = c.curop();
         if ( currentOpP->active() ){
-            nestedOp.reset( new CurOp() );
+            nestedOp.reset( new CurOp( &c , currentOpP ) );
             currentOpP = nestedOp.get();
         }
         CurOp& currentOp = *currentOpP;
@@ -285,25 +285,23 @@ namespace mongo {
         
         OpDebug& debug = currentOp.debug();
         StringBuilder& ss = debug.str;
+        ss << opToString( op ) << " ";
 
         int logThreshold = cmdLine.slowMS;
         bool log = logLevel >= 1;
-
+        
         if ( op == dbQuery ) {
             if ( ! receivedQuery(c , dbresponse, m ) )
                 log = true;
         }
         else if ( op == dbGetMore ) {
-            mongolock lk(writeLock);
             DEV log = true;
-            ss << "getmore ";
             if ( ! receivedGetMore(dbresponse, m, currentOp) )
                 log = true;
         }
         else if ( op == dbMsg ) {
             mongolock lk(writeLock);
 			/* deprecated / rarely used.  intended for connection diagnostics. */
-            ss << "msg ";
             char *p = m.data->_data;
             int len = strlen(p);
             if ( len > 400 )
@@ -327,19 +325,21 @@ namespace mongo {
                 uassert_nothrow("unauthorized");
             }
             else {
-                mongolock lk(writeLock);
-                ss << opToString( op ) << " ";
                 try {
                     if ( op == dbInsert ) {
+                        mongolock lk(writeLock);
                         receivedInsert(m, currentOp);
                     }
                     else if ( op == dbUpdate ) {
                         receivedUpdate(m, currentOp);
                     }
                     else if ( op == dbDelete ) {
+                        mongolock lk(writeLock);
                         receivedDelete(m, currentOp);
                     }
                     else if ( op == dbKillCursors ) {
+                        mongolock lk(writeLock);
+                        currentOp.ensureStarted();
                         logThreshold = 10;
                         ss << "killcursors ";
                         receivedKillCursors(m);
@@ -450,6 +450,7 @@ namespace mongo {
             op.setQuery(query);
         }        
 
+        mongolock lk(1);
         Client::Context ctx( ns );
         op.setWrite();
 
@@ -485,6 +486,7 @@ namespace mongo {
         const char *ns = d.getns();
         StringBuilder& ss = curop.debug().str;
         ss << ns;
+        mongolock lk(false);
         Client::Context ctx(ns);
         curop.setRead();
         int ntoreturn = d.pullInt();
diff --git a/db/query.cpp b/db/query.cpp
index 5288c7ae39c..4538fa973e1 100644
--- a/db/query.cpp
+++ b/db/query.cpp
@@ -759,7 +759,6 @@ namespace mongo {
         int queryOptions = q.queryOptions;
         BSONObj snapshotHint;
         
-        Timer t(curop.startTime());
         if( logLevel >= 2 )
             log() << "runQuery: " << ns << jsobj << endl;
         
@@ -955,7 +954,7 @@ namespace mongo {
                     builder.append("n", n);
                     if ( dqo.scanAndOrderRequired() )
                         builder.append("scanAndOrder", true);
-                    builder.append("millis", t.millis());
+                    builder.append("millis", curop.elapsedMillis());
                     if ( !oldPlan.isEmpty() )
                         builder.append( "oldPlan", oldPlan.firstElement().embeddedObject().firstElement().embeddedObject() );
                     if ( hint.eoo() )
@@ -976,7 +975,7 @@ namespace mongo {
             }
         } // end else for regular query
         
-        int duration = t.millis();
+        int duration = curop.elapsedMillis();
         bool dbprofile = curop.shouldDBProfile( duration );
         if ( dbprofile || duration >= cmdLine.slowMS ) {
             ss << " nscanned:" << nscanned << ' ';