An Overlay-based
Virtual Network Substrate
SpoVNet

Changeset 12745 for source


Ignore:
Timestamp:
Feb 25, 2014, 1:35:11 PM (5 years ago)
Author:
hock@…
Message:

Debug output for faulty SystemQueue?

Location:
source/ariba/utility/system
Files:
2 edited

Legend:

Unmodified
Added
Removed
  • source/ariba/utility/system/SystemQueue.cpp

    r12524 r12745  
    3737
    3838#include "SystemQueue.h"
     39#include <stdexcept>
    3940
    4041namespace ariba {
     
    4344use_logging_cpp(SystemQueue);
    4445
     46// /// Singleton
     47// SystemQueue::_inst(NULL);
     48
     49
    4550SystemQueue::SystemQueue()
    4651#ifndef UNDERLAY_OMNET
    47  : delayScheduler( &directScheduler ), systemQueueRunning( false )
     52 : delayScheduler( &directScheduler ),
     53   systemQueueRunning( false )
    4854#endif
    4955{
    50 }
    51 
    52 SystemQueue::~SystemQueue() {
     56        logging_info("Creating SystemQueue at: " << this);
     57}
     58
     59SystemQueue::~SystemQueue()
     60{
    5361}
    5462
     
    5765{
    5866        static SystemQueue _inst;
    59 //      std::cout << "SystemQueue::instance: " << &_inst << std::endl;
    6067        return _inst;
     68
     69//      /// create singleton instance
     70//      if ( _inst == NULL )
     71//      {
     72//              _inst = new SystemQueue();
     73//             
     74//              logging_info("Creating SystemQueue at: " << _inst);
     75//      }
     76//     
     77//      return *_inst;
    6178}
    6279
     
    209226        boost::mutex::scoped_lock lock( queueMutex );
    210227
     228        if ( delay > 0 )
     229        {
     230                logging_debug("SystemQueue(" << this << ") : Schedule event in: " << delay << " ms; Events in queue (before insert): " << eventsQueue.size() );
     231        }
     232
    211233        eventsQueue.push_back( event );
    212234        eventsQueue.back().scheduledTime = boost::posix_time::microsec_clock::local_time();
    213235        eventsQueue.back().delayTime = delay;
    214236        eventsQueue.back().remainingDelay = delay;
     237       
     238        if ( delay > 0 )
     239        {
     240                logging_debug("SystemQueue(" << this << ") : Events in queue (after insert): " << eventsQueue.size() );
     241        }
    215242
    216243        onItemInserted( event );
     
    267294                        // and deliver it to the queue handler
    268295                        SystemEvent ev = obj->eventsQueue.front();
     296
     297                        // XXX debugging the delay-scheduler..
     298                        if ( ev.delayTime > 0 )
     299                                logging_debug("SystemQueue(" << obj << ") : Events in queue (before execution): " << obj->eventsQueue.size());
     300
    269301                        obj->eventsQueue.erase( obj->eventsQueue.begin() );
    270302
     
    275307                        obj->queueMutex.lock();
    276308
     309                        // XXX debugging the delay-scheduler..
     310                        if ( ev.delayTime > 0 )
     311                                logging_debug("SystemQueue(" << obj << ") : Remaining events in queue (after execution): " << obj->eventsQueue.size());
     312
    277313                } // !obj->eventsQueue.empty() )
    278314        } // while (obj->running)
     
    320356void SystemQueue::QueueThreadDelay::onItemInserted( const SystemEvent& event ){
    321357
    322         if( !isSleeping) return;
     358        if( !isSleeping)
     359        {
     360                logging_warn("SystemQueue(" << this << ") : No, I'm not asleep!! New item inserted.");
     361                return;  // TODO Mario: shouldn't we sort anyway..?
     362        }
    323363
    324364        // break an existing sleep and
     
    336376        EventQueue::iterator iend = eventsQueue.end();
    337377
     378        logging_debug("SystemQueue(" << this << ") : Adjusting remaining delays:");
     379       
     380        // TODO Mario: What about the just inserted event..?
    338381        for( ; i != iend; i++ ) {
    339382
     
    341384                        i->remainingDelay = 0;
    342385                else
     386                {
    343387                        i->remainingDelay -= sleptTime;
     388                       
     389                        // XXX Mario: Testcode, just to find a bug...
     390                        boost::posix_time::time_duration time_passed = sleepEnd - i->getScheduledTime();
     391                        logging_debug("SystemQueue(" << this << ") : Total: " <<
     392                                        i->delayTime << ", remainingDelay: " << i->remainingDelay <<
     393                                        ", time already passed: " << time_passed.total_milliseconds() );
     394                }
    344395
    345396        } // for( ; i != iend; i++ )
     
    372423                        boost::posix_time::milliseconds(event.remainingDelay);
    373424
     425                logging_debug("SystemQueue(" << this << ") : Sleeping for: " << event.remainingDelay << " ms");
     426               
    374427                {
    375428                        boost::unique_lock<boost::mutex> lock( sleepMutex );
     
    377430                        sleepStart = boost::posix_time::microsec_clock::local_time();
    378431                        isSleeping = true;
    379 
     432                       
    380433                        sleepCond.timed_wait( lock, duration );
    381434
     
    393446        uint32_t sleptTime = duration.total_milliseconds();
    394447
     448        logging_debug("SystemQueue(" << this << ") : Slept for: " << sleptTime << " ms; until: " << sleepEnd);
     449       
     450        // TODO MARIO: find the bug that loses events...
    395451        if (event.remainingDelay <= sleptTime)
     452        {
     453                logging_debug("SystemQueue(" << this << ") : Transferring scheduled event into the direct queue. Scheduled time: " << event.getScheduledTime() );
    396454                transferQueue->insert( event, 0 );
     455        }
     456        else
     457        {
     458                logging_warn("SystemQueue(" << this << ") : Scheduled event lost!! :-(   (Sleep should have been " << event.remainingDelay - sleptTime << " ms longer..)");
     459                logging_debug("SystemQueue(" << this << ") : Total delay: " << event.delayTime << "; remaining delay: " << event.remainingDelay);
     460               
     461//              throw std::logic_error("Scheduled event lost!! :-(");
     462        }
    397463}
    398464
  • source/ariba/utility/system/SystemQueue.h

    r12524 r12745  
    223223
    224224        //********************************************************
     225
     226       
     227//      /// Singleton
     228//      static SystemQueue* _inst;
    225229
    226230        QueueThreadDirect directScheduler;
Note: See TracChangeset for help on using the changeset viewer.