2 This file is part of GNUnet.
3 Copyright (C) 2010-2013 GNUnet e.V.
5 GNUnet is free software: you can redistribute it and/or modify it
6 under the terms of the GNU Affero General Public License as published
7 by the Free Software Foundation, either version 3 of the License,
8 or (at your 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 Affero General Public License for more details.
15 You should have received a copy of the GNU Affero General Public License
16 along with this program. If not, see <http://www.gnu.org/licenses/>.
18 SPDX-License-Identifier: AGPL3.0-or-later
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" \
37 #define RTT_TEMPLATE "#!/usr/bin/gnuplot \n" \
38 "set datafile separator ';' \n" \
39 "set title \"Application level roundtrip time between Master and Slaves\" \n" \
40 "set xlabel \"Time in ms\" \n" \
41 "set ylabel \"ms\" \n" \
44 #define BW_TEMPLATE "#!/usr/bin/gnuplot \n" \
45 "set datafile separator ';' \n" \
46 "set title \"Bandwidth inbound and outbound between Master and Slaves\" \n" \
47 "set xlabel \"Time in ms\" \n" \
48 "set ylabel \"Bytes / s \" \n" \
51 #define LOG_ITEMS_TIME 2
52 #define LOG_ITEMS_PER_PEER 17
54 #define LOG_ITEM_BYTES_SENT 1
55 #define LOG_ITEM_MSGS_SENT 2
56 #define LOG_ITEM_THROUGHPUT_SENT 3
57 #define LOG_ITEM_BYTES_RECV 4
58 #define LOG_ITEM_MSGS_RECV 5
59 #define LOG_ITEM_THROUGHPUT_RECV 6
60 #define LOG_ITEM_APP_RTT 7
61 #define LOG_ITEM_ATS_BW_IN 8
62 #define LOG_ITEM_ATS_BW_OUT 9
63 #define LOG_ITEM_ATS_COSTS_LAN 10
64 #define LOG_ITEM_ATS_WAN 11
65 #define LOG_ITEM_ATS_WLAN 12
66 #define LOG_ITEM_ATS_DELAY 13
67 #define LOG_ITEM_ATS_DISTANCE 14
68 #define LOG_ITEM_ATS_NETWORKTYPE 15
69 #define LOG_ITEM_ATS_UTIL_UP 16
70 #define LOG_ITEM_ATS_UTIL_DOWN 17
75 static struct GNUNET_SCHEDULER_Task *log_task;
78 * Reference to perf_ats' masters
83 static struct GNUNET_TIME_Relative frequency;
86 * A single logging time step for a partner
88 struct PartnerLoggingTimestep
93 struct BenchmarkPeer *slave;
96 * Total number of messages this peer has sent
98 unsigned int total_messages_sent;
101 * Total number of bytes this peer has sent
103 unsigned int total_bytes_sent;
106 * Total number of messages this peer has received
108 unsigned int total_messages_received;
111 * Total number of bytes this peer has received
113 unsigned int total_bytes_received;
116 * Total outbound throughput for master in Bytes / s
118 unsigned int throughput_sent;
121 * Total inbound throughput for master in Bytes / s
123 unsigned int throughput_recv;
126 * Accumulated RTT for all messages
128 unsigned int total_app_rtt;
131 * Current application level delay
133 unsigned int app_rtt;
135 /* Current ATS properties */
137 uint32_t ats_distance;
141 uint32_t bandwidth_in;
143 uint32_t bandwidth_out;
145 uint32_t ats_utilization_up;
147 uint32_t ats_utilization_down;
149 uint32_t ats_network_type;
151 uint32_t ats_cost_wan;
153 uint32_t ats_cost_lan;
155 uint32_t ats_cost_wlan;
160 * A single logging time step for a peer
162 struct PeerLoggingTimestep
167 struct PeerLoggingTimestep *next;
172 struct PeerLoggingTimestep *prev;
177 struct GNUNET_TIME_Absolute timestamp;
180 * Total number of messages this peer has sent
182 unsigned int total_messages_sent;
185 * Total number of bytes this peer has sent
187 unsigned int total_bytes_sent;
190 * Total number of messages this peer has received
192 unsigned int total_messages_received;
195 * Total number of bytes this peer has received
197 unsigned int total_bytes_received;
200 * Total outbound throughput for master in Bytes / s
202 unsigned int total_throughput_send;
205 * Total inbound throughput for master in Bytes / s
207 unsigned int total_throughput_recv;
212 struct PartnerLoggingTimestep *slaves_log;
216 * Entry for a benchmark peer
223 struct BenchmarkPeer *peer;
228 struct GNUNET_TIME_Absolute start;
231 * DLL for logging entries: head
233 struct PeerLoggingTimestep *head;
236 * DLL for logging entries: tail
238 struct PeerLoggingTimestep *tail;
242 * Log structure of length num_peers
244 static struct LoggingPeer *lp;
248 write_throughput_gnuplot_script (char *fn, struct LoggingPeer *lp)
250 struct GNUNET_DISK_FileHandle *f;
256 GNUNET_asprintf (&gfn, "gnuplot_throughput_%s", fn);
257 f = GNUNET_DISK_file_open (gfn,
258 GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
259 GNUNET_DISK_PERM_USER_EXEC
260 | GNUNET_DISK_PERM_USER_READ
261 | GNUNET_DISK_PERM_USER_WRITE);
264 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n",
272 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, THROUGHPUT_TEMPLATE, strlen (
273 THROUGHPUT_TEMPLATE)))
274 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
275 "Cannot write data to plot file `%s'\n", gfn);
277 /* Write master data */
278 peer_index = LOG_ITEMS_TIME;
279 GNUNET_asprintf (&data,
280 "plot '%s' using 2:%u with lines title 'Master %u send total', \\\n" \
281 "'%s' using 2:%u with lines title 'Master %u receive total', \\\n",
282 fn, peer_index + LOG_ITEM_THROUGHPUT_SENT, lp->peer->no,
283 fn, peer_index + LOG_ITEM_THROUGHPUT_RECV, lp->peer->no);
284 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, data, strlen (data)))
285 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
286 "Cannot write data to plot file `%s'\n", gfn);
289 peer_index = LOG_ITEMS_TIME + LOG_ITEMS_PER_PEER;
290 for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
292 GNUNET_asprintf (&data,
293 "'%s' using 2:%u with lines title 'Master %u - Slave %u send', \\\n" \
294 "'%s' using 2:%u with lines title 'Master %u - Slave %u receive'%s\n",
295 fn, peer_index + LOG_ITEM_THROUGHPUT_SENT, lp->peer->no,
296 lp->peer->partners[c_s].dest->no,
297 fn, peer_index + LOG_ITEM_THROUGHPUT_RECV, lp->peer->no,
298 lp->peer->partners[c_s].dest->no,
299 (c_s < lp->peer->num_partners - 1) ? ", \\" :
301 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, data, strlen (data)))
302 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
303 "Cannot write data to plot file `%s'\n", gfn);
305 peer_index += LOG_ITEMS_PER_PEER;
308 if (GNUNET_SYSERR == GNUNET_DISK_file_close (f))
309 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n",
312 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
313 "Data successfully written to plot file `%s'\n", gfn);
320 write_rtt_gnuplot_script (char *fn, struct LoggingPeer *lp)
322 struct GNUNET_DISK_FileHandle *f;
328 GNUNET_asprintf (&gfn, "gnuplot_rtt_%s", fn);
329 f = GNUNET_DISK_file_open (gfn,
330 GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
331 GNUNET_DISK_PERM_USER_EXEC
332 | GNUNET_DISK_PERM_USER_READ
333 | GNUNET_DISK_PERM_USER_WRITE);
336 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n",
344 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, RTT_TEMPLATE, strlen (
346 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
347 "Cannot write data to plot file `%s'\n", gfn);
349 index = LOG_ITEMS_TIME + LOG_ITEMS_PER_PEER;
350 for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
352 GNUNET_asprintf (&data,
353 "%s'%s' using 2:%u with lines title 'Master %u - Slave %u '%s\n",
354 (0 == c_s) ? "plot " : "",
355 fn, index + LOG_ITEM_APP_RTT, lp->peer->no,
356 lp->peer->partners[c_s].dest->no,
357 (c_s < lp->peer->num_partners - 1) ? ", \\" :
359 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, data, strlen (data)))
360 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
361 "Cannot write data to plot file `%s'\n", gfn);
363 index += LOG_ITEMS_PER_PEER;
366 if (GNUNET_SYSERR == GNUNET_DISK_file_close (f))
367 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n",
370 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
371 "Data successfully written to plot file `%s'\n", gfn);
376 write_bw_gnuplot_script (char *fn, struct LoggingPeer *lp)
378 struct GNUNET_DISK_FileHandle *f;
384 GNUNET_asprintf (&gfn, "gnuplot_bw_%s", fn);
385 f = GNUNET_DISK_file_open (gfn,
386 GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
387 GNUNET_DISK_PERM_USER_EXEC
388 | GNUNET_DISK_PERM_USER_READ
389 | GNUNET_DISK_PERM_USER_WRITE);
392 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n",
400 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, BW_TEMPLATE, strlen (
402 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
403 "Cannot write data to plot file `%s'\n", gfn);
405 index = LOG_ITEMS_TIME + LOG_ITEMS_PER_PEER;
406 for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
408 GNUNET_asprintf (&data, "%s" \
409 "'%s' using 2:%u with lines title 'BW out master %u - Slave %u ', \\\n" \
410 "'%s' using 2:%u with lines title 'BW in master %u - Slave %u '" \
412 (0 == c_s) ? "plot " : "",
413 fn, index + LOG_ITEM_ATS_BW_OUT, lp->peer->no,
414 lp->peer->partners[c_s].dest->no,
415 fn, index + LOG_ITEM_ATS_BW_IN, lp->peer->no,
416 lp->peer->partners[c_s].dest->no,
417 (c_s < lp->peer->num_partners - 1) ? ", \\" :
419 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, data, strlen (data)))
420 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
421 "Cannot write data to plot file `%s'\n", gfn);
423 index += LOG_ITEMS_PER_PEER;
426 if (GNUNET_SYSERR == GNUNET_DISK_file_close (f))
427 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n",
430 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
431 "Data successfully written to plot file `%s'\n", gfn);
439 struct GNUNET_DISK_FileHandle *f;
444 char *slave_string_tmp;
445 struct PeerLoggingTimestep *cur_lt;
446 struct PartnerLoggingTimestep *plt;
450 for (c_m = 0; c_m < num_peers; c_m++)
452 GNUNET_asprintf (&filename, "%llu_master_%u_%s_%s.data",
453 GNUNET_TIME_absolute_get ().abs_value_us,
454 lp[c_m].peer->no, GNUNET_i2s (&lp[c_m].peer->id), name);
456 f = GNUNET_DISK_file_open (filename,
457 GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
458 GNUNET_DISK_PERM_USER_READ
459 | GNUNET_DISK_PERM_USER_WRITE);
462 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open log file `%s'\n",
464 GNUNET_free (filename);
468 for (cur_lt = lp[c_m].head; NULL != cur_lt; cur_lt = cur_lt->next)
470 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
471 "Master [%u]: timestamp %llu %llu ; %u %u %u ; %u %u %u\n",
473 cur_lt->timestamp, GNUNET_TIME_absolute_get_difference (
474 lp[c_m].start, cur_lt->timestamp).rel_value_us / 1000,
475 cur_lt->total_messages_sent, cur_lt->total_bytes_sent,
476 cur_lt->total_throughput_send,
477 cur_lt->total_messages_received, cur_lt->total_bytes_received,
478 cur_lt->total_throughput_recv);
480 slave_string = GNUNET_strdup (";");
481 for (c_s = 0; c_s < lp[c_m].peer->num_partners; c_s++)
483 plt = &cur_lt->slaves_log[c_s];
486 /* Assembling slave string */
487 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
488 "\t Slave [%u]: %u %u %u ; %u %u %u rtt %u delay %u bw_in %u bw_out %u \n",
490 plt->total_messages_sent, plt->total_bytes_sent,
491 plt->throughput_sent,
492 plt->total_messages_received, plt->total_bytes_received,
493 plt->throughput_recv,
494 plt->app_rtt, plt->ats_delay,
495 plt->bandwidth_in, plt->bandwidth_out);
497 GNUNET_asprintf (&slave_string_tmp,
498 "%s%u;%u;%u;%u;%u;%u;%.3f;%u;%u;%u;%u;%u;%u;%u;%u;%u;%u;",
500 plt->total_messages_sent, plt->total_bytes_sent,
501 plt->throughput_sent,
502 plt->total_messages_received,
503 plt->total_bytes_received, plt->throughput_sent,
504 (double) plt->app_rtt / 1000,
505 plt->bandwidth_in, plt->bandwidth_out,
506 plt->ats_cost_lan, plt->ats_cost_wan,
508 plt->ats_delay, plt->ats_distance,
509 plt->ats_network_type,
510 plt->ats_utilization_up, plt->ats_utilization_down);
511 GNUNET_free (slave_string);
512 slave_string = slave_string_tmp;
514 /* Assembling master string */
518 GNUNET_asprintf (&data, "%llu;%llu;%u;%u;%u;%u;%u;%u;;;;;;;;;;;%s\n",
520 GNUNET_TIME_absolute_get_difference (lp[c_m].start,
523 cur_lt->total_messages_sent, cur_lt->total_bytes_sent,
524 cur_lt->total_throughput_send,
525 cur_lt->total_messages_received,
526 cur_lt->total_bytes_received,
527 cur_lt->total_throughput_recv,
529 GNUNET_free (slave_string);
531 if (GNUNET_SYSERR == GNUNET_DISK_file_write (f, data, strlen (data)))
532 GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
533 "Cannot write data to log file `%s'\n", filename);
536 if (GNUNET_SYSERR == GNUNET_DISK_file_close (f))
538 GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close log file `%s'\n",
540 GNUNET_free (filename);
544 write_throughput_gnuplot_script (filename, lp);
545 write_rtt_gnuplot_script (filename, lp);
546 write_bw_gnuplot_script (filename, lp);
548 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
549 "Data file successfully written to log file `%s'\n", filename);
550 GNUNET_free (filename);
556 collect_log_now (void)
558 struct LoggingPeer *bp;
559 struct PeerLoggingTimestep *mlt;
560 struct PeerLoggingTimestep *prev_log_mlt;
561 struct PartnerLoggingTimestep *slt;
562 struct PartnerLoggingTimestep *prev_log_slt;
563 struct BenchmarkPartner *p;
564 struct GNUNET_TIME_Relative delta;
567 unsigned int app_rtt;
570 if (GNUNET_YES != running)
573 for (c_m = 0; c_m < num_peers; c_m++)
576 mlt = GNUNET_new (struct PeerLoggingTimestep);
577 GNUNET_CONTAINER_DLL_insert_tail (bp->head, bp->tail, mlt);
578 prev_log_mlt = mlt->prev;
582 /* Current master state */
583 mlt->timestamp = GNUNET_TIME_absolute_get ();
584 mlt->total_bytes_sent = bp->peer->total_bytes_sent;
585 mlt->total_messages_sent = bp->peer->total_messages_sent;
586 mlt->total_bytes_received = bp->peer->total_bytes_received;
587 mlt->total_messages_received = bp->peer->total_messages_received;
590 if (NULL == prev_log_mlt)
592 /* Get difference to start */
593 delta = GNUNET_TIME_absolute_get_difference (lp[c_m].start,
598 /* Get difference to last timestep */
599 delta = GNUNET_TIME_absolute_get_difference (mlt->prev->timestamp,
603 /* Multiplication factor for throughput calculation */
604 mult = (1.0 * 1000 * 1000) / (delta.rel_value_us);
606 /* Total throughput */
607 if (NULL != prev_log_mlt)
609 if (mlt->total_bytes_sent - mlt->prev->total_bytes_sent > 0)
610 mlt->total_throughput_send = mult * (mlt->total_bytes_sent
611 - mlt->prev->total_bytes_sent);
613 mlt->total_throughput_send = prev_log_mlt->total_throughput_send; /* no msgs send */
615 if (mlt->total_bytes_received - mlt->prev->total_bytes_received > 0)
616 mlt->total_throughput_recv = mult * (mlt->total_bytes_received
617 - mlt->prev->total_bytes_received);
619 mlt->total_throughput_recv = prev_log_mlt->total_throughput_recv; /* no msgs received */
623 mlt->total_throughput_send = mult * mlt->total_bytes_sent;
624 mlt->total_throughput_send = mult * mlt->total_bytes_received;
627 mlt->slaves_log = GNUNET_malloc (bp->peer->num_partners
628 * sizeof(struct PartnerLoggingTimestep));
630 for (c_s = 0; c_s < bp->peer->num_partners; c_s++)
632 p = &bp->peer->partners[c_s];
633 slt = &mlt->slaves_log[c_s];
635 slt->slave = p->dest;
636 /* Bytes sent from master to this slave */
637 slt->total_bytes_sent = p->bytes_sent;
638 /* Messages sent from master to this slave */
639 slt->total_messages_sent = p->messages_sent;
640 /* Bytes master received from this slave */
641 slt->total_bytes_received = p->bytes_received;
642 /* Messages master received from this slave */
643 slt->total_messages_received = p->messages_received;
644 slt->total_app_rtt = p->total_app_rtt;
645 /* ats performance information */
646 slt->ats_cost_lan = p->ats_cost_lan;
647 slt->ats_cost_wan = p->ats_cost_wan;
648 slt->ats_cost_wlan = p->ats_cost_wlan;
649 slt->ats_delay = p->ats_delay;
650 slt->ats_distance = p->ats_distance;
651 slt->ats_network_type = p->ats_network_type;
652 slt->ats_utilization_down = p->ats_utilization_down;
653 slt->ats_utilization_up = p->ats_utilization_up;
654 slt->bandwidth_in = p->bandwidth_in;
655 slt->bandwidth_out = p->bandwidth_out;
657 /* Total application level rtt */
658 if (NULL == prev_log_mlt)
660 if (0 != slt->total_messages_sent)
661 app_rtt = slt->total_app_rtt / slt->total_messages_sent;
667 prev_log_slt = &prev_log_mlt->slaves_log[c_s];
668 if ((slt->total_messages_sent - prev_log_slt->total_messages_sent) > 0)
669 app_rtt = (slt->total_app_rtt - prev_log_slt->total_app_rtt)
670 / (slt->total_messages_sent
671 - prev_log_slt->total_messages_sent);
673 app_rtt = prev_log_slt->app_rtt; /* No messages were */
675 slt->app_rtt = app_rtt;
677 /* Partner throughput */
678 if (NULL != prev_log_mlt)
680 prev_log_slt = &prev_log_mlt->slaves_log[c_s];
681 if (slt->total_bytes_sent - prev_log_slt->total_bytes_sent > 0)
682 slt->throughput_sent = mult * (slt->total_bytes_sent
683 - prev_log_slt->total_bytes_sent);
685 slt->throughput_sent = prev_log_slt->throughput_sent; /* no msgs send */
687 if (slt->total_bytes_received - prev_log_slt->total_bytes_received > 0)
688 slt->throughput_recv = mult * (slt->total_bytes_received
689 - prev_log_slt->total_bytes_received);
691 slt->throughput_recv = prev_log_slt->throughput_recv; /* no msgs received */
695 slt->throughput_sent = mult * slt->total_bytes_sent;
696 slt->throughput_sent = mult * slt->total_bytes_received;
699 GNUNET_log (GNUNET_ERROR_TYPE_DEBUG,
700 "Master [%u]: slave [%u]\n",
701 bp->peer->no, p->dest->no);
707 collect_log_task (void *cls)
711 log_task = GNUNET_SCHEDULER_add_delayed (frequency,
712 &collect_log_task, NULL);
720 struct PeerLoggingTimestep *cur;
722 if (GNUNET_YES != running)
725 if (NULL != log_task)
727 GNUNET_SCHEDULER_cancel (log_task);
730 collect_log_task (NULL);
732 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
733 _ ("Stop logging\n"));
737 for (c_m = 0; c_m < num_peers; c_m++)
739 while (NULL != (cur = lp[c_m].head))
741 GNUNET_CONTAINER_DLL_remove (lp[c_m].head, lp[c_m].tail, cur);
742 GNUNET_free (cur->slaves_log);
752 perf_logging_start (struct GNUNET_TIME_Relative log_frequency,
753 char *testname, struct BenchmarkPeer *masters, int
758 GNUNET_log (GNUNET_ERROR_TYPE_INFO,
759 _ ("Start logging `%s'\n"), testname);
761 num_peers = num_masters;
763 frequency = log_frequency;
765 lp = GNUNET_malloc (num_masters * sizeof(struct LoggingPeer));
767 for (c_m = 0; c_m < num_masters; c_m++)
769 lp[c_m].peer = &masters[c_m];
770 lp[c_m].start = GNUNET_TIME_absolute_get ();
773 /* Schedule logging task */
774 log_task = GNUNET_SCHEDULER_add_now (&collect_log_task, NULL);
775 running = GNUNET_YES;
777 /* end of file perf_ats_logging.c */