diff --git a/src/ifmap/ifmap_log.cc b/src/ifmap/ifmap_log.cc index c4c5cdd9acc..78e174112c2 100644 --- a/src/ifmap/ifmap_log.cc +++ b/src/ifmap/ifmap_log.cc @@ -20,6 +20,11 @@ SandeshTraceBufferPtr IFMapPeerTraceBuf( SandeshTraceBufferPtr IFMapSmTraceBuf( SandeshTraceBufferCreate("IFMapSmTraceBuf", 50000)); +// Trace buffer for update-sender messages +SandeshTraceBufferPtr IFMapUpdateSenderBuf( + SandeshTraceBufferCreate("IFMapUpdateSenderBuf", 50000)); + // Trace buffer for xmpp messages SandeshTraceBufferPtr IFMapXmppTraceBuf( SandeshTraceBufferCreate("IFMapXmppTraceBuf", 50000)); + diff --git a/src/ifmap/ifmap_log.h b/src/ifmap/ifmap_log.h index d0f8d7f2012..ffc9d13e07f 100644 --- a/src/ifmap/ifmap_log.h +++ b/src/ifmap/ifmap_log.h @@ -15,6 +15,7 @@ extern SandeshTraceBufferPtr IFMapTraceBuf; extern SandeshTraceBufferPtr IFMapBigMsgTraceBuf; extern SandeshTraceBufferPtr IFMapPeerTraceBuf; extern SandeshTraceBufferPtr IFMapSmTraceBuf; +extern SandeshTraceBufferPtr IFMapUpdateSenderBuf; extern SandeshTraceBufferPtr IFMapXmppTraceBuf; // Log and trace regular messages @@ -84,6 +85,13 @@ do { \ IFMAP_SM_TRACE(obj##Trace, __VA_ARGS__); \ } while(0) +#define IFMAP_UPD_SENDER_TRACE(obj, ...) \ +do { \ + if (!LoggingDisabled()) { \ + obj::TraceMsg(IFMapUpdateSenderBuf, __FILE__, __LINE__, __VA_ARGS__); \ + } \ +} while(0) + // Log and trace big-sized messages #define IFMAP_DEBUG_LOG_BIG_MSG(obj, category, ...) \ diff --git a/src/ifmap/ifmap_log.sandesh b/src/ifmap/ifmap_log.sandesh index bc151cc1e99..da204409a9e 100644 --- a/src/ifmap/ifmap_log.sandesh +++ b/src/ifmap/ifmap_log.sandesh @@ -392,3 +392,60 @@ trace sandesh IFMapXmlLoadErrorTrace { 2: u32 length } +trace sandesh IFMapUSSplitBlocked { + 1: string message1 + 2: string blocked_set + 3: string message2 + 4: string marker +} + +trace sandesh IFMapUSAllBlocked { + 1: string marker + 2: string message + 3: string entry +} + +trace sandesh IFMapUSSubsetBlocked { + 1: string message1 + 2: string blocked_clients + 3: string message2 + 4: string entry + 5: string message3 + 6: string marker +} + +trace sandesh IFMapUSMoveAfterLast { + 1: string message1 + 2: string marker + 3: string message2 + 4: string entry + 5: string message3 + 6: string blocked_set +} + +trace sandesh IFMapUSMarkerMerge { + 1: string message1 + 2: string marker1 + 3: string message2 + 4: string marker2 +} + +trace sandesh IFMapUSMarkerSplit { + 1: string message1 + 2: string blocked_set + 3: string message2 + 4: string marker +} + +trace sandesh IFMapUSSendScheduled { + 1: string message1 + 2: string send_scheduled + 3: string message2 + 4: u32 client + 5: string marker +} + +trace sandesh IFMapUSQueueActive { + 1: string message + 2: string clients +} diff --git a/src/ifmap/ifmap_update.cc b/src/ifmap/ifmap_update.cc index 65a2bb7853d..4cc212179dc 100644 --- a/src/ifmap/ifmap_update.cc +++ b/src/ifmap/ifmap_update.cc @@ -53,8 +53,7 @@ std::string IFMapUpdate::ConfigName() { } std::string IFMapUpdate::ToString() { - std::string name = ConfigName(); - return TypeToString() + " of " + name; + return TypeToString() + ":" + ConfigName(); } void IFMapUpdate::AdvertiseReset(const BitSet &set) { @@ -73,6 +72,10 @@ IFMapMarker::IFMapMarker() : IFMapListEntry(MARKER) { } +std::string IFMapMarker::ToString() { + return std::string("Marker:") + mask.ToNumberedString(); +} + IFMapState::IFMapState(IFMapNode *node) : sig_(kInvalidSig), data_(node), crc_(0) { } diff --git a/src/ifmap/ifmap_update.h b/src/ifmap/ifmap_update.h index e872b028aae..7ec495600be 100644 --- a/src/ifmap/ifmap_update.h +++ b/src/ifmap/ifmap_update.h @@ -51,12 +51,16 @@ struct IFMapListEntry { }; IFMapListEntry(EntryType type) : type(type), queue_insert_at(0), sequence(0) { } + virtual ~IFMapListEntry() { } boost::intrusive::list_member_hook<> node; EntryType type; uint64_t queue_insert_at; uint64_t sequence; + virtual std::string ToString() { + return std::string("To implement"); + } bool IsMarker() const { return ((type == MARKER) ? true : false); } bool IsUpdate() const { return ((type == UPDATE) ? true : false); } bool IsDelete() const { return ((type == DELETE) ? true : false); } @@ -82,6 +86,7 @@ class IFMapUpdate : public IFMapListEntry { public: IFMapUpdate(IFMapNode *node, bool positive); IFMapUpdate(IFMapLink *link, bool positive); + virtual ~IFMapUpdate() { } void AdvertiseReset(const BitSet &set); void AdvertiseOr(const BitSet &set); @@ -90,7 +95,7 @@ class IFMapUpdate : public IFMapListEntry { const IFMapObjectPtr &data() const { return data_; } std::string ConfigName(); - std::string ToString(); + virtual std::string ToString(); bool IsNode() const { return data_.IsNode(); } bool IsLink() const { return data_.IsLink(); } @@ -103,6 +108,8 @@ class IFMapUpdate : public IFMapListEntry { struct IFMapMarker : public IFMapListEntry { IFMapMarker(); + virtual ~IFMapMarker() { } + virtual std::string ToString(); BitSet mask; }; diff --git a/src/ifmap/ifmap_update_sender.cc b/src/ifmap/ifmap_update_sender.cc index bbb8927d1bd..0b102c2c5f7 100644 --- a/src/ifmap/ifmap_update_sender.cc +++ b/src/ifmap/ifmap_update_sender.cc @@ -38,11 +38,16 @@ class IFMapUpdateSender::SendTask : public Task { for (size_t i = send_scheduled.find_first(); i != BitSet::npos; i = send_scheduled.find_next(i)) { // Dequeue from client marker (i). + IFMAP_UPD_SENDER_TRACE(IFMapUSSendScheduled, "Send scheduled for", + send_scheduled.ToNumberedString(), "client", i, + sender_->queue_->GetMarker(i)->ToString()); sender_->Send(sender_->queue_->GetMarker(i)); } if (sender_->queue_active_) { // Dequeue from tail marker. // Reset queue_active_ + IFMAP_UPD_SENDER_TRACE(IFMapUSQueueActive, "Queue active for", + sender_->queue_->tail_marker()->ToString()); sender_->Send(sender_->queue_->tail_marker()); sender_->queue_active_ = false; } @@ -113,6 +118,8 @@ void IFMapUpdateSender::Send(IFMapMarker *imarker) { // blocked clients, insert it before marker and continue with the ready // set. if (!blocked_clients.empty()) { + IFMAP_UPD_SENDER_TRACE(IFMapUSSplitBlocked, "Splitting blocked clients", + blocked_clients.ToNumberedString(), "from", marker->ToString()); queue_->MarkerSplitBefore(marker, marker, blocked_clients); } @@ -169,6 +176,8 @@ void IFMapUpdateSender::Send(IFMapMarker *imarker) { if (!blocked_set.empty()) { // All the clients in this marker are blocked. We are done. if (blocked_set == marker->mask) { + IFMAP_UPD_SENDER_TRACE(IFMapUSAllBlocked, marker->ToString(), + "blocked before", curr->ToString()); queue_->MoveMarkerBefore(marker, curr); return; } @@ -176,6 +185,9 @@ void IFMapUpdateSender::Send(IFMapMarker *imarker) { // a marker for them 'before' curr since they have seen // everything before curr. Let the ready clients continue the // traversal. + IFMAP_UPD_SENDER_TRACE(IFMapUSSubsetBlocked, "Clients", + blocked_set.ToNumberedString(), "blocked before", + curr->ToString(), "and split from", marker->ToString()); queue_->MarkerSplitBefore(marker, curr, blocked_set); send_set.Reset(blocked_set); } @@ -190,8 +202,8 @@ void IFMapUpdateSender::Send(IFMapMarker *imarker) { // The buffer will be filled in the common case of updates being added // after the tail_marker. + BitSet blk_set; if (!message_->IsEmpty()) { - BitSet blk_set; SendUpdate(base_send_set, &blk_set); } // If the last node in the Q was the tail_marker, we would have already @@ -207,6 +219,9 @@ void IFMapUpdateSender::Send(IFMapMarker *imarker) { // is advantageous since by the time we get the next trigger, a blocked // client could have become ready and splitting the marker now would be // useless. + IFMAP_UPD_SENDER_TRACE(IFMapUSMoveAfterLast, "Moving", marker->ToString(), + "before", last->ToString(), "with blocked_set", + blk_set.ToNumberedString()); queue_->MoveMarkerAfter(marker, last); } return; @@ -279,6 +294,8 @@ IFMapMarker* IFMapUpdateSender::ProcessMarker(IFMapMarker *marker, // If all the clients are ready or all are blocked, merge marker into // next_marker. marker will be deleted. if (blocked_set.empty() || ready_set.empty()) { + IFMAP_UPD_SENDER_TRACE(IFMapUSMarkerMerge, "Merging", marker->ToString(), + "into", next_marker->ToString()); queue_->MarkerMerge(next_marker, marker, marker->mask); assert(next_marker->mask == total_set); } else { @@ -287,8 +304,12 @@ IFMapMarker* IFMapUpdateSender::ProcessMarker(IFMapMarker *marker, // split next_marker into 2 markers: first with the blocked_set and the // second with the ready_set, with first(blocked) preceding the // second(ready). + IFMAP_UPD_SENDER_TRACE(IFMapUSMarkerMerge, "Merging", marker->ToString(), + "into", next_marker->ToString()); queue_->MarkerMerge(next_marker, marker, marker->mask); assert(next_marker->mask == total_set); + IFMAP_UPD_SENDER_TRACE(IFMapUSMarkerSplit, "Splitting blocked clients", + blocked_set.ToNumberedString(), "from", next_marker->ToString()); queue_->MarkerSplitBefore(next_marker, next_marker, blocked_set); } if (ready_set.empty()) {