[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
[GNUnet-SVN] r36442 - in gnunet/src: core transport
|
From: |
gnunet |
|
Subject: |
[GNUnet-SVN] r36442 - in gnunet/src: core transport |
|
Date: |
Mon, 5 Oct 2015 18:35:44 +0200 |
Author: grothoff
Date: 2015-10-05 18:35:44 +0200 (Mon, 05 Oct 2015)
New Revision: 36442
Modified:
gnunet/src/core/gnunet-service-core.h
gnunet/src/core/gnunet-service-core_clients.c
gnunet/src/core/gnunet-service-core_neighbours.c
gnunet/src/core/gnunet-service-core_sessions.c
gnunet/src/transport/transport_api.c
Log:
adding DEBUG logic for #3863
Modified: gnunet/src/core/gnunet-service-core.h
===================================================================
--- gnunet/src/core/gnunet-service-core.h 2015-10-05 15:28:21 UTC (rev
36441)
+++ gnunet/src/core/gnunet-service-core.h 2015-10-05 16:35:44 UTC (rev
36442)
@@ -67,6 +67,11 @@
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?
*/
struct GNUNET_TIME_Absolute deadline;
Modified: gnunet/src/core/gnunet-service-core_clients.c
===================================================================
--- gnunet/src/core/gnunet-service-core_clients.c 2015-10-05 15:28:21 UTC
(rev 36441)
+++ gnunet/src/core/gnunet-service-core_clients.c 2015-10-05 16:35:44 UTC
(rev 36442)
@@ -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 @@
*/
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 @@
*/
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 @@
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 @@
/**
- * 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 @@
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 @@
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 @@
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 @@
* @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 @@
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 @@
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 @@
{
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 @@
{
/* 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);
Modified: gnunet/src/core/gnunet-service-core_neighbours.c
===================================================================
--- gnunet/src/core/gnunet-service-core_neighbours.c 2015-10-05 15:28:21 UTC
(rev 36441)
+++ gnunet/src/core/gnunet-service-core_neighbours.c 2015-10-05 16:35:44 UTC
(rev 36442)
@@ -57,10 +57,15 @@
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 @@
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 @@
struct NeighbourMessageEntry *m;
size_t ret;
char *cbuf;
+ struct GNUNET_TIME_Relative delay;
n->th = NULL;
m = n->message_head;
@@ -250,6 +256,7 @@
process_queue (n);
return 0;
}
+ delay = GNUNET_TIME_absolute_get_duration (m->submission_time);
cbuf = buf;
GNUNET_assert (size >= m->size);
memcpy (cbuf,
@@ -256,12 +263,24 @@
&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 @@
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,
Modified: gnunet/src/core/gnunet-service-core_sessions.c
===================================================================
--- gnunet/src/core/gnunet-service-core_sessions.c 2015-10-05 15:28:21 UTC
(rev 36441)
+++ gnunet/src/core/gnunet-service-core_sessions.c 2015-10-05 16:35:44 UTC
(rev 36442)
@@ -125,12 +125,12 @@
/**
* 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
Modified: gnunet/src/transport/transport_api.c
===================================================================
--- gnunet/src/transport/transport_api.c 2015-10-05 15:28:21 UTC (rev
36441)
+++ gnunet/src/transport/transport_api.c 2015-10-05 16:35:44 UTC (rev
36442)
@@ -84,7 +84,7 @@
* 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 @@
/**
* 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 @@
* 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 @@
/**
* 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
/**
* 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 @@
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 @@
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);
| [Prev in Thread] |
Current Thread |
[Next in Thread] |
- [GNUnet-SVN] r36442 - in gnunet/src: core transport,
gnunet <=