Changeset 12745 for source/ariba/utility/system/SystemQueue.cpp

Timestamp:

Feb 25, 2014, 1:35:11 PM (11 years ago)

Author:

hock@…

Message:

Debug output for faulty SystemQueue

File:

• source/ariba/utility/system/SystemQueue.cpp (modified) (12 diffs)

source/ariba/utility/system/SystemQueue.cpp

@@ -37 +37 @@
 
 #include "SystemQueue.h"
+#include <stdexcept>
 
 namespace ariba {
@@ -43 +44 @@
 use_logging_cpp(SystemQueue);
 
+// /// Singleton
+// SystemQueue::_inst(NULL);
+
+
 SystemQueue::SystemQueue()
 #ifndef UNDERLAY_OMNET
- : delayScheduler( &directScheduler ), systemQueueRunning( false )
+ : delayScheduler( &directScheduler ),
+   systemQueueRunning( false )
 #endif
 {
-}
-
-SystemQueue::~SystemQueue() {
+        logging_info("Creating SystemQueue at: " << this);
+}
+
+SystemQueue::~SystemQueue()
+{
 }
 
@@ -57 +65 @@
 {
         static SystemQueue _inst;
-//      std::cout << "SystemQueue::instance: " << &_inst << std::endl;
         return _inst;
+
+//      /// create singleton instance
+//      if ( _inst == NULL )
+//      {
+//              _inst = new SystemQueue();
+//              
+//              logging_info("Creating SystemQueue at: " << _inst);
+//      }
+//      
+//      return *_inst;
 }
 
@@ -209 +226 @@
         boost::mutex::scoped_lock lock( queueMutex );
 
+        if ( delay > 0 )
+        {
+                logging_debug("SystemQueue(" << this << ") : Schedule event in: " << delay << " ms; Events in queue (before insert): " << eventsQueue.size() );
+        }
+
         eventsQueue.push_back( event );
         eventsQueue.back().scheduledTime = boost::posix_time::microsec_clock::local_time();
         eventsQueue.back().delayTime = delay;
         eventsQueue.back().remainingDelay = delay;
+        
+        if ( delay > 0 )
+        {
+                logging_debug("SystemQueue(" << this << ") : Events in queue (after insert): " << eventsQueue.size() );
+        }
 
         onItemInserted( event );
@@ -267 +294 @@
                         // and deliver it to the queue handler
                         SystemEvent ev = obj->eventsQueue.front();
+
+                        // XXX debugging the delay-scheduler..
+                        if ( ev.delayTime > 0 )
+                                logging_debug("SystemQueue(" << obj << ") : Events in queue (before execution): " << obj->eventsQueue.size());
+
                         obj->eventsQueue.erase( obj->eventsQueue.begin() );
 
@@ -275 +307 @@
                         obj->queueMutex.lock();
 
+                        // XXX debugging the delay-scheduler..
+                        if ( ev.delayTime > 0 )
+                                logging_debug("SystemQueue(" << obj << ") : Remaining events in queue (after execution): " << obj->eventsQueue.size());
+
                 } // !obj->eventsQueue.empty() )
         } // while (obj->running)
@@ -320 +356 @@
 void SystemQueue::QueueThreadDelay::onItemInserted( const SystemEvent& event ){
 
-        if( !isSleeping) return;
+        if( !isSleeping)
+        {
+                logging_warn("SystemQueue(" << this << ") : No, I'm not asleep!! New item inserted."); 
+                return;  // TODO Mario: shouldn't we sort anyway..?
+        }
 
         // break an existing sleep and
@@ -336 +376 @@
         EventQueue::iterator iend = eventsQueue.end();
 
+        logging_debug("SystemQueue(" << this << ") : Adjusting remaining delays:");
+        
+        // TODO Mario: What about the just inserted event..?
         for( ; i != iend; i++ ) {
 
@@ -341 +384 @@
                         i->remainingDelay = 0;
                 else
+                {
                         i->remainingDelay -= sleptTime;
+                        
+                        // XXX Mario: Testcode, just to find a bug...
+                        boost::posix_time::time_duration time_passed = sleepEnd - i->getScheduledTime();
+                        logging_debug("SystemQueue(" << this << ") : Total: " <<
+                                        i->delayTime << ", remainingDelay: " << i->remainingDelay <<
+                                        ", time already passed: " << time_passed.total_milliseconds() );
+                }
 
         } // for( ; i != iend; i++ )
@@ -372 +423 @@
                         boost::posix_time::milliseconds(event.remainingDelay);
 
+                logging_debug("SystemQueue(" << this << ") : Sleeping for: " << event.remainingDelay << " ms");
+                
                 {
                         boost::unique_lock<boost::mutex> lock( sleepMutex );
@@ -377 +430 @@
                         sleepStart = boost::posix_time::microsec_clock::local_time();
                         isSleeping = true;
-
+                        
                         sleepCond.timed_wait( lock, duration );
 
@@ -393 +446 @@
         uint32_t sleptTime = duration.total_milliseconds();
 
+        logging_debug("SystemQueue(" << this << ") : Slept for: " << sleptTime << " ms; until: " << sleepEnd);
+        
+        // TODO MARIO: find the bug that loses events...
         if (event.remainingDelay <= sleptTime)
+        {
+                logging_debug("SystemQueue(" << this << ") : Transferring scheduled event into the direct queue. Scheduled time: " << event.getScheduledTime() );
                 transferQueue->insert( event, 0 );
+        }
+        else
+        {
+                logging_warn("SystemQueue(" << this << ") : Scheduled event lost!! :-(   (Sleep should have been " << event.remainingDelay - sleptTime << " ms longer..)");
+                logging_debug("SystemQueue(" << this << ") : Total delay: " << event.delayTime << "; remaining delay: " << event.remainingDelay);
+                
+//              throw std::logic_error("Scheduled event lost!! :-(");
+        }
 }