2 This file is part of GNUnet.
3 (C) 2010-2013 Christian Grothoff (and other contributing authors)
5 GNUnet is free software; you can redistribute it and/or modify
6 it under the terms of the GNU General Public License as published
7 by the Free Software Foundation; either version 3, or (at your
8 option) any later version.
10 GNUnet is distributed in the hope that it will be useful, but
11 WITHOUT ANY WARRANTY; without even the implied warranty of
12 MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
13 General Public License for more details.
15 You should have received a copy of the GNU General Public License
16 along with GNUnet; see the file COPYING. If not, write to the
17 Free Software Foundation, Inc., 59 Temple Place - Suite 330,
18 Boston, MA 02111-1307, USA.
21 * @file ats/perf_ats_logging.c
22 * @brief ats benchmark: logging for performance tests
23 * @author Christian Grothoff
24 * @author Matthias Wachs
27 #include "gnunet_util_lib.h"
30 #define THROUGHPUT_TEMPLATE "#!/usr/bin/gnuplot \n" \
31 "set datafile separator ';' \n" \
32 "set title \"Throughput between Master and Slaves\" \n" \
33 "set xlabel \"Time in ms\" \n" \
34 "set ylabel \"Bytes/s\" \n"
36 #define RTT_TEMPLATE "#!/usr/bin/gnuplot \n" \
37 "set datafile separator ';' \n" \
38 "set title \"Application level roundtrip time between Master and Slaves\" \n" \
39 "set xlabel \"Time in ms\" \n" \
40 "set ylabel \"ms\" \n"
42 #define LOG_ITEMS_PER_PEER 7
43 #define LOG_ITEMS_TIME 2
45 #define LOG_ITEMS_BYTES_SENT 1
46 #define LOG_ITEMS_MSGS_SENT 2
47 #define LOG_ITEMS_THROUGHPUT_SENT 3
48 #define LOG_ITEMS_BYTES_RECV 4
49 #define LOG_ITEMS_MSGS_RECV 5
50 #define LOG_ITEMS_THROUGHPUT_RECV 6
51 #define LOG_ITEMS_APP_RTT 7
57 static GNUNET_SCHEDULER_TaskIdentifier log_task;
60 * Reference to perf_ats' masters
65 static struct GNUNET_TIME_Relative frequency;
68 * A single logging time step for a partner
70 struct PartnerLoggingTimestep
75 struct BenchmarkPeer *slave;
78 * Total number of messages this peer has sent
80 unsigned int total_messages_sent;
83 * Total number of bytes this peer has sent
85 unsigned int total_bytes_sent;
88 * Total number of messages this peer has received
90 unsigned int total_messages_received;
93 * Total number of bytes this peer has received
95 unsigned int total_bytes_received;
98 * Accumulated RTT for all messages
100 unsigned int total_app_rtt;
103 * Current application level delay
105 unsigned int app_rtt;
107 /* Current ATS properties */
109 uint32_t ats_distance;
113 uint32_t bandwidth_in;
115 uint32_t bandwidth_out;
117 uint32_t ats_utilization_up;
119 uint32_t ats_utilization_down;
121 uint32_t ats_network_type;
123 uint32_t ats_cost_wan;
125 uint32_t ats_cost_lan;
127 uint32_t ats_cost_wlan;
132 * A single logging time step for a peer
134 struct PeerLoggingTimestep
139 struct PeerLoggingTimestep *next;
144 struct PeerLoggingTimestep *prev;
149 struct GNUNET_TIME_Absolute timestamp;
152 * Total number of messages this peer has sent
154 unsigned int total_messages_sent;
157 * Total number of bytes this peer has sent
159 unsigned int total_bytes_sent;
162 * Total number of messages this peer has received
164 unsigned int total_messages_received;
167 * Total number of bytes this peer has received
169 unsigned int total_bytes_received;
174 struct PartnerLoggingTimestep *slaves_log;
178 * Entry for a benchmark peer
185 struct BenchmarkPeer *peer;
190 struct GNUNET_TIME_Absolute start;
193 * DLL for logging entries: head
195 struct PeerLoggingTimestep *head;
198 * DLL for logging entries: tail
200 struct PeerLoggingTimestep *tail;
204 * Log structure of length num_peers
206 static struct LoggingPeer *lp;
210 write_throughput_gnuplot_script (char * fn, struct LoggingPeer *lp)
212 struct GNUNET_DISK_FileHandle *f;
218 GNUNET_asprintf (&gfn, "gnuplot_throughput_%s",fn);
219 f = GNUNET_DISK_file_open (gfn,
220 GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
221 GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE);
224 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
231 if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, THROUGHPUT_TEMPLATE, strlen(THROUGHPUT_TEMPLATE)))
232 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
234 /* Write master data */
235 peer_index = LOG_ITEMS_TIME;
236 GNUNET_asprintf (&data, "plot '%s' using 2:%u with lines title 'Master %u send total', \\\n" \
237 "'%s' using 2:%u with lines title 'Master %u receive total', \\\n",
238 fn, peer_index + LOG_ITEMS_THROUGHPUT_SENT, lp->peer->no,
239 fn, peer_index + LOG_ITEMS_THROUGHPUT_RECV, lp->peer->no);
240 if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
241 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
244 peer_index = LOG_ITEMS_TIME + LOG_ITEMS_PER_PEER ;
245 for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
247 GNUNET_asprintf (&data, "'%s' using 2:%u with lines title 'Master %u - Slave %u send', \\\n" \
248 "'%s' using 2:%u with lines title 'Master %u - Slave %u receive'%s\n",
249 fn, peer_index + LOG_ITEMS_THROUGHPUT_SENT, lp->peer->no, lp->peer->partners[c_s].dest->no,
250 fn, peer_index + LOG_ITEMS_THROUGHPUT_RECV, lp->peer->no, lp->peer->partners[c_s].dest->no,
251 (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1");
252 if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
253 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
255 peer_index += LOG_ITEMS_PER_PEER;
258 if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
259 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn);
261 GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn);
268 write_rtt_gnuplot_script (char * fn, struct LoggingPeer *lp)
270 struct GNUNET_DISK_FileHandle *f;
276 GNUNET_asprintf (&gfn, "gnuplot_rtt_%s",fn);
277 f = GNUNET_DISK_file_open (gfn,
278 GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
279 GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE);
282 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
289 if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, RTT_TEMPLATE, strlen(RTT_TEMPLATE)))
290 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
292 index = LOG_ITEMS_TIME + LOG_ITEMS_PER_PEER;
293 for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
295 GNUNET_asprintf (&data, "%s'%s' using 2:%u with lines title 'Master %u - Slave %u '%s\n",
296 (0 == c_s) ? "plot " :"",
297 fn, index + LOG_ITEMS_APP_RTT, lp->peer->no, lp->peer->partners[c_s].dest->no,
298 (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1");
299 if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
300 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
302 index += LOG_ITEMS_PER_PEER;
305 if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
306 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn);
308 GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn);
315 struct GNUNET_DISK_FileHandle *f;
316 struct GNUNET_TIME_Relative delta;
320 char *slave_string_tmp;
321 struct PeerLoggingTimestep *cur_lt;
322 struct PartnerLoggingTimestep *plt;
325 unsigned int throughput_recv;
326 unsigned int throughput_send;
327 unsigned int throughput_recv_slave;
328 unsigned int throughput_send_slave;
329 int last_throughput_send;
330 int last_throughput_recv;
333 for (c_m = 0; c_m < num_peers; c_m++)
335 GNUNET_asprintf (&filename, "%llu_master_%u_%s_%s.data", GNUNET_TIME_absolute_get().abs_value_us,
336 lp[c_m].peer->no, GNUNET_i2s(&lp[c_m].peer->id), name);
338 f = GNUNET_DISK_file_open (filename,
339 GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
340 GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE);
343 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open log file `%s'\n", filename);
344 GNUNET_free (filename);
348 last_throughput_recv = 0;
349 last_throughput_send = 0;
351 for (cur_lt = lp[c_m].head; NULL != cur_lt; cur_lt = cur_lt->next)
353 if (NULL == cur_lt->prev)
355 delta = GNUNET_TIME_absolute_get_difference (lp[c_m].start, cur_lt->timestamp);
358 delta = GNUNET_TIME_absolute_get_difference (cur_lt->prev->timestamp, cur_lt->timestamp);
360 /* Multiplication factor for throughput calculation */
361 mult = (1.0 * 1000 * 1000) / (delta.rel_value_us);
362 if (NULL != cur_lt->prev)
364 if (cur_lt->total_bytes_sent - cur_lt->prev->total_bytes_sent > 0)
366 throughput_send = cur_lt->total_bytes_sent - cur_lt->prev->total_bytes_sent;
367 throughput_send *= mult;
372 throughput_send = last_throughput_send; /* no msgs received */
375 if (cur_lt->total_bytes_received - cur_lt->prev->total_bytes_received > 0)
377 throughput_recv = cur_lt->total_bytes_received - cur_lt->prev->total_bytes_received;
378 throughput_recv *= mult;
383 throughput_recv = last_throughput_recv; /* no msgs received */
388 throughput_send = cur_lt->total_bytes_sent;
389 throughput_recv = cur_lt->total_bytes_received;
391 throughput_send *= mult;
392 throughput_recv *= mult;
395 last_throughput_send = throughput_send;
396 last_throughput_recv = throughput_recv;
399 GNUNET_log(GNUNET_ERROR_TYPE_INFO,
400 "Master [%u]: timestamp %llu %llu ; %u %u %u ; %u %u %u\n", lp[c_m].peer->no,
401 cur_lt->timestamp, GNUNET_TIME_absolute_get_difference(lp[c_m].start,cur_lt->timestamp).rel_value_us / 1000,
402 cur_lt->total_messages_sent, cur_lt->total_bytes_sent, throughput_send,
403 cur_lt->total_messages_received, cur_lt->total_bytes_received, throughput_recv);
405 slave_string = GNUNET_strdup (";");
406 for (c_s = 0; c_s < lp[c_m].peer->num_partners; c_s++)
409 plt = &cur_lt->slaves_log[c_s];
410 if (NULL != cur_lt->prev)
412 throughput_send_slave = plt->total_bytes_sent - cur_lt->prev->slaves_log[c_s].total_bytes_sent;
413 throughput_recv_slave = plt->total_bytes_received - cur_lt->prev->slaves_log[c_s].total_bytes_received;
417 throughput_send_slave = plt->total_bytes_sent;
418 throughput_recv_slave = plt->total_bytes_received;
420 throughput_send_slave *= mult;
421 throughput_recv_slave *= mult;
422 /* Assembling slave string */
423 GNUNET_log(GNUNET_ERROR_TYPE_INFO,
424 "\t Slave [%u]: %u %u %u ; %u %u %u rtt %u delay %u \n", plt->slave->no,
425 plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave,
426 plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave,
427 plt->app_rtt, plt->ats_delay);
430 GNUNET_asprintf(&slave_string_tmp, "%s%u;%u;%u;%u;%u;%u;%.3f;",slave_string,
431 plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave,
432 plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave,
433 (double) plt->app_rtt / 1000);
434 GNUNET_free (slave_string);
435 slave_string = slave_string_tmp;
437 /* Assembling master string */
438 GNUNET_asprintf (&data, "%llu;%llu;%u;%u;%u;%u;%u;%u;%s\n",
440 GNUNET_TIME_absolute_get_difference(lp[c_m].start,cur_lt->timestamp).rel_value_us / 1000,
441 cur_lt->total_messages_sent, cur_lt->total_bytes_sent, throughput_send,
442 cur_lt->total_messages_received, cur_lt->total_bytes_received, throughput_recv,
444 GNUNET_free (slave_string);
446 if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
447 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to log file `%s'\n", filename);
450 if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
452 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close log file `%s'\n", filename);
453 GNUNET_free (filename);
457 write_throughput_gnuplot_script (filename, lp);
458 write_rtt_gnuplot_script (filename, lp);
460 GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data file successfully written to log file `%s'\n", filename);
461 GNUNET_free (filename);
467 collect_log_now (void)
469 struct LoggingPeer *bp;
470 struct PeerLoggingTimestep *mlt;
471 struct PartnerLoggingTimestep *slt;
472 struct PartnerLoggingTimestep *prev_log_slt;
473 struct BenchmarkPartner *p;
476 unsigned int app_rtt;
478 if (GNUNET_YES != running)
481 for (c_m = 0; c_m < num_peers; c_m++)
484 mlt = GNUNET_malloc (sizeof (struct PeerLoggingTimestep));
485 GNUNET_CONTAINER_DLL_insert_tail(bp->head, bp->tail, mlt);
489 /* Current master state */
490 mlt->timestamp = GNUNET_TIME_absolute_get();
491 mlt->total_bytes_sent = bp->peer->total_bytes_sent;
492 mlt->total_messages_sent = bp->peer->total_messages_sent;
493 mlt->total_bytes_received = bp->peer->total_bytes_received;
494 mlt->total_messages_received = bp->peer->total_messages_received;
496 mlt->slaves_log = GNUNET_malloc (bp->peer->num_partners *
497 sizeof (struct PartnerLoggingTimestep));
499 for (c_s = 0; c_s < bp->peer->num_partners; c_s++)
501 p = &bp->peer->partners[c_s];
502 slt = &mlt->slaves_log[c_s];
504 slt->slave = p->dest;
505 /* Bytes sent from master to this slave */
506 slt->total_bytes_sent = p->bytes_sent;
507 /* Messages sent from master to this slave */
508 slt->total_messages_sent = p->messages_sent;
509 /* Bytes master received from this slave */
510 slt->total_bytes_received = p->bytes_received;
511 /* Messages master received from this slave */
512 slt->total_messages_received = p->messages_received;
513 slt->total_app_rtt = p->total_app_rtt;
514 /* ats performance information */
515 slt->ats_cost_lan = p->ats_cost_lan;
516 slt->ats_cost_wan = p->ats_cost_wan;
517 slt->ats_cost_wlan = p->ats_cost_wlan;
518 slt->ats_delay = p->ats_delay;
519 slt->ats_distance = p->ats_distance;
520 slt->ats_network_type = p->ats_network_type;
521 slt->ats_utilization_down = p->ats_utilization_down;
522 slt->ats_utilization_up = p->ats_utilization_up;
524 /* Total application level rtt */
525 if (NULL == mlt->prev)
527 if (0 != slt->total_messages_sent)
528 app_rtt = slt->total_app_rtt / slt->total_messages_sent;
534 prev_log_slt = &mlt->prev->slaves_log[c_s];
535 if ((slt->total_messages_sent - prev_log_slt->total_messages_sent) > 0)
536 app_rtt = (slt->total_app_rtt - prev_log_slt->total_app_rtt) /
537 (slt->total_messages_sent - prev_log_slt->total_messages_sent);
539 app_rtt = prev_log_slt->app_rtt; /* No messages were */
541 slt->app_rtt = app_rtt;
542 GNUNET_log(GNUNET_ERROR_TYPE_DEBUG,
543 "Master [%u]: slave [%u]\n",
544 bp->peer->no, p->dest->no);
550 collect_log_task (void *cls, const struct GNUNET_SCHEDULER_TaskContext *tc)
552 log_task = GNUNET_SCHEDULER_NO_TASK;
556 if (tc->reason == GNUNET_SCHEDULER_REASON_SHUTDOWN)
559 log_task = GNUNET_SCHEDULER_add_delayed (frequency,
560 &collect_log_task, NULL);
568 struct GNUNET_SCHEDULER_TaskContext tc;
569 struct PeerLoggingTimestep *cur;
571 if (GNUNET_YES!= running)
574 if (GNUNET_SCHEDULER_NO_TASK != log_task)
575 GNUNET_SCHEDULER_cancel (log_task);
576 log_task = GNUNET_SCHEDULER_NO_TASK;
577 tc.reason = GNUNET_SCHEDULER_REASON_SHUTDOWN;
578 collect_log_task (NULL, &tc);
580 GNUNET_log(GNUNET_ERROR_TYPE_INFO,
581 _("Stop logging\n"));
585 for (c_m = 0; c_m < num_peers; c_m++)
587 while (NULL != (cur = lp[c_m].head))
589 GNUNET_CONTAINER_DLL_remove (lp[c_m].head, lp[c_m].tail, cur);
590 GNUNET_free (cur->slaves_log);
599 perf_logging_start (struct GNUNET_TIME_Relative log_frequency,
600 char * testname, struct BenchmarkPeer *masters, int num_masters)
603 GNUNET_log(GNUNET_ERROR_TYPE_INFO,
604 _("Start logging `%s'\n"), testname);
606 num_peers = num_masters;
608 frequency = log_frequency;
610 lp = GNUNET_malloc (num_masters * sizeof (struct LoggingPeer));
612 for (c_m = 0; c_m < num_masters; c_m ++)
614 lp[c_m].peer = &masters[c_m];
615 lp[c_m].start = GNUNET_TIME_absolute_get();
618 /* Schedule logging task */
619 log_task = GNUNET_SCHEDULER_add_now (&collect_log_task, NULL);
620 running = GNUNET_YES;
622 /* end of file perf_ats_logging.c */