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\" \n" \
  33 "set xlabel \"Time in ms\" \n" \
  34 "set ylabel \"Bytes/s\" \n"
  35
  36 /**
  37  * Logging task
  38  */
  39 static GNUNET_SCHEDULER_TaskIdentifier log_task;
  40
  41 /**
  42  * Reference to perf_ats' masters
  43  */
  44 static int num_peers;
  45 static int running;
  46 static char *name;
  47 static struct GNUNET_TIME_Relative frequency;
  48
  49 /**
  50  * A single logging time step for a partner
  51  */
  52 struct PartnerLoggingTimestep
  53 {
  54   /**
  55    * Peer
  56    */
  57   struct BenchmarkPeer *slave;
  58
  59   /**
  60    * Total number of messages this peer has sent
  61    */
  62   unsigned int total_messages_sent;
  63
  64   /**
  65    * Total number of bytes this peer has sent
  66    */
  67   unsigned int total_bytes_sent;
  68
  69   /**
  70    * Total number of messages this peer has received
  71    */
  72   unsigned int total_messages_received;
  73
  74   /**
  75    * Total number of bytes this peer has received
  76    */
  77   unsigned int total_bytes_received;
  78 };
  79
  80
  81 /**
  82  * A single logging time step for a peer
  83  */
  84 struct PeerLoggingTimestep
  85 {
  86   /**
  87    * Next in DLL
  88    */
  89   struct PeerLoggingTimestep *next;
  90
  91   /**
  92    * Prev in DLL
  93    */
  94   struct PeerLoggingTimestep *prev;
  95
  96   /**
  97    * Logging timestamp
  98    */
  99   struct GNUNET_TIME_Absolute timestamp;
 100
 101   /**
 102    * Total number of messages this peer has sent
 103    */
 104   unsigned int total_messages_sent;
 105
 106   /**
 107    * Total number of bytes this peer has sent
 108    */
 109   unsigned int total_bytes_sent;
 110
 111   /**
 112    * Total number of messages this peer has received
 113    */
 114   unsigned int total_messages_received;
 115
 116   /**
 117    * Total number of bytes this peer has received
 118    */
 119   unsigned int total_bytes_received;
 120
 121   /**
 122    * Logs for slaves
 123    */
 124   struct PartnerLoggingTimestep *slaves_log;
 125 };
 126
 127 /**
 128  * Entry for a benchmark peer
 129  */
 130 struct LoggingPeer
 131 {
 132   /**
 133    * Peer
 134    */
 135   struct BenchmarkPeer *peer;
 136
 137   /**
 138    * Start time
 139    */
 140   struct GNUNET_TIME_Absolute start;
 141
 142   /**
 143    * DLL for logging entries: head
 144    */
 145   struct PeerLoggingTimestep *head;
 146
 147   /**
 148    * DLL for logging entries: tail
 149    */
 150   struct PeerLoggingTimestep *tail;
 151 };
 152
 153 /**
 154  * Log structure of length num_peers
 155  */
 156 static struct LoggingPeer *lp;
 157
 158
 159 static void
 160 write_gnuplot_script (char * fn, struct LoggingPeer *lp)
 161 {
 162   struct GNUNET_DISK_FileHandle *f;
 163   char * gfn;
 164   char *data;
 165   int c_s;
 166   int index;
 167
 168   GNUNET_asprintf (&gfn, "gnuplot_%s",fn);
 169   f = GNUNET_DISK_file_open (gfn,
 170       GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
 171       GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE);
 172   if (NULL == f)
 173   {
 174     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn);
 175     GNUNET_free (gfn);
 176     return;
 177   }
 178
 179   /* Write header */
 180
 181   if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, THROUGHPUT_TEMPLATE, strlen(THROUGHPUT_TEMPLATE)))
 182     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 183
 184   /* Write master data */
 185   GNUNET_asprintf (&data, "plot '%s' using 2:%u with lines title 'Master %u send', \\\n" \
 186                            "'%s' using 2:%u with lines title 'Master %u receive', \\\n",
 187                            fn, 5, lp->peer->no,
 188                            fn, 8, lp->peer->no);
 189   if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
 190     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 191   GNUNET_free (data);
 192
 193   index = 11;
 194   for (c_s = 0; c_s < lp->peer->num_partners; c_s++)
 195   {
 196     GNUNET_asprintf (&data, "'%s' using 2:%u with lines title 'Slave %u send', \\\n" \
 197                             "'%s' using 2:%u with lines title 'Slave %u receive'%s\n",
 198                             fn, index, lp->peer->no,
 199                             fn, index+3, lp->peer->no,
 200                             (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1");
 201     if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
 202         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn);
 203     GNUNET_free (data);
 204     index += 6;
 205   }
 206
 207   if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
 208     GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn);
 209
 210   GNUNET_free (gfn);
 211 }
 212
 213 static void
 214 write_to_file ()
 215 {
 216   struct GNUNET_DISK_FileHandle *f;
 217   char * filename;
 218   char *data;
 219   char *slave_string;
 220   char *slave_string_tmp;
 221   struct PeerLoggingTimestep *cur_lt;
 222   struct PartnerLoggingTimestep *plt;
 223   int c_m;
 224   int c_s;
 225   unsigned int throughput_recv;
 226   unsigned int throughput_send;
 227   unsigned int throughput_recv_slave;
 228   unsigned int throughput_send_slave;
 229   double mult;
 230
 231   for (c_m = 0; c_m < num_peers; c_m++)
 232   {
 233     GNUNET_asprintf (&filename, "%llu_master_%u_%s_%s.data", GNUNET_TIME_absolute_get().abs_value_us,
 234         lp[c_m].peer->no, GNUNET_i2s(&lp[c_m].peer->id), name);
 235
 236     f = GNUNET_DISK_file_open (filename,
 237         GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE,
 238         GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE);
 239     if (NULL == f)
 240     {
 241       GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open log file `%s'\n", filename);
 242       GNUNET_free (filename);
 243       return;
 244     }
 245
 246
 247     for (cur_lt = lp[c_m].head; NULL != cur_lt; cur_lt = cur_lt->next)
 248     {
 249       mult = (1.0 * 1000 * 1000) /  (LOGGING_FREQUENCY.rel_value_us);
 250       if (NULL != cur_lt->prev)
 251       {
 252         throughput_send = cur_lt->total_bytes_sent - cur_lt->prev->total_bytes_sent;
 253         throughput_recv = cur_lt->total_bytes_received - cur_lt->prev->total_bytes_received;
 254       }
 255       else
 256       {
 257         throughput_send = cur_lt->total_bytes_sent;
 258         throughput_recv = cur_lt->total_bytes_received;
 259       }
 260       throughput_send *= mult;
 261       throughput_recv *= mult;
 262
 263
 264       GNUNET_log(GNUNET_ERROR_TYPE_INFO,
 265           "Master [%u]: timestamp %llu %llu ; %u %u %u ; %u %u %u\n", lp[c_m].peer->no,
 266           cur_lt->timestamp, GNUNET_TIME_absolute_get_difference(lp[c_m].start,cur_lt->timestamp).rel_value_us / 1000,
 267           cur_lt->total_messages_sent, cur_lt->total_bytes_sent, throughput_send,
 268           cur_lt->total_messages_received, cur_lt->total_bytes_received, throughput_recv);
 269
 270       slave_string = GNUNET_strdup (";");
 271       for (c_s = 0; c_s < lp[c_m].peer->num_partners; c_s++)
 272       {
 273         /* Log partners */
 274         plt = &cur_lt->slaves_log[c_s];
 275         if (NULL != cur_lt->prev)
 276         {
 277           throughput_send_slave = plt->total_bytes_sent - cur_lt->prev->slaves_log[c_s].total_bytes_sent;
 278           throughput_recv_slave = plt->total_bytes_received - cur_lt->prev->slaves_log[c_s].total_bytes_received;
 279         }
 280         else
 281         {
 282           throughput_send_slave = plt->total_bytes_sent;
 283           throughput_recv_slave = plt->total_bytes_received;
 284         }
 285         throughput_send_slave *= mult;
 286         throughput_recv_slave *= mult;
 287
 288         GNUNET_log(GNUNET_ERROR_TYPE_INFO,
 289             "\t Slave [%u]: %u %u %u ; %u %u %u \n", plt->slave->no,
 290             plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave,
 291             plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave);
 292
 293
 294         GNUNET_asprintf(&slave_string_tmp, "%s%u;%u;%u;%u;%u;%u;",slave_string,
 295             plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave,
 296             plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave);
 297         GNUNET_free (slave_string);
 298         slave_string = slave_string_tmp;
 299       }
 300
 301       GNUNET_asprintf (&data, "%llu;%llu;%u;%u;%u;%u;%u;%u%s\n",
 302           cur_lt->timestamp,
 303           GNUNET_TIME_absolute_get_difference(lp[c_m].start,cur_lt->timestamp).rel_value_us / 1000,
 304           cur_lt->total_messages_sent, cur_lt->total_bytes_sent, throughput_send,
 305           cur_lt->total_messages_received, cur_lt->total_bytes_received, throughput_recv,
 306           slave_string);
 307       GNUNET_free (slave_string);
 308
 309       if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data)))
 310         GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to log file `%s'\n", filename);
 311       GNUNET_free (data);
 312     }
 313     if (GNUNET_SYSERR == GNUNET_DISK_file_close(f))
 314     {
 315       GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close log file `%s'\n", filename);
 316       GNUNET_free (filename);
 317       return;
 318     }
 319
 320     write_gnuplot_script (filename, lp);
 321
 322     GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data file successfully written to log file `%s'\n", filename);
 323     GNUNET_free (filename);
 324   }
 325 }
 326
 327 static void
 328 collect_log_task (void *cls, const struct GNUNET_SCHEDULER_TaskContext *tc)
 329 {
 330   int c_m;
 331   int c_s;
 332   struct PeerLoggingTimestep *mlt;
 333   struct PartnerLoggingTimestep *slt;
 334   struct BenchmarkPartner *p;
 335
 336   log_task = GNUNET_SCHEDULER_NO_TASK;
 337
 338   for (c_m = 0; c_m < num_peers; c_m++)
 339   {
 340     mlt = GNUNET_malloc (sizeof (struct PeerLoggingTimestep));
 341     GNUNET_CONTAINER_DLL_insert_tail(lp[c_m].head, lp[c_m].tail, mlt);
 342
 343     /* Collect data */
 344     mlt->timestamp = GNUNET_TIME_absolute_get();
 345     mlt->total_bytes_sent = lp[c_m].peer->total_bytes_sent;
 346     mlt->total_messages_sent = lp[c_m].peer->total_messages_sent;
 347     mlt->total_bytes_received = lp[c_m].peer->total_bytes_received;
 348     mlt->total_messages_received = lp[c_m].peer->total_messages_received;
 349
 350     mlt->slaves_log = GNUNET_malloc (lp[c_m].peer->num_partners *
 351         sizeof (struct PartnerLoggingTimestep));
 352
 353     for (c_s = 0; c_s < lp[c_m].peer->num_partners; c_s++)
 354     {
 355       p = &lp[c_m].peer->partners[c_s];
 356       slt = &mlt->slaves_log[c_s];
 357       slt->slave = p->dest;
 358       slt->total_bytes_sent = p->dest->total_bytes_sent;
 359       slt->total_messages_sent = p->dest->total_messages_sent;
 360       slt->total_bytes_received = p->dest->total_bytes_received;
 361       slt->total_messages_received = p->dest->total_messages_received;
 362
 363       GNUNET_log(GNUNET_ERROR_TYPE_DEBUG,
 364           "Master [%u]: slave [%u]\n",
 365           lp[c_m].peer->no, p->dest->no);
 366     }
 367   }
 368
 369   if (tc->reason == GNUNET_SCHEDULER_REASON_SHUTDOWN)
 370     return;
 371
 372   log_task = GNUNET_SCHEDULER_add_delayed (frequency,
 373       &collect_log_task, NULL);
 374 }
 375
 376
 377 void
 378 perf_logging_stop ()
 379 {
 380   int c_m;
 381   struct GNUNET_SCHEDULER_TaskContext tc;
 382   struct PeerLoggingTimestep *cur;
 383
 384   if (GNUNET_YES!= running)
 385     return;
 386
 387   if (GNUNET_SCHEDULER_NO_TASK != log_task)
 388     GNUNET_SCHEDULER_cancel (log_task);
 389   log_task = GNUNET_SCHEDULER_NO_TASK;
 390   tc.reason = GNUNET_SCHEDULER_REASON_SHUTDOWN;
 391   collect_log_task (NULL, &tc);
 392
 393   GNUNET_log(GNUNET_ERROR_TYPE_INFO,
 394       _("Stop logging\n"));
 395
 396   write_to_file ();
 397
 398   for (c_m = 0; c_m < num_peers; c_m++)
 399   {
 400     while (NULL != (cur = lp[c_m].head))
 401     {
 402       GNUNET_CONTAINER_DLL_remove (lp[c_m].head, lp[c_m].tail, cur);
 403       GNUNET_free (cur->slaves_log);
 404       GNUNET_free (cur);
 405     }
 406   }
 407
 408   GNUNET_free (lp);
 409 }
 410
 411 void
 412 perf_logging_start (struct GNUNET_TIME_Relative log_frequency,
 413     char * testname, struct BenchmarkPeer *masters, int num_masters)
 414 {
 415   int c_m;
 416   GNUNET_log(GNUNET_ERROR_TYPE_INFO,
 417       _("Start logging `%s'\n"), testname);
 418
 419   num_peers = num_masters;
 420   name = testname;
 421   frequency = log_frequency;
 422
 423   lp = GNUNET_malloc (num_masters * sizeof (struct LoggingPeer));
 424
 425   for (c_m = 0; c_m < num_masters; c_m ++)
 426   {
 427     lp[c_m].peer = &masters[c_m];
 428     lp[c_m].start = GNUNET_TIME_absolute_get();
 429   }
 430
 431   /* Schedule logging task */
 432   log_task = GNUNET_SCHEDULER_add_now (&collect_log_task, NULL);
 433   running = GNUNET_YES;
 434 }
 435 /* end of file perf_ats_logging.c */
 436