debug packetflow

prrt/proto/processes/dataReceiver.c

@@ -107,6 +107,8 @@ static bool send_feedback(PrrtSocket *sock_ptr,
     pthread_setcancelstate(PTHREAD_CANCEL_ENABLE, NULL);
     free(buf);
 
+    debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u sent", (unsigned long) PrrtClock_get_current_time_us(), PrrtPacket_type(feedback_pkt_ptr), feedback_pkt_ptr->sequenceNumber);
+
     PrrtPacket_destroy(feedback_pkt_ptr);
     XlapTimeStampCycle(sock_ptr, kind, seqno, SendFeedbackEnd);
 
@@ -135,6 +137,7 @@ static void handle_data_packet(PrrtSocket *sock_ptr, PrrtPacket *packet) {
     if (PrrtTimestamp_cmp(now, payload->packetTimeout_us) > 0) {
         debug(DEBUG_DATARECEIVER, "Timeout data packet %u (%lu > %lu)", seqno, (unsigned long) now,
               (unsigned long) payload->packetTimeout_us);
+        debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u exeeded deadline %lu", (unsigned long) now, PrrtPacket_type(packet), packet->sequenceNumber, (unsigned long) PrrtDataPacket_packet_timeout(packet));
         PrrtDeliveredPacketTable_test_set_is_number_relevant(sock_ptr->deliveredPacketTable, packet->sequenceNumber);
         PrrtPacket_destroy(packet);
     } else if (!PrrtDeliveredPacketTable_test_set_is_number_relevant(sock_ptr->deliveredPacketTable,
@@ -320,6 +323,7 @@ void *receive_data_loop(void *ptr) {
 
         prrtPacketType_t packetType = PrrtPacket_type(packet);
         debug(DEBUG_DATARECEIVER, "received packet %d:%u", (int) packetType, seqno);
+        debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u received", (unsigned long) PrrtClock_get_current_time_us(), PrrtPacket_type(packet), packet->sequenceNumber);
         packet->channelReceive = packet_recv_timestamp;
 
         enum XlapTimestampPacketKind kind = ts_any_packet;

prrt/proto/processes/dataTransmitter.c

@@ -156,6 +156,7 @@ static bool send_packet(PrrtSocket *sock_ptr, PrrtPacket *packet) {
     send_to_socket(sock_ptr, buf, PrrtPacket_size(packet), &timestamp, &cyclestamp);
     XlapTimeStampValue(sock_ptr, ts_data_packet, packet->sequenceNumber, ChannelTransmit, timestamp);
     XlapCycleStampValue(sock_ptr, ts_data_packet, packet->sequenceNumber, ChannelTransmit, cyclestamp);
+    debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u sent", (unsigned long) PrrtClock_get_current_time_us(), PrrtPacket_type(packet), packet->sequenceNumber);
 
     PrrtReceiver_add_outstanding_packet_state(sock_ptr->receiver, packet, PrrtClock_TimespecToPrrtTimestamp(timestamp));
 

prrt/proto/socket.c

@@ -36,6 +36,8 @@ static inline prrtPacketLength_t deliver_packet(const PrrtSocket *s, void *buffe
             len += timespec_size;
         }
 
+        debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u delivered", (unsigned long) PrrtClock_get_current_time_us(), PrrtPacket_type(packet), packet->sequenceNumber);
+
         XlapTimeStampCycle(s, ts_data_packet, packet->sequenceNumber, CopyOutputEnd);
 
         memcpy(addr, &(packet->sender_addr), sizeof(struct sockaddr_in));

prrt/proto/stores/packetDeliveryStore.c

@@ -118,6 +118,7 @@ PrrtPacket *PrrtPacketDeliveryStore_get_packet(PrrtPacketDeliveryStore *store, p
             store->tree = BPTree_delete(store->tree, PrrtDataPacket_packet_timeout(packet));
             prrtTimestamp_t now = PrrtClock_get_current_time_us();
             if (PrrtTimestamp_cmp(now, PrrtDataPacket_packet_timeout(packet)) > 0) {
+                debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u exeeded deadline %lu", (unsigned long) now, PrrtPacket_type(packet), packet->sequenceNumber, (unsigned long) PrrtDataPacket_packet_timeout(packet));
                 timed_out = true;
                 PrrtPacket_destroy(packet);
                 packet = NULL;
@@ -138,6 +139,7 @@ bool PrrtPacketDeliveryStore_insert(PrrtPacketDeliveryStore *store, PrrtPacket *
     check(pthread_mutex_lock(&store->lock) == EXIT_SUCCESS, "Lock failed.");
     prrtTimestamp_t timeout = PrrtDataPacket_packet_timeout(packet);
     store->tree = BPTree_insert(store->tree, timeout, packet);
+    debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u inserted", (unsigned long) PrrtClock_get_current_time_us(), PrrtPacket_type(packet), packet->sequenceNumber);
 
     pthread_cond_broadcast(&store->wait_for_data);
 
@@ -161,6 +163,7 @@ void PrrtPacketDeliveryStore_cleanup(PrrtPacketDeliveryStore *store, prrtTimesta
     while (List_count(packetList) > 0) {
         PrrtPacket *packet = List_shift(packetList);
         store->tree = BPTree_delete(store->tree, PrrtDataPacket_packet_timeout(packet));
+        debug(DEBUG_PACKETFLOW, "%lu: Packet %d:%u exeeded deadline %lu", (unsigned long) now, PrrtPacket_type(packet), packet->sequenceNumber, (unsigned long) PrrtDataPacket_packet_timeout(packet));
         PrrtPacket_destroy(packet);
     }
     List_destroy(packetList);

prrt/util/dbg.h

@@ -15,12 +15,13 @@
 #define DEBUG_RECEIVER        0
 #define DEBUG_SENDER          0
 #define DEBUG_SOCKET          0
-#define DEBUG_DATARECEIVER    1
+#define DEBUG_DATARECEIVER    0
 #define DEBUG_CLEANUP         0
 #define DEBUG_DATATRANSMITTER 0
 #define DEBUG_HARDSTAMPING    0
 #define DEBUG_FEEDBACK        0
-#define DEBUG_TIMERECEIVER    1
+#define DEBUG_TIMERECEIVER    0
+#define DEBUG_PACKETFLOW      1
 
 #ifdef DEBUG
 #define debug(DOMAIN, M, ...) do { if (DEBUG_ALL||(DOMAIN)) fprintf(stderr, "DEBUG %-20s %s:%d: " M "\n", #DOMAIN + 6, __FILE__, __LINE__, ##__VA_ARGS__); } while (0)