From 4dcb414e2faabc800577c25dec3b63e3ceaaa84b Mon Sep 17 00:00:00 2001 From: Christian Grothoff Date: Mon, 5 Oct 2015 16:35:44 +0000 Subject: adding DEBUG logic for #3863 --- src/core/gnunet-service-core.h | 5 ++ src/core/gnunet-service-core_clients.c | 94 +++++++++++++++++++++++-------- src/core/gnunet-service-core_neighbours.c | 36 +++++++++--- src/core/gnunet-service-core_sessions.c | 4 +- src/transport/transport_api.c | 61 ++++++++++++-------- 5 files changed, 143 insertions(+), 57 deletions(-) diff --git a/src/core/gnunet-service-core.h b/src/core/gnunet-service-core.h index a95dc561f..15e995921 100644 --- a/src/core/gnunet-service-core.h +++ b/src/core/gnunet-service-core.h @@ -66,6 +66,11 @@ struct GSC_ClientActiveRequest */ struct GNUNET_PeerIdentity target; + /** + * At what time did we first see this request? + */ + struct GNUNET_TIME_Absolute received_time; + /** * By what time would the client want to see this message out? */ diff --git a/src/core/gnunet-service-core_clients.c b/src/core/gnunet-service-core_clients.c index e90d91529..57a5d5826 100644 --- a/src/core/gnunet-service-core_clients.c +++ b/src/core/gnunet-service-core_clients.c @@ -29,6 +29,7 @@ #include "gnunet_transport_service.h" #include "gnunet-service-core.h" #include "gnunet-service-core_clients.h" +#include "gnunet-service-core_neighbours.h" #include "gnunet-service-core_sessions.h" #include "gnunet-service-core_typemap.h" #include "core.h" @@ -149,7 +150,8 @@ find_client (struct GNUNET_SERVER_Client *client) */ static void send_to_client (struct GSC_Client *client, - const struct GNUNET_MessageHeader *msg, int can_drop) + const struct GNUNET_MessageHeader *msg, + int can_drop) { GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, "Preparing to send %u bytes of message of type %u to client.\n", @@ -219,8 +221,10 @@ type_match (uint16_t type, struct GSC_Client *c) */ static void send_to_all_clients (const struct GNUNET_PeerIdentity *partner, - const struct GNUNET_MessageHeader *msg, int can_drop, - uint32_t options, uint16_t type) + const struct GNUNET_MessageHeader *msg, + int can_drop, + uint32_t options, + uint16_t type) { struct GSC_Client *c; int tm; @@ -399,6 +403,7 @@ handle_client_send_request (void *cls, GSC_SESSIONS_dequeue_request (car); } car->target = req->peer; + car->received_time = GNUNET_TIME_absolute_get (); car->deadline = GNUNET_TIME_absolute_ntoh (req->deadline); car->priority = (enum GNUNET_CORE_Priority) ntohl (req->priority); car->msize = ntohs (req->size); @@ -441,7 +446,7 @@ struct TokenizerContext /** - * Handle CORE_SEND request. + * Handle #GNUNET_MESSAGE_TYPE_CORE_CORE_SEND request. * * @param cls unused * @param client the client issuing the request @@ -456,6 +461,7 @@ handle_client_send (void *cls, struct GSC_Client *c; struct TokenizerContext tc; uint16_t msize; + struct GNUNET_TIME_Relative delay; msize = ntohs (message->size); if (msize < @@ -476,8 +482,9 @@ handle_client_send (void *cls, GNUNET_SERVER_receive_done (client, GNUNET_SYSERR); return; } - tc.car = - GNUNET_CONTAINER_multipeermap_get (c->requests, &sm->peer); + tc.car + = GNUNET_CONTAINER_multipeermap_get (c->requests, + &sm->peer); if (NULL == tc.car) { /* Must have been that we first approved the request, then got disconnected @@ -489,28 +496,49 @@ handle_client_send (void *cls, gettext_noop ("# messages discarded (session disconnected)"), 1, GNUNET_NO); - GNUNET_SERVER_receive_done (client, GNUNET_OK); + GNUNET_SERVER_receive_done (client, + GNUNET_OK); return; } + delay = GNUNET_TIME_absolute_get_duration (tc.car->received_time); + tc.cork = ntohl (sm->cork); + tc.priority = (enum GNUNET_CORE_Priority) ntohl (sm->priority); + if (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us) + GNUNET_log (GNUNET_ERROR_TYPE_WARNING, + "Client waited %s for transmission of %u bytes to `%s'%s, CORE queue is %u entries\n", + GNUNET_STRINGS_relative_time_to_string (delay, + GNUNET_YES), + msize, + GNUNET_i2s (&sm->peer), + tc.cork ? "" : " (corked)", + GSC_NEIGHBOURS_get_queue_size (&sm->peer)); + else + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Client waited %s for transmission of %u bytes to `%s'%s, CORE queue is %u entries\n", + GNUNET_STRINGS_relative_time_to_string (delay, + GNUNET_YES), + msize, + GNUNET_i2s (&sm->peer), + tc.cork ? "" : " (corked)", + GSC_NEIGHBOURS_get_queue_size (&sm->peer)); + GNUNET_assert (GNUNET_YES == GNUNET_CONTAINER_multipeermap_remove (c->requests, &sm->peer, tc.car)); - tc.cork = ntohl (sm->cork); - tc.priority = (enum GNUNET_CORE_Priority) ntohl (sm->priority); - GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Client asked for transmission of %u bytes to `%s' %s\n", - msize, - GNUNET_i2s (&sm->peer), tc.cork ? "now" : ""); GNUNET_SERVER_mst_receive (client_mst, &tc, - (const char *) &sm[1], msize, - GNUNET_YES, GNUNET_NO); + (const char *) &sm[1], + msize, + GNUNET_YES, + GNUNET_NO); if (0 != - memcmp (&tc.car->target, &GSC_my_identity, + memcmp (&tc.car->target, + &GSC_my_identity, sizeof (struct GNUNET_PeerIdentity))) GSC_SESSIONS_dequeue_request (tc.car); GNUNET_free (tc.car); - GNUNET_SERVER_receive_done (client, GNUNET_OK); + GNUNET_SERVER_receive_done (client, + GNUNET_OK); } @@ -525,7 +553,8 @@ handle_client_send (void *cls, * @param message the actual message */ static int -client_tokenizer_callback (void *cls, void *client, +client_tokenizer_callback (void *cls, + void *client, const struct GNUNET_MessageHeader *message) { struct TokenizerContext *tc = client; @@ -535,9 +564,13 @@ client_tokenizer_callback (void *cls, void *client, GNUNET_snprintf (buf, sizeof (buf), gettext_noop ("# bytes of messages of type %u received"), (unsigned int) ntohs (message->type)); - GNUNET_STATISTICS_update (GSC_stats, buf, ntohs (message->size), GNUNET_NO); + GNUNET_STATISTICS_update (GSC_stats, + buf, + ntohs (message->size), + GNUNET_NO); if (0 == - memcmp (&car->target, &GSC_my_identity, + memcmp (&car->target, + &GSC_my_identity, sizeof (struct GNUNET_PeerIdentity))) { GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, @@ -618,7 +651,8 @@ handle_client_disconnect (void *cls, if (NULL == client) return; GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Client %p has disconnected from core service.\n", client); + "Client %p has disconnected from core service.\n", + client); c = find_client (client); if (c == NULL) return; /* client never sent INIT */ @@ -654,6 +688,8 @@ GSC_CLIENTS_solicit_request (struct GSC_ClientActiveRequest *car) { struct GSC_Client *c; struct SendMessageReady smr; + struct GNUNET_TIME_Relative delay; + struct GNUNET_TIME_Relative left; c = car->client_handle; if (GNUNET_YES != @@ -662,12 +698,26 @@ GSC_CLIENTS_solicit_request (struct GSC_ClientActiveRequest *car) { /* connection has gone down since, drop request */ GNUNET_assert (0 != - memcmp (&car->target, &GSC_my_identity, + memcmp (&car->target, + &GSC_my_identity, sizeof (struct GNUNET_PeerIdentity))); GSC_SESSIONS_dequeue_request (car); GSC_CLIENTS_reject_request (car); return; } + delay = GNUNET_TIME_absolute_get_duration (car->received_time); + left = GNUNET_TIME_absolute_get_remaining (car->deadline); + if ( (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us) || + (0 == left.rel_value_us) ) + GNUNET_log (GNUNET_ERROR_TYPE_WARNING, + "Client waited %s for permission to transmit to `%s'%s (priority %u)\n", + GNUNET_STRINGS_relative_time_to_string (delay, + GNUNET_YES), + GNUNET_i2s (&car->target), + (0 == left.rel_value_us) + ? " (past deadline)" + : "", + car->priority); smr.header.size = htons (sizeof (struct SendMessageReady)); smr.header.type = htons (GNUNET_MESSAGE_TYPE_CORE_SEND_READY); smr.size = htons (car->msize); diff --git a/src/core/gnunet-service-core_neighbours.c b/src/core/gnunet-service-core_neighbours.c index 5e5ed4db3..f89206dfe 100644 --- a/src/core/gnunet-service-core_neighbours.c +++ b/src/core/gnunet-service-core_neighbours.c @@ -57,9 +57,14 @@ struct NeighbourMessageEntry struct GNUNET_TIME_Absolute deadline; /** - * How long is the message? (number of bytes following the "struct - * MessageEntry", but not including the size of "struct - * MessageEntry" itself!) + * What time did we submit the request? + */ + struct GNUNET_TIME_Absolute submission_time; + + /** + * How long is the message? (number of bytes following the `struct + * MessageEntry`, but not including the size of `struct + * MessageEntry` itself!) */ size_t size; @@ -157,7 +162,7 @@ free_neighbour (struct Neighbour *n) struct NeighbourMessageEntry *m; GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Destroying neighbour entry for peer `%4s'\n", + "Destroying neighbour entry for peer `%s'\n", GNUNET_i2s (&n->peer)); while (NULL != (m = n->message_head)) { @@ -227,6 +232,7 @@ transmit_ready (void *cls, struct NeighbourMessageEntry *m; size_t ret; char *cbuf; + struct GNUNET_TIME_Relative delay; n->th = NULL; m = n->message_head; @@ -250,18 +256,31 @@ transmit_ready (void *cls, process_queue (n); return 0; } + delay = GNUNET_TIME_absolute_get_duration (m->submission_time); cbuf = buf; GNUNET_assert (size >= m->size); memcpy (cbuf, &m[1], m->size); ret = m->size; - GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Copied message of type %u and size %u into transport buffer for `%4s'\n", + if (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us) + GNUNET_log (GNUNET_ERROR_TYPE_WARNING, + "Copied message of type %u and size %u into transport buffer for `%s' with delay of %s\n", (unsigned int) ntohs (((struct GNUNET_MessageHeader *) &m[1])->type), (unsigned int) ret, - GNUNET_i2s (&n->peer)); + GNUNET_i2s (&n->peer), + GNUNET_STRINGS_relative_time_to_string (delay, + GNUNET_YES)); + else + GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, + "Copied message of type %u and size %u into transport buffer for `%s' with delay of %s\n", + (unsigned int) + ntohs (((struct GNUNET_MessageHeader *) &m[1])->type), + (unsigned int) ret, + GNUNET_i2s (&n->peer), + GNUNET_STRINGS_relative_time_to_string (delay, + GNUNET_YES)); GNUNET_free (m); n->has_excess_bandwidth = GNUNET_NO; process_queue (n); @@ -295,11 +314,12 @@ process_queue (struct Neighbour *n) return; } GNUNET_log (GNUNET_ERROR_TYPE_DEBUG, - "Asking transport for transmission of %u bytes to `%4s' in next %s\n", + "Asking transport for transmission of %u bytes to `%s' in next %s\n", (unsigned int) m->size, GNUNET_i2s (&n->peer), GNUNET_STRINGS_relative_time_to_string (GNUNET_TIME_absolute_get_remaining (m->deadline), GNUNET_NO)); + m->submission_time = GNUNET_TIME_absolute_get (); n->th = GNUNET_TRANSPORT_notify_transmit_ready (transport, &n->peer, diff --git a/src/core/gnunet-service-core_sessions.c b/src/core/gnunet-service-core_sessions.c index 8706c873e..bbabf8866 100644 --- a/src/core/gnunet-service-core_sessions.c +++ b/src/core/gnunet-service-core_sessions.c @@ -125,12 +125,12 @@ struct Session /** * Task to transmit corked messages with a delay. */ - struct GNUNET_SCHEDULER_Task * cork_task; + struct GNUNET_SCHEDULER_Task *cork_task; /** * Task to transmit our type map. */ - struct GNUNET_SCHEDULER_Task * typemap_task; + struct GNUNET_SCHEDULER_Task *typemap_task; /** * Retransmission delay we currently use for the typemap diff --git a/src/transport/transport_api.c b/src/transport/transport_api.c index 8ebf82b8a..312762ba4 100644 --- a/src/transport/transport_api.c +++ b/src/transport/transport_api.c @@ -84,7 +84,7 @@ struct GNUNET_TRANSPORT_TransmitHandle * Task to trigger request timeout if the request is stalled due to * congestion. */ - struct GNUNET_SCHEDULER_Task * timeout_task; + struct GNUNET_SCHEDULER_Task *timeout_task; /** * How many bytes is our notify callback waiting for? @@ -171,7 +171,7 @@ struct GNUNET_TRANSPORT_GetHelloHandle /** * Task for calling the HelloUpdateCallback when we already have a HELLO */ - struct GNUNET_SCHEDULER_Task * notify_task; + struct GNUNET_SCHEDULER_Task *notify_task; /** * Closure for @e rec. @@ -422,7 +422,7 @@ struct GNUNET_TRANSPORT_Handle * Heap sorting peers with pending messages by the timestamps that * specify when we could next send a message to the respective peer. * Excludes control messages (which can always go out immediately). - * Maps time stamps to 'struct Neighbour' entries. + * Maps time stamps to `struct Neighbour` entries. */ struct GNUNET_CONTAINER_Heap *ready_heap; @@ -439,10 +439,10 @@ struct GNUNET_TRANSPORT_Handle /** * ID of the task trying to trigger transmission for a peer while * maintaining bandwidth quotas. In use if there are no control - * messages and the smallest entry in the 'ready_heap' has a time + * messages and the smallest entry in the @e ready_heap has a time * stamp in the future. */ - struct GNUNET_SCHEDULER_Task * quota_task; + struct GNUNET_SCHEDULER_Task *quota_task; /** * Delay until we try to reconnect. @@ -515,7 +515,7 @@ outbound_bw_tracker_update (void *cls) delay = GNUNET_BANDWIDTH_tracker_get_delay (&n->out_tracker, n->th->notify_size + n->traffic_overhead); LOG (GNUNET_ERROR_TYPE_DEBUG, - "New outbound delay %llu us\n", + "New outbound delay %s us\n", GNUNET_STRINGS_relative_time_to_string (delay, GNUNET_NO)); GNUNET_CONTAINER_heap_update_cost (n->h->ready_heap, @@ -554,7 +554,7 @@ neighbour_add (struct GNUNET_TRANSPORT_Handle *h, struct Neighbour *n; LOG (GNUNET_ERROR_TYPE_DEBUG, - "Creating entry for neighbour `%4s'.\n", + "Creating entry for neighbour `%s'.\n", GNUNET_i2s (pid)); n = GNUNET_new (struct Neighbour); n->id = *pid; @@ -664,7 +664,7 @@ demultiplexer (void *cls, break; } LOG (GNUNET_ERROR_TYPE_DEBUG, - "Receiving (my own) HELLO message (%u bytes), I am `%4s'.\n", + "Receiving (my own) HELLO message (%u bytes), I am `%s'.\n", (unsigned int) size, GNUNET_i2s (&me)); GNUNET_free_non_null (h->my_hello); @@ -698,7 +698,7 @@ demultiplexer (void *cls, break; } LOG (GNUNET_ERROR_TYPE_DEBUG, - "Receiving CONNECT message for `%4s'.\n", + "Receiving CONNECT message for `%s'.\n", GNUNET_i2s (&cim->id)); n = neighbour_find (h, &cim->id); if (NULL != n) @@ -709,7 +709,7 @@ demultiplexer (void *cls, n = neighbour_add (h, &cim->id); LOG (GNUNET_ERROR_TYPE_DEBUG, - "Receiving CONNECT message for `%4s' with quota %u\n", + "Receiving CONNECT message for `%s' with quota %u\n", GNUNET_i2s (&cim->id), ntohl (cim->quota_out.value__)); GNUNET_BANDWIDTH_tracker_update_quota (&n->out_tracker, @@ -727,7 +727,7 @@ demultiplexer (void *cls, dim = (const struct DisconnectInfoMessage *) msg; GNUNET_break (ntohl (dim->reserved) == 0); LOG (GNUNET_ERROR_TYPE_DEBUG, - "Receiving DISCONNECT message for `%4s'.\n", + "Receiving DISCONNECT message for `%s'.\n", GNUNET_i2s (&dim->peer)); n = neighbour_find (h, &dim->peer); if (NULL == n) @@ -792,7 +792,7 @@ demultiplexer (void *cls, break; } LOG (GNUNET_ERROR_TYPE_DEBUG, - "Received message of type %u from `%4s'.\n", + "Received message of type %u from `%s'.\n", ntohs (imm->type), GNUNET_i2s (&im->peer)); n = neighbour_find (h, &im->peer); if (NULL == n) @@ -816,7 +816,7 @@ demultiplexer (void *cls, if (NULL == n) break; LOG (GNUNET_ERROR_TYPE_DEBUG, - "Receiving SET_QUOTA message for `%4s' with quota %u\n", + "Receiving SET_QUOTA message for `%s' with quota %u\n", GNUNET_i2s (&qm->peer), ntohl (qm->quota.value__)); GNUNET_BANDWIDTH_tracker_update_quota (&n->out_tracker, @@ -1262,7 +1262,7 @@ send_try_connect (void *cls, if (NULL == buf) { LOG (GNUNET_ERROR_TYPE_DEBUG, - "Discarding `%s' request to `%4s' due to error in transport service connection.\n", + "Discarding `%s' request to `%s' due to error in transport service connection.\n", "REQUEST_CONNECT", GNUNET_i2s (&tch->pid)); if (NULL != tch->cb) @@ -1272,7 +1272,7 @@ send_try_connect (void *cls, return 0; } LOG (GNUNET_ERROR_TYPE_DEBUG, - "Transmitting `%s' request with respect to `%4s'.\n", + "Transmitting `%s' request with respect to `%s'.\n", "REQUEST_CONNECT", GNUNET_i2s (&tch->pid)); GNUNET_assert (size >= sizeof (struct TransportRequestConnectMessage)); @@ -1367,7 +1367,7 @@ send_try_disconnect (void *cls, if (NULL == buf) { LOG (GNUNET_ERROR_TYPE_DEBUG, - "Discarding `%s' request to `%4s' due to error in transport service connection.\n", + "Discarding `%s' request to `%s' due to error in transport service connection.\n", "REQUEST_DISCONNECT", GNUNET_i2s (&tdh->pid)); if (NULL != tdh->cb) @@ -1377,7 +1377,7 @@ send_try_disconnect (void *cls, return 0; } LOG (GNUNET_ERROR_TYPE_DEBUG, - "Transmitting `%s' request with respect to `%4s'.\n", + "Transmitting `%s' request with respect to `%s'.\n", "REQUEST_DISCONNECT", GNUNET_i2s (&tdh->pid)); GNUNET_assert (size >= sizeof (struct TransportRequestDisconnectMessage)); @@ -1620,7 +1620,7 @@ GNUNET_TRANSPORT_offer_hello (struct GNUNET_TRANSPORT_Handle *handle, msg = GNUNET_malloc (size); memcpy (msg, hello, size); LOG (GNUNET_ERROR_TYPE_DEBUG, - "Offering `%s' message of `%4s' to transport for validation.\n", "HELLO", + "Offering HELLO message of `%s' to transport for validation.\n", GNUNET_i2s (&peer)); ohh = GNUNET_new (struct GNUNET_TRANSPORT_OfferHelloHandle); @@ -1638,7 +1638,7 @@ GNUNET_TRANSPORT_offer_hello (struct GNUNET_TRANSPORT_Handle *handle, /** * Cancel the request to transport to offer the HELLO message * - * @param ohh the GNUNET_TRANSPORT_OfferHelloHandle to cancel + * @param ohh the handle for the operation to cancel */ void GNUNET_TRANSPORT_offer_hello_cancel (struct GNUNET_TRANSPORT_OfferHelloHandle *ohh) @@ -1716,7 +1716,9 @@ GNUNET_TRANSPORT_get_hello (struct GNUNET_TRANSPORT_Handle *handle, hwl->rec = rec; hwl->rec_cls = rec_cls; hwl->handle = handle; - GNUNET_CONTAINER_DLL_insert (handle->hwl_head, handle->hwl_tail, hwl); + GNUNET_CONTAINER_DLL_insert (handle->hwl_head, + handle->hwl_tail, + hwl); if (NULL != handle->my_hello) hwl->notify_task = GNUNET_SCHEDULER_add_now (&call_hello_update_cb_async, hwl); @@ -1928,11 +1930,20 @@ GNUNET_TRANSPORT_notify_transmit_ready (struct GNUNET_TRANSPORT_Handle *handle, n->traffic_overhead = 0; if (delay.rel_value_us > timeout.rel_value_us) delay.rel_value_us = 0; /* notify immediately (with failure) */ - LOG (GNUNET_ERROR_TYPE_DEBUG, - "Bandwidth tracker allows next transmission to peer %s in %s\n", - GNUNET_i2s (target), - GNUNET_STRINGS_relative_time_to_string (delay, - GNUNET_YES)); + if (delay.rel_value_us > GNUNET_TIME_UNIT_SECONDS.rel_value_us) + LOG (GNUNET_ERROR_TYPE_WARNING, + "At bandwidth %u byte/s next transmission to %s in %s\n", + (unsigned int) n->out_tracker.available_bytes_per_s__, + GNUNET_i2s (target), + GNUNET_STRINGS_relative_time_to_string (delay, + GNUNET_YES)); + else + LOG (GNUNET_ERROR_TYPE_DEBUG, + "At bandwidth %u byte/s next transmission to %s in %s\n", + (unsigned int) n->out_tracker.available_bytes_per_s__, + GNUNET_i2s (target), + GNUNET_STRINGS_relative_time_to_string (delay, + GNUNET_YES)); n->hn = GNUNET_CONTAINER_heap_insert (handle->ready_heap, n, delay.rel_value_us); -- cgit v1.2.3