=== modified file 'storage/ndb/src/common/debugger/EventLogger.cpp' --- storage/ndb/src/common/debugger/EventLogger.cpp 2009-05-27 12:11:46 +0000 +++ storage/ndb/src/common/debugger/EventLogger.cpp 2009-08-07 12:53:17 +0000 @@ -1080,7 +1080,7 @@ const EventLoggerBase::EventRepLogLevelM ROW(StartPhaseCompleted, LogLevel::llStartUp, 4, Logger::LL_INFO ), ROW(CM_REGCONF, LogLevel::llStartUp, 3, Logger::LL_INFO ), ROW(CM_REGREF, LogLevel::llStartUp, 8, Logger::LL_INFO ), - ROW(FIND_NEIGHBOURS, LogLevel::llStartUp, 8, Logger::LL_INFO ), + ROW(FIND_NEIGHBOURS, LogLevel::llStartUp, 7, Logger::LL_INFO ), ROW(NDBStopStarted, LogLevel::llStartUp, 1, Logger::LL_INFO ), ROW(NDBStopCompleted, LogLevel::llStartUp, 1, Logger::LL_INFO ), ROW(NDBStopForced, LogLevel::llStartUp, 1, Logger::LL_ALERT ), === modified file 'storage/ndb/src/kernel/blocks/qmgr/Qmgr.hpp' --- storage/ndb/src/kernel/blocks/qmgr/Qmgr.hpp 2009-05-27 12:11:46 +0000 +++ storage/ndb/src/kernel/blocks/qmgr/Qmgr.hpp 2009-08-07 12:53:17 +0000 @@ -299,7 +299,7 @@ private: Uint16 aFailedNode, UintR aSendFailRep, FailRep::FailCause failCause); - void findNeighbours(Signal* signal); + void findNeighbours(Signal* signal, Uint32 from); Uint16 translateDynamicIdToNodeId(Signal* signal, UintR TdynamicId); void initData(Signal* signal); === modified file 'storage/ndb/src/kernel/blocks/qmgr/QmgrMain.cpp' --- storage/ndb/src/kernel/blocks/qmgr/QmgrMain.cpp 2009-05-27 12:11:46 +0000 +++ storage/ndb/src/kernel/blocks/qmgr/QmgrMain.cpp 2009-08-07 12:56:06 +0000 @@ -247,8 +247,11 @@ Qmgr::execSTART_ORD(Signal* signal) /** * Start timer handling */ + Uint64 now = NdbTick_CurrentMillisecond(); signal->theData[0] = ZTIMER_HANDLING; - sendSignal(QMGR_REF, GSN_CONTINUEB, signal, 1, JBB); + signal->theData[1] = Uint32(now >> 32); + signal->theData[2] = Uint32(now); + sendSignal(QMGR_REF, GSN_CONTINUEB, signal, 3, JBB); NodeRecPtr nodePtr; for (nodePtr.i = 1; nodePtr.i < MAX_NODES; nodePtr.i++) @@ -409,17 +412,19 @@ Qmgr::execDIH_RESTARTCONF(Signal*signal) void Qmgr::setHbDelay(UintR aHbDelay) { + NDB_TICKS now = NdbTick_CurrentMillisecond(); hb_send_timer.setDelay(aHbDelay < 10 ? 10 : aHbDelay); - hb_send_timer.reset(); + hb_send_timer.reset(now); hb_check_timer.setDelay(aHbDelay < 10 ? 10 : aHbDelay); - hb_check_timer.reset(); + hb_check_timer.reset(now); } void Qmgr::setHbApiDelay(UintR aHbApiDelay) { + NDB_TICKS now = NdbTick_CurrentMillisecond(); chbApiDelay = (aHbApiDelay < 100 ? 100 : aHbApiDelay); hb_api_timer.setDelay(chbApiDelay); - hb_api_timer.reset(); + hb_api_timer.reset(now); } void Qmgr::setArbitTimeout(UintR aArbitTimeout) @@ -1929,13 +1934,14 @@ void Qmgr::execCM_ADD(Signal* signal) addNodePtr.p->phase = ZRUNNING; setNodeInfo(addNodePtr.i).m_heartbeat_cnt= 0; c_clusterNodes.set(addNodePtr.i); - findNeighbours(signal); + findNeighbours(signal, __LINE__); /** * SEND A HEARTBEAT IMMEDIATELY TO DECREASE THE RISK THAT WE MISS EARLY * HEARTBEATS. */ sendHeartbeat(signal); + hb_send_timer.reset(0); /** * ENABLE COMMUNICATION WITH ALL BLOCKS WITH THE NEWLY ADDED NODE @@ -1966,7 +1972,7 @@ Qmgr::joinedCluster(Signal* signal, Node */ nodePtr.p->phase = ZRUNNING; setNodeInfo(nodePtr.i).m_heartbeat_cnt= 0; - findNeighbours(signal); + findNeighbours(signal, __LINE__); c_clusterNodes.set(nodePtr.i); c_start.reset(); @@ -1975,6 +1981,7 @@ Qmgr::joinedCluster(Signal* signal, Node * THAT WE MISS EARLY HEARTBEATS. */ sendHeartbeat(signal); + hb_send_timer.reset(0); /** * ENABLE COMMUNICATION WITH ALL BLOCKS IN THE CURRENT CLUSTER AND SET @@ -2112,7 +2119,9 @@ void Qmgr::execCM_ACKADD(Signal* signal) * WE HAVE BEEN INCLUDED INTO THE CLUSTER. IT IS NOW TIME TO CALCULATE WHICH * ARE OUR LEFT AND RIGHT NEIGHBOURS FOR THE HEARTBEAT PROTOCOL. *--------------------------------------------------------------------------*/ -void Qmgr::findNeighbours(Signal* signal) +#include +extern EventLogger g_eventLogger; +void Qmgr::findNeighbours(Signal* signal, Uint32 from) { UintR toldLeftNeighbour; UintR tfnLeftFound; @@ -2122,6 +2131,7 @@ void Qmgr::findNeighbours(Signal* signal NodeRecPtr fnNodePtr; NodeRecPtr fnOwnNodePtr; + Uint32 toldRightNeighbour = cneighbourh; toldLeftNeighbour = cneighbourl; tfnLeftFound = 0; tfnMaxFound = 0; @@ -2222,6 +2232,12 @@ void Qmgr::findNeighbours(Signal* signal }//if }//for sendSignal(CMVMI_REF, GSN_EVENT_REP, signal, Tlen, JBB); + g_eventLogger.info("findNeighbours from: %u old (left: %u right: %u) new (%u %u)", + from, + toldLeftNeighbour, + toldRightNeighbour, + cneighbourl, + cneighbourh); }//Qmgr::findNeighbours() /* @@ -2247,8 +2263,9 @@ void Qmgr::initData(Signal* signal) c_allow_api_connect = 0; ctoStatus = Q_NOT_ACTIVE; + NDB_TICKS now = NdbTick_CurrentMillisecond(); interface_check_timer.setDelay(1000); - interface_check_timer.reset(); + interface_check_timer.reset(now); clatestTransactionCheck = 0; // catch-all for missing initializations @@ -2346,6 +2363,17 @@ void Qmgr::timerHandlingLab(Signal* sign myNodePtr.i = getOwnNodeId(); ptrCheckGuard(myNodePtr, MAX_NDB_NODES, nodeRec); + Uint32 sentHi = signal->theData[1]; + Uint32 sentLo = signal->theData[2]; + Uint64 sent = (Uint64(sentHi) << 32) + sentLo; + + if (TcurrentTime >= sent + 50 || (TcurrentTime < sent)) + { + jam(); + ndbout_c("WARNING: timerHandlingLab now: %llu sent: %llu diff: %d", + TcurrentTime, sent, int(TcurrentTime - sent)); + } + if (myNodePtr.p->phase == ZRUNNING) { jam(); /**--------------------------------------------------------------------- @@ -2354,25 +2382,25 @@ void Qmgr::timerHandlingLab(Signal* sign if (hb_send_timer.check(TcurrentTime)) { jam(); sendHeartbeat(signal); - hb_send_timer.reset(); + hb_send_timer.reset(TcurrentTime); } if (hb_check_timer.check(TcurrentTime)) { jam(); checkHeartbeat(signal); - hb_check_timer.reset(); + hb_check_timer.reset(TcurrentTime); } } if (interface_check_timer.check(TcurrentTime)) { jam(); - interface_check_timer.reset(); + interface_check_timer.reset(TcurrentTime); checkStartInterface(signal, TcurrentTime); } if (hb_api_timer.check(TcurrentTime)) { jam(); - hb_api_timer.reset(); + hb_api_timer.reset(TcurrentTime); apiHbHandlingLab(signal, TcurrentTime); } @@ -2404,7 +2432,9 @@ void Qmgr::timerHandlingLab(Signal* sign // Resend this signal with 10 milliseconds delay. //-------------------------------------------------- signal->theData[0] = ZTIMER_HANDLING; - sendSignalWithDelay(QMGR_REF, GSN_CONTINUEB, signal, 10, 1); + signal->theData[1] = Uint32(TcurrentTime >> 32); + signal->theData[2] = Uint32(TcurrentTime); + sendSignalWithDelay(QMGR_REF, GSN_CONTINUEB, signal, 10, 3); return; }//Qmgr::timerHandlingLab() @@ -4159,7 +4189,7 @@ void Qmgr::failReport(Signal* signal, return; }//if failedNodePtr.p->ndynamicId = 0; - findNeighbours(signal); + findNeighbours(signal, __LINE__); if (failedNodePtr.i == cpresident) { jam(); /**-------------------------------------------------------------------- === modified file 'storage/ndb/src/kernel/blocks/qmgr/timer.hpp' --- storage/ndb/src/kernel/blocks/qmgr/timer.hpp 2009-05-26 18:53:34 +0000 +++ storage/ndb/src/kernel/blocks/qmgr/timer.hpp 2009-08-07 12:53:17 +0000 @@ -39,33 +39,28 @@ public: /** * Start timer */ - inline void reset() { - m_current_time = NdbTick_CurrentMillisecond(); + inline void reset(NDB_TICKS now) { + m_current_time = now; m_alarm_time = m_current_time + m_delay; } - /** - * Check for alarm - */ - inline bool check() { return check(NdbTick_CurrentMillisecond()); } - - inline bool check(NDB_TICKS check_time) { + inline bool check(NDB_TICKS now) { /** * Standard alarm check */ - if (check_time > m_alarm_time) return true; + if (now > m_alarm_time) return true; /** * Time progressing, but it is not alarm time yet */ - if (check_time >= m_current_time) return false; + if (now >= m_current_time) return false; /** * Time has moved backwards */ - reset(); + reset(now); return false; - } + } private: NDB_TICKS m_current_time; === modified file 'storage/ndb/src/kernel/vm/ThreadConfig.cpp' --- storage/ndb/src/kernel/vm/ThreadConfig.cpp 2009-05-27 12:11:46 +0000 +++ storage/ndb/src/kernel/vm/ThreadConfig.cpp 2009-08-07 12:53:17 +0000 @@ -60,11 +60,9 @@ ThreadConfig::scanTimeQueue() // time backwards. We cannot know how long time has past since last // time and we make a best try with 0 milliseconds. //-------------------------------------------------------------------- -#ifdef VM_TRACE ndbout << "Time moved backwards with "; ndbout << (globalData.internalMillisecCounter - currMilliSecond); ndbout << " milliseconds" << endl; -#endif globalData.internalMillisecCounter = currMilliSecond; }//if if (currMilliSecond > (globalData.internalMillisecCounter + 1500)) { @@ -73,11 +71,9 @@ ThreadConfig::scanTimeQueue() // if operator changed the time or if the OS has misbehaved badly. // We set the new time to one second from the past. //-------------------------------------------------------------------- -#ifdef VM_TRACE ndbout << "Time moved forward with "; ndbout << (currMilliSecond - globalData.internalMillisecCounter); ndbout << " milliseconds" << endl; -#endif globalData.internalMillisecCounter = currMilliSecond - 1000; }//if while (((currMilliSecond - globalData.internalMillisecCounter) > 0) &&