@@ -352,17 +352,26 @@ void SimpleMessenger::dispatch_entry()
<< " " << m->get_footer().data_crc << ")"
<< " " << m << " con " << m->get_connection()
<< dendl;
+ utime_t recv_stamp = m->get_recv_stamp();
+ utime_t disp_stamp = g_clock.now();
ms_deliver_dispatch(m);
dispatch_throttle_release(msize);
- dout(20) << "done calling dispatch on " << m << dendl;
+ utime_t done_stamp = g_clock.now();
+ dout(20) << "dispatch_entry done with " << m
+ << " que_et " << disp_stamp - recv_stamp
+ << " op_et " << done_stamp - disp_stamp
+ << " tot_et " << done_stamp - recv_stamp << dendl;
}
}
dispatch_queue.lock.Lock();
}
- if (!dispatch_queue.stop)
+ if (!dispatch_queue.stop) {
+ dout(20) << " Waiting for new work on SimpleMessenger dispatch queue" << dendl;
dispatch_queue.cond.Wait(dispatch_queue.lock); //wait for something to be put on queue
+ dout(20) << " Got new work on SimpleMessenger dispatch queue" << dendl;
+ }
}
dispatch_queue.lock.Unlock();
@@ -553,8 +562,10 @@ void SimpleMessenger::Pipe::queue_received(Message *m, int priority)
dout(20) << "queue_received queuing pipe" << dendl;
if (!queue_items.count(priority))
queue_items[priority] = new xlist<Pipe *>::item(this);
- if (messenger->dispatch_queue.queued_pipes.empty())
+ if (messenger->dispatch_queue.queued_pipes.empty()) {
+ dout(20) << " Waking up SimpleMessenger dispatch queue" << dendl;
messenger->dispatch_queue.cond.Signal();
+ }
messenger->dispatch_queue.queued_pipes[priority].push_back(queue_items[priority]);
}