logging on demand + log bandwidth
[oweals/gnunet.git] / src / ats-tests / perf_ats_logging.c
1 /*
2  This file is part of GNUnet.
3  (C) 2010-2013 Christian Grothoff (and other contributing authors)
4
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.
9
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.
14
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.
19  */
20 /**
21  * @file ats/perf_ats_logging.c
22  * @brief ats benchmark: logging for performance tests
23  * @author Christian Grothoff
24  * @author Matthias Wachs
25  */
26 #include "platform.h"
27 #include "gnunet_util_lib.h"
28 #include "perf_ats.h"
29
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"
35
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"
41
42 #define LOG_ITEMS_PER_PEER 7
43 #define LOG_ITEMS_TIME 2
44
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
52
53
54 /**
55  * Logging task
56  */
57 static GNUNET_SCHEDULER_TaskIdentifier log_task;
58
59 /**
60  * Reference to perf_ats' masters
61  */
62 static int num_peers;
63 static int running;
64 static char *name;
65 static struct GNUNET_TIME_Relative frequency;
66
67 /**
68  * A single logging time step for a partner
69  */
70 struct PartnerLoggingTimestep
71 {
72   /**
73    * Peer
74    */
75   struct BenchmarkPeer *slave;
76
77   /**
78    * Total number of messages this peer has sent
79    */
80   unsigned int total_messages_sent;
81
82   /**
83    * Total number of bytes this peer has sent
84    */
85   unsigned int total_bytes_sent;
86
87   /**
88    * Total number of messages this peer has received
89    */
90   unsigned int total_messages_received;
91
92   /**
93    * Total number of bytes this peer has received
94    */
95   unsigned int total_bytes_received;
96
97   /**
98    * Accumulated RTT for all messages
99    */
100   unsigned int total_app_rtt;
101
102   /**
103    * Current application level delay
104    */
105   unsigned int app_rtt;
106
107   /* Current ATS properties */
108
109   uint32_t ats_distance;
110
111   uint32_t ats_delay;
112
113   uint32_t bandwidth_in;
114
115   uint32_t bandwidth_out;
116
117   uint32_t ats_utilization_up;
118
119   uint32_t ats_utilization_down;
120
121   uint32_t ats_network_type;
122
123   uint32_t ats_cost_wan;
124
125   uint32_t ats_cost_lan;
126
127   uint32_t ats_cost_wlan;
128 };
129
130
131 /**
132  * A single logging time step for a peer
133  */
134 struct PeerLoggingTimestep
135 {
136   /**
137    * Next in DLL
138    */
139   struct PeerLoggingTimestep *next;
140
141   /**
142    * Prev in DLL
143    */
144   struct PeerLoggingTimestep *prev;
145
146   /**
147    * Logging timestamp
148    */
149   struct GNUNET_TIME_Absolute timestamp;
150
151   /**
152    * Total number of messages this peer has sent
153    */
154   unsigned int total_messages_sent;
155
156   /**
157    * Total number of bytes this peer has sent
158    */
159   unsigned int total_bytes_sent;
160
161   /**
162    * Total number of messages this peer has received
163    */
164   unsigned int total_messages_received;
165
166   /**
167    * Total number of bytes this peer has received
168    */
169   unsigned int total_bytes_received;
170
171   /**
172    * Logs for slaves
173    */
174   struct PartnerLoggingTimestep *slaves_log;
175 };
176
177 /**
178  * Entry for a benchmark peer
179  */
180 struct LoggingPeer
181 {
182   /**
183    * Peer
184    */
185   struct BenchmarkPeer *peer;
186
187   /**
188    * Start time
189    */
190   struct GNUNET_TIME_Absolute start;
191
192   /**
193    * DLL for logging entries: head
194    */
195   struct PeerLoggingTimestep *head;
196
197   /**
198    * DLL for logging entries: tail
199    */
200   struct PeerLoggingTimestep *tail;
201 };
202
203 /**
204  * Log structure of length num_peers
205  */
206 static struct LoggingPeer *lp;
207
208
209 static void
210 write_throughput_gnuplot_script (char * fn, struct LoggingPeer *lp)
211 {
212   struct GNUNET_DISK_FileHandle *f;
213   char * gfn;
214   char *data;
215   int c_s;
216   int peer_index;
217
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);
222   if (NULL == f)
223   {
224     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
225     GNUNET_free (gfn);
226     return;
227   }
228
229   /* Write header */
230
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);
233
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);
242   GNUNET_free (data);
243
244   peer_index = LOG_ITEMS_TIME + LOG_ITEMS_PER_PEER ;
245   for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
246   {
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);
254     GNUNET_free (data);
255     peer_index += LOG_ITEMS_PER_PEER;
256   }
257
258   if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
259     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn);
260   else
261     GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn);
262
263   GNUNET_free (gfn);
264 }
265
266
267 static void
268 write_rtt_gnuplot_script (char * fn, struct LoggingPeer *lp)
269 {
270   struct GNUNET_DISK_FileHandle *f;
271   char * gfn;
272   char *data;
273   int c_s;
274   int index;
275
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);
280   if (NULL == f)
281   {
282     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
283     GNUNET_free (gfn);
284     return;
285   }
286
287   /* Write header */
288
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);
291
292   index = LOG_ITEMS_TIME + LOG_ITEMS_PER_PEER;
293   for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
294   {
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);
301     GNUNET_free (data);
302     index += LOG_ITEMS_PER_PEER;
303   }
304
305   if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
306     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn);
307   else
308     GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn);
309   GNUNET_free (gfn);
310 }
311
312 static void
313 write_to_file ()
314 {
315   struct GNUNET_DISK_FileHandle *f;
316   struct GNUNET_TIME_Relative delta;
317   char * filename;
318   char *data;
319   char *slave_string;
320   char *slave_string_tmp;
321   struct PeerLoggingTimestep *cur_lt;
322   struct PartnerLoggingTimestep *plt;
323   int c_m;
324   int c_s;
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;
331   double mult;
332
333   for (c_m = 0; c_m < num_peers; c_m++)
334   {
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);
337
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);
341     if (NULL == f)
342     {
343       GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open log file `%s'\n", filename);
344       GNUNET_free (filename);
345       return;
346     }
347
348     last_throughput_recv = 0;
349     last_throughput_send = 0;
350
351     for (cur_lt = lp[c_m].head; NULL != cur_lt; cur_lt = cur_lt->next)
352     {
353       if (NULL == cur_lt->prev)
354       {
355         delta = GNUNET_TIME_absolute_get_difference (lp[c_m].start, cur_lt->timestamp);
356       }
357       else
358         delta = GNUNET_TIME_absolute_get_difference (cur_lt->prev->timestamp, cur_lt->timestamp);
359
360       /* Multiplication factor for throughput calculation */
361       mult = (1.0 * 1000 * 1000) / (delta.rel_value_us);
362       if (NULL != cur_lt->prev)
363       {
364         if (cur_lt->total_bytes_sent - cur_lt->prev->total_bytes_sent > 0)
365         {
366           throughput_send = cur_lt->total_bytes_sent - cur_lt->prev->total_bytes_sent;
367           throughput_send *= mult;
368         }
369         else
370         {
371           //GNUNET_break (0);
372           throughput_send = last_throughput_send; /* no msgs received */
373         }
374
375         if (cur_lt->total_bytes_received - cur_lt->prev->total_bytes_received > 0)
376         {
377           throughput_recv = cur_lt->total_bytes_received - cur_lt->prev->total_bytes_received;
378           throughput_recv *= mult;
379         }
380         else
381         {
382          // GNUNET_break (0);
383           throughput_recv = last_throughput_recv; /* no msgs received */
384         }
385       }
386       else
387       {
388         throughput_send = cur_lt->total_bytes_sent;
389         throughput_recv = cur_lt->total_bytes_received;
390
391         throughput_send *= mult;
392         throughput_recv *= mult;
393
394       }
395       last_throughput_send = throughput_send;
396       last_throughput_recv = throughput_recv;
397
398
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);
404
405       slave_string = GNUNET_strdup (";");
406       for (c_s = 0; c_s < lp[c_m].peer->num_partners; c_s++)
407       {
408         /* Log partners */
409         plt = &cur_lt->slaves_log[c_s];
410         if (NULL != cur_lt->prev)
411         {
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;
414         }
415         else
416         {
417           throughput_send_slave = plt->total_bytes_sent;
418           throughput_recv_slave = plt->total_bytes_received;
419         }
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);
428
429
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;
436       }
437       /* Assembling master string */
438       GNUNET_asprintf (&data, "%llu;%llu;%u;%u;%u;%u;%u;%u;%s\n",
439           cur_lt->timestamp,
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,
443           slave_string);
444       GNUNET_free (slave_string);
445
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);
448       GNUNET_free (data);
449     }
450     if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
451     {
452       GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close log file `%s'\n", filename);
453       GNUNET_free (filename);
454       return;
455     }
456
457     write_throughput_gnuplot_script (filename, lp);
458     write_rtt_gnuplot_script (filename, lp);
459
460     GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data file successfully written to log file `%s'\n", filename);
461     GNUNET_free (filename);
462   }
463 }
464
465
466 void
467 collect_log_now (void)
468 {
469   struct LoggingPeer *bp;
470   struct PeerLoggingTimestep *mlt;
471   struct PartnerLoggingTimestep *slt;
472   struct PartnerLoggingTimestep *prev_log_slt;
473   struct BenchmarkPartner *p;
474   int c_s;
475   int c_m;
476   unsigned int app_rtt;
477
478   if (GNUNET_YES != running)
479     return;
480
481   for (c_m = 0; c_m < num_peers; c_m++)
482   {
483     bp = &lp[c_m];
484     mlt = GNUNET_malloc (sizeof (struct PeerLoggingTimestep));
485     GNUNET_CONTAINER_DLL_insert_tail(bp->head, bp->tail, mlt);
486
487     /* Collect data */
488
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;
495
496     mlt->slaves_log = GNUNET_malloc (bp->peer->num_partners *
497         sizeof (struct PartnerLoggingTimestep));
498
499     for (c_s = 0; c_s < bp->peer->num_partners; c_s++)
500     {
501       p = &bp->peer->partners[c_s];
502       slt = &mlt->slaves_log[c_s];
503
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;
523
524       /* Total application level rtt  */
525       if (NULL == mlt->prev)
526       {
527         if (0 != slt->total_messages_sent)
528           app_rtt = slt->total_app_rtt / slt->total_messages_sent;
529         else
530           app_rtt = 0;
531       }
532       else
533       {
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);
538         else
539           app_rtt = prev_log_slt->app_rtt; /* No messages were */
540       }
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);
545     }
546   }
547 }
548
549 static void
550 collect_log_task (void *cls, const struct GNUNET_SCHEDULER_TaskContext *tc)
551 {
552   log_task = GNUNET_SCHEDULER_NO_TASK;
553
554   collect_log_now();
555
556   if (tc->reason == GNUNET_SCHEDULER_REASON_SHUTDOWN)
557     return;
558
559   log_task = GNUNET_SCHEDULER_add_delayed (frequency,
560       &collect_log_task, NULL);
561 }
562
563
564 void
565 perf_logging_stop ()
566 {
567   int c_m;
568   struct GNUNET_SCHEDULER_TaskContext tc;
569   struct PeerLoggingTimestep *cur;
570
571   if (GNUNET_YES!= running)
572     return;
573
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);
579
580   GNUNET_log(GNUNET_ERROR_TYPE_INFO,
581       _("Stop logging\n"));
582
583   write_to_file ();
584
585   for (c_m = 0; c_m < num_peers; c_m++)
586   {
587     while (NULL != (cur = lp[c_m].head))
588     {
589       GNUNET_CONTAINER_DLL_remove (lp[c_m].head, lp[c_m].tail, cur);
590       GNUNET_free (cur->slaves_log);
591       GNUNET_free (cur);
592     }
593   }
594
595   GNUNET_free (lp);
596 }
597
598 void
599 perf_logging_start (struct GNUNET_TIME_Relative log_frequency,
600     char * testname, struct BenchmarkPeer *masters, int num_masters)
601 {
602   int c_m;
603   GNUNET_log(GNUNET_ERROR_TYPE_INFO,
604       _("Start logging `%s'\n"), testname);
605
606   num_peers = num_masters;
607   name = testname;
608   frequency = log_frequency;
609
610   lp = GNUNET_malloc (num_masters * sizeof (struct LoggingPeer));
611
612   for (c_m = 0; c_m < num_masters; c_m ++)
613   {
614     lp[c_m].peer = &masters[c_m];
615     lp[c_m].start = GNUNET_TIME_absolute_get();
616   }
617
618   /* Schedule logging task */
619   log_task = GNUNET_SCHEDULER_add_now (&collect_log_task, NULL);
620   running = GNUNET_YES;
621 }
622 /* end of file perf_ats_logging.c */
623