src/ats-tests/ats-testing-log.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-tests/ats-testing-log.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 "ats-testing.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 "set grid \n"
  36
  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" \
  42 "set grid \n"
  43
  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" \
  49 "set grid \n"
  50
  51 #define LOG_ITEMS_TIME 2
  52 #define LOG_ITEMS_PER_PEER 17
  53
  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
  71
  72 /**
  73  * A single logging time step for a partner
  74  */
  75 struct PartnerLoggingTimestep
  76 {
  77   /**
  78    * Peer
  79    */
  80   struct BenchmarkPeer *slave;
  81
  82   /**
  83    * Total number of messages this peer has sent
  84    */
  85   unsigned int total_messages_sent;
  86
  87   /**
  88    * Total number of bytes this peer has sent
  89    */
  90   unsigned int total_bytes_sent;
  91
  92   /**
  93    * Total number of messages this peer has received
  94    */
  95   unsigned int total_messages_received;
  96
  97   /**
  98    * Total number of bytes this peer has received
  99    */
 100   unsigned int total_bytes_received;
 101
 102   /**
 103    * Total outbound throughput for master in Bytes / s
 104    */
 105   unsigned int throughput_sent;
 106
 107   /**
 108    * Total inbound throughput for master in Bytes / s
 109    */
 110   unsigned int throughput_recv;
 111
 112   /**
 113    * Accumulated RTT for all messages
 114    */
 115   unsigned int total_app_rtt;
 116
 117   /**
 118    * Current application level delay
 119    */
 120   unsigned int app_rtt;
 121
 122   /* Current ATS properties */
 123
 124   uint32_t ats_distance;
 125
 126   uint32_t ats_delay;
 127
 128   uint32_t bandwidth_in;
 129
 130   uint32_t bandwidth_out;
 131
 132   uint32_t ats_utilization_up;
 133
 134   uint32_t ats_utilization_down;
 135
 136   uint32_t ats_network_type;
 137
 138   uint32_t ats_cost_wan;
 139
 140   uint32_t ats_cost_lan;
 141
 142   uint32_t ats_cost_wlan;
 143
 144   double pref_bandwidth;
 145   double pref_delay;
 146 };
 147
 148
 149 /**
 150  * A single logging time step for a peer
 151  */
 152 struct PeerLoggingTimestep
 153 {
 154   /**
 155    * Next in DLL
 156    */
 157   struct PeerLoggingTimestep *next;
 158
 159   /**
 160    * Prev in DLL
 161    */
 162   struct PeerLoggingTimestep *prev;
 163
 164   /**
 165    * Logging timestamp
 166    */
 167   struct GNUNET_TIME_Absolute timestamp;
 168
 169   /**
 170    * Total number of messages this peer has sent
 171    */
 172   unsigned int total_messages_sent;
 173
 174   /**
 175    * Total number of bytes this peer has sent
 176    */
 177   unsigned int total_bytes_sent;
 178
 179   /**
 180    * Total number of messages this peer has received
 181    */
 182   unsigned int total_messages_received;
 183
 184   /**
 185    * Total number of bytes this peer has received
 186    */
 187   unsigned int total_bytes_received;
 188
 189   /**
 190    * Total outbound throughput for master in Bytes / s
 191    */
 192   unsigned int total_throughput_send;
 193
 194   /**
 195    * Total inbound throughput for master in Bytes / s
 196    */
 197   unsigned int total_throughput_recv;
 198
 199   /**
 200    * Logs for slaves
 201    */
 202   struct PartnerLoggingTimestep *slaves_log;
 203 };
 204
 205 /**
 206  * Entry for a benchmark peer
 207  */
 208 struct LoggingPeer
 209 {
 210   /**
 211    * Peer
 212    */
 213   struct BenchmarkPeer *peer;
 214
 215   /**
 216    * Start time
 217    */
 218   struct GNUNET_TIME_Absolute start;
 219
 220   /**
 221    * DLL for logging entries: head
 222    */
 223   struct PeerLoggingTimestep *head;
 224
 225   /**
 226    * DLL for logging entries: tail
 227    */
 228   struct PeerLoggingTimestep *tail;
 229 };
 230
 231 struct LoggingHandle
 232 {
 233   /**
 234    * Logging task
 235    */
 236   struct GNUNET_SCHEDULER_Task * log_task;
 237
 238   /**
 239    * Reference to perf_ats' masters
 240    */
 241   int num_masters;
 242   int num_slaves;
 243   int running;
 244   int verbose;
 245   char *name;
 246   struct GNUNET_TIME_Relative frequency;
 247
 248   /**
 249    * Log structure of length num_peers
 250    */
 251   struct LoggingPeer *lp;
 252 };
 253
 254
 255
 256 static void
 257 write_throughput_gnuplot_script (char * fn, struct LoggingPeer *lp, char **fs, int slaves)
 258 {
 259   struct GNUNET_DISK_FileHandle *f;
 260   char * gfn;
 261   char *data;
 262   int c_s;
 263
 264   GNUNET_asprintf (&gfn, "gnuplot_throughput_%s",fn);
 265   fprintf (stderr, "Writing throughput plot for master %u and %u slaves to `%s'\n",
 266       lp->peer->no, slaves, gfn);
 267
 268   f = GNUNET_DISK_file_open (gfn,
 269       GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
 270       GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ |
 271       GNUNET_DISK_PERM_USER_WRITE);
 272   if (NULL == f)
 273   {
 274     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
 275     GNUNET_free (gfn);
 276     return;
 277   }
 278
 279   /* Write header */
 280   if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, THROUGHPUT_TEMPLATE,
 281       strlen(THROUGHPUT_TEMPLATE)))
 282     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 283         "Cannot write data to plot file `%s'\n", gfn);
 284
 285   /* Write master data */
 286   GNUNET_asprintf (&data,
 287       "plot '%s' using 2:%u with lines title 'Master %u send total', \\\n" \
 288       "'%s' using 2:%u with lines title 'Master %u receive total', \\\n",
 289       fn, LOG_ITEMS_TIME + LOG_ITEM_THROUGHPUT_SENT, lp->peer->no,
 290       fn, LOG_ITEMS_TIME + LOG_ITEM_THROUGHPUT_RECV, lp->peer->no);
 291   if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
 292     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 293   GNUNET_free (data);
 294
 295   for (c_s = 0; c_s < slaves; c_s++)
 296   {
 297     GNUNET_asprintf (&data, "'%s' using 2:%u with lines title 'Master %u - Slave %u send', \\\n" \
 298         "'%s' using 2:%u with lines title 'Master %u - Slave %u receive'%s\n",
 299         fs[c_s],
 300         LOG_ITEMS_TIME + LOG_ITEM_THROUGHPUT_SENT,
 301         lp->peer->no,
 302         lp->peer->partners[c_s].dest->no,
 303         fs[c_s],
 304         LOG_ITEMS_TIME + LOG_ITEM_THROUGHPUT_RECV,
 305         lp->peer->no,
 306         lp->peer->partners[c_s].dest->no,
 307         (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1");
 308     if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
 309         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 310     GNUNET_free (data);
 311   }
 312
 313   if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
 314     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 315         "Cannot close gnuplot file `%s'\n", gfn);
 316   else
 317     GNUNET_log (GNUNET_ERROR_TYPE_INFO,
 318         "Data successfully written to plot file `%s'\n", gfn);
 319   GNUNET_free (gfn);
 320 }
 321
 322
 323 static void
 324 write_rtt_gnuplot_script (char * fn, struct LoggingPeer *lp, char **fs, int slaves)
 325 {
 326   struct GNUNET_DISK_FileHandle *f;
 327   char * gfn;
 328   char *data;
 329   int c_s;
 330
 331   GNUNET_asprintf (&gfn, "gnuplot_rtt_%s",fn);
 332   fprintf (stderr, "Writing rtt plot for master %u to `%s'\n",
 333       lp->peer->no, gfn);
 334
 335   f = GNUNET_DISK_file_open (gfn,
 336       GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
 337       GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ |
 338       GNUNET_DISK_PERM_USER_WRITE);
 339   if (NULL == f)
 340   {
 341     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
 342     GNUNET_free (gfn);
 343     return;
 344   }
 345
 346   /* Write header */
 347   if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, RTT_TEMPLATE, strlen(RTT_TEMPLATE)))
 348     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 349
 350   for (c_s = 0; c_s < slaves; c_s++)
 351   {
 352     GNUNET_asprintf (&data, "%s'%s' using 2:%u with lines title 'Master %u - Slave %u '%s\n",
 353         (0 == c_s) ? "plot " :"",
 354         fs[c_s],
 355         LOG_ITEMS_TIME + LOG_ITEM_APP_RTT,
 356         lp->peer->no,
 357         lp->peer->partners[c_s].dest->no,
 358         (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1");
 359     if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
 360         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 361     GNUNET_free (data);
 362   }
 363
 364   if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
 365     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn);
 366   else
 367     GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn);
 368   GNUNET_free (gfn);
 369 }
 370
 371 static void
 372 write_bw_gnuplot_script (char * fn, struct LoggingPeer *lp, char **fs, int slaves)
 373 {
 374   struct GNUNET_DISK_FileHandle *f;
 375   char * gfn;
 376   char *data;
 377   int c_s;
 378
 379   GNUNET_asprintf (&gfn, "gnuplot_bw_%s",fn);
 380   fprintf (stderr, "Writing bandwidth plot for master %u to `%s'\n",
 381       lp->peer->no, gfn);
 382
 383   f = GNUNET_DISK_file_open (gfn,
 384       GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
 385       GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ |
 386       GNUNET_DISK_PERM_USER_WRITE);
 387   if (NULL == f)
 388   {
 389     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
 390     GNUNET_free (gfn);
 391     return;
 392   }
 393
 394   /* Write header */
 395   if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, BW_TEMPLATE, strlen(BW_TEMPLATE)))
 396     GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 397         "Cannot write data to plot file `%s'\n", gfn);
 398
 399   for (c_s = 0; c_s < slaves; c_s++)
 400   {
 401     GNUNET_asprintf (&data, "%s"\
 402         "'%s' using 2:%u with lines title 'BW out master %u - Slave %u ', \\\n" \
 403         "'%s' using 2:%u with lines title 'BW in master %u - Slave %u '"\
 404         "%s\n",
 405         (0 == c_s) ? "plot " :"",
 406         fs[c_s],
 407         LOG_ITEMS_TIME + LOG_ITEM_ATS_BW_OUT,
 408         lp->peer->no, c_s,
 409         fs[c_s],
 410         LOG_ITEMS_TIME + LOG_ITEM_ATS_BW_IN,
 411         lp->peer->no, c_s,
 412         (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1");
 413     if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
 414         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 415     GNUNET_free (data);
 416   }
 417
 418   if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
 419     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn);
 420   else
 421     GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn);
 422   GNUNET_free (gfn);
 423 }
 424
 425
 426 void
 427 GNUNET_ATS_TEST_logging_write_to_file (struct LoggingHandle *l,
 428     char *experiment_name, int plots)
 429 {
 430   struct GNUNET_DISK_FileHandle *f[l->num_slaves];
 431   struct GNUNET_DISK_FileHandle *f_m;
 432   char *tmp_exp_name;
 433   char *filename_master;
 434   char *filename_slaves[l->num_slaves];
 435   char *data;
 436   struct PeerLoggingTimestep *cur_lt;
 437   struct PartnerLoggingTimestep *plt;
 438   struct GNUNET_TIME_Absolute timestamp;
 439   int c_m;
 440   int c_s;
 441
 442
 443   timestamp = GNUNET_TIME_absolute_get();
 444
 445   tmp_exp_name = experiment_name;
 446   for (c_m = 0; c_m < l->num_masters; c_m++)
 447   {
 448     GNUNET_asprintf (&filename_master, "%s_%llu_master%u_%s",
 449         experiment_name, timestamp.abs_value_us, c_m, l->name);
 450     fprintf (stderr, "Writing data for master %u to file `%s'\n",
 451         c_m,filename_master);
 452
 453     f_m = GNUNET_DISK_file_open (filename_master,
 454         GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
 455         GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE);
 456     if (NULL == f_m)
 457     {
 458       GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open log file `%s'\n", filename_master);
 459       GNUNET_free (filename_master);
 460       return;
 461     }
 462
 463     GNUNET_asprintf (&data, "# master %u; experiment : %s\n"
 464         "timestamp; timestamp delta; #messages sent; #bytes sent; #throughput sent; #messages received; #bytes received; #throughput received; \n" ,
 465         c_m,  experiment_name);
 466     if (GNUNET_SYSERR == GNUNET_DISK_file_write(f_m, data, strlen(data)))
 467       GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 468           "Cannot write data to log file `%s'\n",filename_master);
 469     GNUNET_free (data);
 470
 471     for (c_s = 0; c_s < l->lp[c_m].peer->num_partners; c_s++)
 472     {
 473       GNUNET_asprintf (&filename_slaves[c_s], "%s_%llu_master%u_slave_%u_%s",
 474           tmp_exp_name, timestamp.abs_value_us, c_m, c_s, l->name);
 475
 476       fprintf (stderr, "Writing data for master %u slave %u to file `%s'\n",
 477           c_m, c_s, filename_slaves[c_s]);
 478
 479       f[c_s] = GNUNET_DISK_file_open (filename_slaves[c_s],
 480           GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
 481           GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE);
 482       if (NULL == f[c_s])
 483       {
 484         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open log file `%s'\n", filename_slaves[c_s]);
 485         GNUNET_free (filename_slaves[c_s]);
 486         GNUNET_break (GNUNET_OK == GNUNET_DISK_file_close(f_m));
 487         GNUNET_free (filename_master);
 488         return;
 489       }
 490
 491       /* Header */
 492       GNUNET_asprintf (&data, "# master %u; slave %u ; experiment : %s\n"
 493           "timestamp; timestamp delta; #messages sent; #bytes sent; #throughput sent; #messages received; #bytes received; #throughput received; " \
 494           "rtt; bw in; bw out; ats_cost_lan; ats_cost_wlan; ats_delay; ats_distance; ats_network_type; ats_utilization_up ;ats_utilization_down;" \
 495           "pref bandwidth; pref delay\n",
 496           c_m, c_s, experiment_name);
 497       if (GNUNET_SYSERR == GNUNET_DISK_file_write(f[c_s], data, strlen(data)))
 498         GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 499             "Cannot write data to log file `%s'\n",filename_slaves[c_s]);
 500       GNUNET_free (data);
 501     }
 502
 503     for (cur_lt = l->lp[c_m].head; NULL != cur_lt; cur_lt = cur_lt->next)
 504     {
 505       if (l->verbose)
 506         fprintf (stderr,
 507            "Master [%u]: timestamp %llu %llu ; %u %u %u ; %u %u %u\n",
 508            l->lp[c_m].peer->no,
 509            (long long unsigned int) cur_lt->timestamp.abs_value_us,
 510            (long long unsigned int) GNUNET_TIME_absolute_get_difference(l->lp[c_m].start,
 511                cur_lt->timestamp).rel_value_us / 1000,
 512            cur_lt->total_messages_sent,
 513            cur_lt->total_bytes_sent,
 514            cur_lt->total_throughput_send,
 515            cur_lt->total_messages_received,
 516            cur_lt->total_bytes_received,
 517            cur_lt->total_throughput_recv);
 518
 519       /* Assembling master string */
 520       GNUNET_asprintf (&data, "%llu;%llu;%u;%u;%u;%u;%u;%u;\n",
 521           (long long unsigned int) cur_lt->timestamp.abs_value_us,
 522           (long long unsigned int) GNUNET_TIME_absolute_get_difference(l->lp[c_m].start,
 523               cur_lt->timestamp).rel_value_us / 1000,
 524           cur_lt->total_messages_sent,
 525           cur_lt->total_bytes_sent,
 526           cur_lt->total_throughput_send,
 527           cur_lt->total_messages_received,
 528           cur_lt->total_bytes_received,
 529           cur_lt->total_throughput_recv);
 530
 531       if (GNUNET_SYSERR == GNUNET_DISK_file_write(f_m, data, strlen(data)))
 532         GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 533             "Cannot write data to master file %u\n", c_m);
 534       GNUNET_free (data);
 535
 536
 537       for (c_s = 0; c_s < l->lp[c_m].peer->num_partners; c_s++)
 538       {
 539         plt = &cur_lt->slaves_log[c_s];
 540         /* Log partners */
 541
 542         /* Assembling slave string */
 543         GNUNET_asprintf(&data,
 544             "%llu;%llu;%u;%u;%u;%u;%u;%u;%.3f;%u;%u;%u;%u;%u;%u;%u;%u;%u;%u;%.3f;%.3f\n",
 545             (long long unsigned int) cur_lt->timestamp.abs_value_us,
 546             (long long unsigned int) GNUNET_TIME_absolute_get_difference(l->lp[c_m].start,
 547                 cur_lt->timestamp).rel_value_us / 1000,
 548             plt->total_messages_sent,
 549             plt->total_bytes_sent,
 550             plt->throughput_sent,
 551             plt->total_messages_received,
 552             plt->total_bytes_received,
 553             plt->throughput_recv,
 554             (double) plt->app_rtt / 1000,
 555             plt->bandwidth_in,
 556             plt->bandwidth_out,
 557             plt->ats_cost_lan,
 558             plt->ats_cost_wan,
 559             plt->ats_cost_wlan,
 560             plt->ats_delay,
 561             plt->ats_distance,
 562             plt->ats_network_type,
 563             plt->ats_utilization_up,
 564             plt->ats_utilization_down,
 565             plt->pref_bandwidth,
 566             plt->pref_delay);
 567
 568         if (l->verbose)
 569           fprintf (stderr,
 570               "\t Slave [%u]: %u %u %u ; %u %u %u rtt %u delay %u bw_in %u bw_out %u \n",
 571               plt->slave->no,
 572               plt->total_messages_sent,
 573               plt->total_bytes_sent,
 574               plt->throughput_sent,
 575               plt->total_messages_received,
 576               plt->total_bytes_received,
 577               plt->throughput_recv,
 578               plt->app_rtt,
 579               plt->ats_delay,
 580               plt->bandwidth_in,
 581               plt->bandwidth_out);
 582
 583         if (GNUNET_SYSERR == GNUNET_DISK_file_write(f[c_s], data, strlen(data)))
 584           GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 585               "Cannot write data to log file `%s'\n", filename_slaves[c_s]);
 586         GNUNET_free (data);
 587
 588       }
 589     }
 590
 591     for (c_s = 0; c_s < l->lp[c_m].peer->num_partners; c_s++)
 592     {
 593       if (GNUNET_SYSERR == GNUNET_DISK_file_close(f[c_s]))
 594       {
 595         GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 596             "Cannot close log file for master[%u] slave[%u]\n", c_m, c_s);
 597         continue;
 598       }
 599       GNUNET_log (GNUNET_ERROR_TYPE_INFO,
 600           "Data file successfully written to log file for `%s'\n",
 601           filename_slaves[c_s]);
 602     }
 603
 604     if (GNUNET_SYSERR == GNUNET_DISK_file_close(f_m))
 605     {
 606       GNUNET_log_strerror_file (GNUNET_ERROR_TYPE_ERROR,
 607                                 "close",
 608                                 filename_master);
 609       GNUNET_free (filename_master);
 610       return;
 611     }
 612     GNUNET_log (GNUNET_ERROR_TYPE_INFO,
 613         "Data file successfully written to log file for master `%s'\n", filename_master);
 614
 615     if (GNUNET_YES == plots)
 616     {
 617       write_throughput_gnuplot_script (filename_master, &l->lp[c_m], filename_slaves, l->num_slaves);
 618       write_rtt_gnuplot_script (filename_master, &l->lp[c_m], filename_slaves, l->num_slaves);
 619       write_bw_gnuplot_script (filename_master, &l->lp[c_m], filename_slaves, l->num_slaves);
 620     }
 621   }
 622   GNUNET_free (filename_master);
 623 }
 624
 625 /**
 626  * Log all data now
 627  *
 628  * @param l logging handle to use
 629  */
 630 void
 631 GNUNET_ATS_TEST_logging_now (struct LoggingHandle *l)
 632 {
 633   struct LoggingPeer *bp;
 634   struct PeerLoggingTimestep *mlt;
 635   struct PeerLoggingTimestep *prev_log_mlt;
 636   struct PartnerLoggingTimestep *slt;
 637   struct PartnerLoggingTimestep *prev_log_slt;
 638   struct BenchmarkPartner *p;
 639   struct GNUNET_TIME_Relative delta;
 640   int c_s;
 641   int c_m;
 642   unsigned int app_rtt;
 643   double mult;
 644
 645   if (GNUNET_YES != l->running)
 646     return;
 647
 648   for (c_m = 0; c_m < l->num_masters; c_m++)
 649   {
 650     bp = &l->lp[c_m];
 651     mlt = GNUNET_new (struct PeerLoggingTimestep);
 652     GNUNET_CONTAINER_DLL_insert_tail(l->lp[c_m].head, l->lp[c_m].tail, mlt);
 653     prev_log_mlt = mlt->prev;
 654
 655     /* Collect data */
 656     /* Current master state */
 657     mlt->timestamp = GNUNET_TIME_absolute_get();
 658     mlt->total_bytes_sent = bp->peer->total_bytes_sent;
 659     mlt->total_messages_sent = bp->peer->total_messages_sent;
 660     mlt->total_bytes_received = bp->peer->total_bytes_received;
 661     mlt->total_messages_received = bp->peer->total_messages_received;
 662
 663     /* Throughput */
 664     if (NULL == prev_log_mlt)
 665      {
 666        /* Get difference to start */
 667        delta = GNUNET_TIME_absolute_get_difference (l->lp[c_m].start, mlt->timestamp);
 668      }
 669      else
 670      {
 671        /* Get difference to last timestep */
 672        delta = GNUNET_TIME_absolute_get_difference (mlt->prev->timestamp, mlt->timestamp);
 673      }
 674
 675      /* Multiplication factor for throughput calculation */
 676      mult = (double) GNUNET_TIME_UNIT_SECONDS.rel_value_us / (delta.rel_value_us);
 677
 678      /* Total throughput */
 679      if (NULL != prev_log_mlt)
 680      {
 681        if (mlt->total_bytes_sent - mlt->prev->total_bytes_sent > 0)
 682        {
 683          mlt->total_throughput_send = mult * (mlt->total_bytes_sent - mlt->prev->total_bytes_sent);
 684        }
 685        else
 686        {
 687          mlt->total_throughput_send = 0;
 688         // mlt->total_throughput_send = prev_log_mlt->total_throughput_send; /* no msgs send */
 689        }
 690
 691        if (mlt->total_bytes_received - mlt->prev->total_bytes_received > 0)
 692        {
 693          mlt->total_throughput_recv = mult * (mlt->total_bytes_received - mlt->prev->total_bytes_received);
 694        }
 695        else
 696        {
 697          mlt->total_throughput_send = 0;
 698          //mlt->total_throughput_recv = prev_log_mlt->total_throughput_recv; /* no msgs received */
 699        }
 700      }
 701      else
 702      {
 703        mlt->total_throughput_send = mult * mlt->total_bytes_sent;
 704        mlt->total_throughput_send = mult * mlt->total_bytes_received;
 705      }
 706
 707     if (GNUNET_YES == l->verbose)
 708     {
 709       GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 710           "Master[%u] delta: %llu us, bytes (sent/received): %u / %u; throughput send/recv: %u / %u\n", c_m,
 711           delta.rel_value_us,
 712           mlt->total_bytes_sent,
 713           mlt->total_bytes_received,
 714           mlt->total_throughput_send,
 715           mlt->total_throughput_recv);
 716     }
 717
 718     mlt->slaves_log = GNUNET_malloc (bp->peer->num_partners *
 719         sizeof (struct PartnerLoggingTimestep));
 720
 721     for (c_s = 0; c_s < bp->peer->num_partners; c_s++)
 722     {
 723       GNUNET_log (GNUNET_ERROR_TYPE_INFO,
 724           "Collect logging data master[%u] slave [%u]\n", c_m, c_s);
 725
 726       p = &bp->peer->partners[c_s];
 727       slt = &mlt->slaves_log[c_s];
 728
 729       slt->slave = p->dest;
 730       /* Bytes sent from master to this slave */
 731       slt->total_bytes_sent = p->bytes_sent;
 732       /* Messages sent from master to this slave */
 733       slt->total_messages_sent = p->messages_sent;
 734       /* Bytes master received from this slave */
 735       slt->total_bytes_received = p->bytes_received;
 736       /* Messages master received from this slave */
 737       slt->total_messages_received = p->messages_received;
 738       slt->total_app_rtt = p->total_app_rtt;
 739       /* ats performance information */
 740       slt->ats_cost_lan = p->ats_cost_lan;
 741       slt->ats_cost_wan = p->ats_cost_wan;
 742       slt->ats_cost_wlan = p->ats_cost_wlan;
 743       slt->ats_delay = p->ats_delay;
 744       slt->ats_distance = p->ats_distance;
 745       slt->ats_network_type = p->ats_network_type;
 746       slt->ats_utilization_down = p->ats_utilization_down;
 747       slt->ats_utilization_up = p->ats_utilization_up;
 748       slt->bandwidth_in = p->bandwidth_in;
 749       slt->bandwidth_out = p->bandwidth_out;
 750       slt->pref_bandwidth = p->pref_bandwidth;
 751       slt->pref_delay = p->pref_delay;
 752
 753       /* Total application level rtt  */
 754       if (NULL == prev_log_mlt)
 755       {
 756         if (0 != slt->total_messages_sent)
 757           app_rtt = slt->total_app_rtt / slt->total_messages_sent;
 758         else
 759           app_rtt = 0;
 760       }
 761       else
 762       {
 763         prev_log_slt =  &prev_log_mlt->slaves_log[c_s];
 764         if ((slt->total_messages_sent - prev_log_slt->total_messages_sent) > 0)
 765           app_rtt = (slt->total_app_rtt - prev_log_slt->total_app_rtt) /
 766                   (slt->total_messages_sent - prev_log_slt->total_messages_sent);
 767         else
 768         {
 769           app_rtt = prev_log_slt->app_rtt; /* No messages were */
 770         }
 771       }
 772       slt->app_rtt = app_rtt;
 773
 774       /* Partner throughput */
 775       if (NULL != prev_log_mlt)
 776       {
 777         prev_log_slt =  &prev_log_mlt->slaves_log[c_s];
 778         if (slt->total_bytes_sent > prev_log_slt->total_bytes_sent)
 779           slt->throughput_sent = mult * (slt->total_bytes_sent - prev_log_slt->total_bytes_sent);
 780         else
 781           slt->throughput_sent = 0;
 782
 783         if (slt->total_bytes_received > prev_log_slt->total_bytes_received)
 784           slt->throughput_recv = mult *
 785               (slt->total_bytes_received - prev_log_slt->total_bytes_received);
 786         else
 787           slt->throughput_recv = 0;
 788       }
 789       else
 790       {
 791         slt->throughput_sent = mult * slt->total_bytes_sent;
 792         slt->throughput_recv = mult * slt->total_bytes_received;
 793       }
 794
 795       if (GNUNET_YES == l->verbose)
 796       {
 797         GNUNET_log (GNUNET_ERROR_TYPE_ERROR,
 798             "Master [%u] -> Slave [%u]: delta: %llu us, bytes (sent/received): %u / %u; throughput send/recv: %u / %u\n",
 799             c_m, c_s,
 800             delta.rel_value_us,
 801             mlt->total_bytes_sent,
 802             mlt->total_bytes_received,
 803             slt->throughput_sent,
 804             slt->throughput_recv);
 805       }
 806       else
 807         GNUNET_log(GNUNET_ERROR_TYPE_DEBUG,
 808           "Master [%u]: slave [%u]\n",
 809           bp->peer->no, p->dest->no);
 810     }
 811   }
 812 }
 813
 814 static void
 815 collect_log_task (void *cls, const struct GNUNET_SCHEDULER_TaskContext *tc)
 816 {
 817   struct LoggingHandle *l = cls;
 818   l->log_task = NULL;
 819
 820   GNUNET_ATS_TEST_logging_now (l);
 821
 822   if (tc->reason == GNUNET_SCHEDULER_REASON_SHUTDOWN)
 823     return;
 824
 825   l->log_task = GNUNET_SCHEDULER_add_delayed (l->frequency,
 826       &collect_log_task, l);
 827 }
 828
 829 /**
 830  * Stop logging
 831  *
 832  * @param l the logging handle
 833  */
 834 void
 835 GNUNET_ATS_TEST_logging_stop (struct LoggingHandle *l)
 836 {
 837   if (GNUNET_YES!= l->running)
 838     return;
 839
 840   if (NULL != l->log_task)
 841     GNUNET_SCHEDULER_cancel (l->log_task);
 842   l->log_task = NULL;
 843   l->running = GNUNET_NO;
 844
 845   GNUNET_log(GNUNET_ERROR_TYPE_INFO,
 846       _("Stop logging\n"));
 847 }
 848
 849 /**
 850  * Clean up logging data
 851  *
 852  * @param l the logging handle
 853  */
 854 void
 855 GNUNET_ATS_TEST_logging_clean_up (struct LoggingHandle *l)
 856 {
 857   int c_m;
 858   struct PeerLoggingTimestep *cur;
 859
 860   if (GNUNET_YES == l->running)
 861     GNUNET_ATS_TEST_logging_stop (l);
 862
 863   for (c_m = 0; c_m < l->num_masters; c_m++)
 864   {
 865     while (NULL != (cur = l->lp[c_m].head))
 866     {
 867       GNUNET_CONTAINER_DLL_remove (l->lp[c_m].head, l->lp[c_m].tail, cur);
 868       GNUNET_free (cur->slaves_log);
 869       GNUNET_free (cur);
 870     }
 871   }
 872
 873   GNUNET_free (l->lp);
 874   GNUNET_free (l);
 875 }
 876
 877
 878 /**
 879  * Start logging
 880  *
 881  * @param log_frequency the logging frequency
 882  * @param testname the testname
 883  * @param masters the master peers used for benchmarking
 884  * @param num_masters the number of master peers
 885  * @param num_slaves the number of slave peers
 886  * @param verbose verbose logging
 887  * @return the logging handle or NULL on error
 888  */
 889 struct LoggingHandle *
 890 GNUNET_ATS_TEST_logging_start(struct GNUNET_TIME_Relative log_frequency,
 891     char *testname, struct BenchmarkPeer *masters, int num_masters, int num_slaves,
 892     int verbose)
 893 {
 894   struct LoggingHandle *l;
 895   int c_m;
 896   GNUNET_log(GNUNET_ERROR_TYPE_INFO,
 897       _("Start logging `%s'\n"), testname);
 898
 899   l = GNUNET_new (struct LoggingHandle);
 900   l->num_masters = num_masters;
 901   l->num_slaves = num_slaves;
 902   l->name = testname;
 903   l->frequency = log_frequency;
 904   l->verbose = verbose;
 905   l->lp = GNUNET_malloc (num_masters * sizeof (struct LoggingPeer));
 906
 907   for (c_m = 0; c_m < num_masters; c_m ++)
 908   {
 909     l->lp[c_m].peer = &masters[c_m];
 910     l->lp[c_m].start = GNUNET_TIME_absolute_get();
 911   }
 912
 913   /* Schedule logging task */
 914   l->log_task = GNUNET_SCHEDULER_add_now (&collect_log_task, l);
 915   l->running = GNUNET_YES;
 916
 917   return l;
 918 }
 919 /* end of file ats-testing-log.c */
 920