diff options
author | Matthias Wachs <wachs@net.in.tum.de> | 2013-09-20 13:17:21 +0000 |
---|---|---|
committer | Matthias Wachs <wachs@net.in.tum.de> | 2013-09-20 13:17:21 +0000 |
commit | d4347e0238b041e24ffc71fc8a76bb43fe5b2cef (patch) | |
tree | 276a51a3a280a13c0161b56fbd95fd59d35b8029 /src/ats-tests/perf_ats_logging.c | |
parent | 5a45188a6d8bf111023b9c6cd81915c4b94b2fb3 (diff) | |
download | gnunet-d4347e0238b041e24ffc71fc8a76bb43fe5b2cef.tar.gz gnunet-d4347e0238b041e24ffc71fc8a76bb43fe5b2cef.zip |
logging application layer RTT
Diffstat (limited to 'src/ats-tests/perf_ats_logging.c')
-rw-r--r-- | src/ats-tests/perf_ats_logging.c | 141 |
1 files changed, 127 insertions, 14 deletions
diff --git a/src/ats-tests/perf_ats_logging.c b/src/ats-tests/perf_ats_logging.c index 6c68ce0fc..30d6e397e 100644 --- a/src/ats-tests/perf_ats_logging.c +++ b/src/ats-tests/perf_ats_logging.c | |||
@@ -33,6 +33,14 @@ | |||
33 | "set xlabel \"Time in ms\" \n" \ | 33 | "set xlabel \"Time in ms\" \n" \ |
34 | "set ylabel \"Bytes/s\" \n" | 34 | "set ylabel \"Bytes/s\" \n" |
35 | 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 | |||
36 | /** | 44 | /** |
37 | * Logging task | 45 | * Logging task |
38 | */ | 46 | */ |
@@ -75,6 +83,17 @@ struct PartnerLoggingTimestep | |||
75 | * Total number of bytes this peer has received | 83 | * Total number of bytes this peer has received |
76 | */ | 84 | */ |
77 | unsigned int total_bytes_received; | 85 | unsigned int total_bytes_received; |
86 | |||
87 | /** | ||
88 | * Accumulated RTT for all messages | ||
89 | */ | ||
90 | unsigned int total_app_rtt; | ||
91 | |||
92 | |||
93 | /** | ||
94 | * Current application level delay | ||
95 | */ | ||
96 | unsigned int app_rtt; | ||
78 | }; | 97 | }; |
79 | 98 | ||
80 | 99 | ||
@@ -157,7 +176,7 @@ static struct LoggingPeer *lp; | |||
157 | 176 | ||
158 | 177 | ||
159 | static void | 178 | static void |
160 | write_gnuplot_script (char * fn, struct LoggingPeer *lp) | 179 | write_throughput_gnuplot_script (char * fn, struct LoggingPeer *lp) |
161 | { | 180 | { |
162 | struct GNUNET_DISK_FileHandle *f; | 181 | struct GNUNET_DISK_FileHandle *f; |
163 | char * gfn; | 182 | char * gfn; |
@@ -165,7 +184,7 @@ write_gnuplot_script (char * fn, struct LoggingPeer *lp) | |||
165 | int c_s; | 184 | int c_s; |
166 | int index; | 185 | int index; |
167 | 186 | ||
168 | GNUNET_asprintf (&gfn, "gnuplot_%s",fn); | 187 | GNUNET_asprintf (&gfn, "gnuplot_throughput_%s",fn); |
169 | f = GNUNET_DISK_file_open (gfn, | 188 | f = GNUNET_DISK_file_open (gfn, |
170 | GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE, | 189 | GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE, |
171 | GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE); | 190 | GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE); |
@@ -190,26 +209,75 @@ write_gnuplot_script (char * fn, struct LoggingPeer *lp) | |||
190 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn); | 209 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn); |
191 | GNUNET_free (data); | 210 | GNUNET_free (data); |
192 | 211 | ||
193 | index = 11; | 212 | index = 2 + LOG_ITEMS_PER_PEER + 3 ; |
194 | for (c_s = 0; c_s < lp->peer->num_partners; c_s++) | 213 | for (c_s = 0; c_s < lp->peer->num_partners; c_s++) |
195 | { | 214 | { |
196 | GNUNET_asprintf (&data, "'%s' using 2:%u with lines title 'Master - Slave %u send', \\\n" \ | 215 | GNUNET_asprintf (&data, "'%s' using 2:%u with lines title 'Master - Slave %u send', \\\n" \ |
197 | "'%s' using 2:%u with lines title 'Master - Slave %u receive'%s\n", | 216 | "'%s' using 2:%u with lines title 'Master - Slave %u receive'%s\n", |
198 | fn, index, lp->peer->no, | 217 | fn, index, lp->peer->partners[c_s].dest->no, |
199 | fn, index+3, lp->peer->no, | 218 | fn, index+3, lp->peer->partners[c_s].dest->no, |
200 | (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1"); | 219 | (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1"); |
201 | if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data))) | 220 | 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); | 221 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn); |
203 | GNUNET_free (data); | 222 | GNUNET_free (data); |
204 | index += 6; | 223 | index += LOG_ITEMS_PER_PEER; |
205 | } | 224 | } |
206 | 225 | ||
207 | if (GNUNET_SYSERR == GNUNET_DISK_file_close(f)) | 226 | if (GNUNET_SYSERR == GNUNET_DISK_file_close(f)) |
208 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn); | 227 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn); |
228 | else | ||
229 | GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn); | ||
209 | 230 | ||
210 | GNUNET_free (gfn); | 231 | GNUNET_free (gfn); |
211 | } | 232 | } |
212 | 233 | ||
234 | |||
235 | static void | ||
236 | write_rtt_gnuplot_script (char * fn, struct LoggingPeer *lp) | ||
237 | { | ||
238 | struct GNUNET_DISK_FileHandle *f; | ||
239 | char * gfn; | ||
240 | char *data; | ||
241 | int c_s; | ||
242 | int index; | ||
243 | |||
244 | GNUNET_asprintf (&gfn, "gnuplot_rtt_%s",fn); | ||
245 | f = GNUNET_DISK_file_open (gfn, | ||
246 | GNUNET_DISK_OPEN_WRITE | GNUNET_DISK_OPEN_CREATE, | ||
247 | GNUNET_DISK_PERM_USER_EXEC | GNUNET_DISK_PERM_USER_READ | GNUNET_DISK_PERM_USER_WRITE); | ||
248 | if (NULL == f) | ||
249 | { | ||
250 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot open gnuplot file `%s'\n", gfn); | ||
251 | GNUNET_free (gfn); | ||
252 | return; | ||
253 | } | ||
254 | |||
255 | /* Write header */ | ||
256 | |||
257 | if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, RTT_TEMPLATE, strlen(RTT_TEMPLATE))) | ||
258 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn); | ||
259 | |||
260 | /* 1st column: 2 * timestamp _+ 7 * master + 7 */ | ||
261 | index = 2 + LOG_ITEMS_PER_PEER + LOG_ITEMS_PER_PEER; | ||
262 | for (c_s = 0; c_s < lp->peer->num_partners; c_s++) | ||
263 | { | ||
264 | GNUNET_asprintf (&data, "%s'%s' using 2:%u with lines title 'Master - Slave %u '%s\n", | ||
265 | (0 == c_s) ? "plot " :"", | ||
266 | fn, index, lp->peer->partners[c_s].dest->no, | ||
267 | (c_s < lp->peer->num_partners -1) ? ", \\" : "\n pause -1"); | ||
268 | if (GNUNET_SYSERR == GNUNET_DISK_file_write(f, data, strlen(data))) | ||
269 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot write data to plot file `%s'\n", gfn); | ||
270 | GNUNET_free (data); | ||
271 | index += LOG_ITEMS_PER_PEER; | ||
272 | } | ||
273 | |||
274 | if (GNUNET_SYSERR == GNUNET_DISK_file_close(f)) | ||
275 | GNUNET_log (GNUNET_ERROR_TYPE_ERROR, "Cannot close gnuplot file `%s'\n", gfn); | ||
276 | else | ||
277 | GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data successfully written to plot file `%s'\n", gfn); | ||
278 | GNUNET_free (gfn); | ||
279 | } | ||
280 | |||
213 | static void | 281 | static void |
214 | write_to_file () | 282 | write_to_file () |
215 | { | 283 | { |
@@ -284,21 +352,22 @@ write_to_file () | |||
284 | } | 352 | } |
285 | throughput_send_slave *= mult; | 353 | throughput_send_slave *= mult; |
286 | throughput_recv_slave *= mult; | 354 | throughput_recv_slave *= mult; |
287 | 355 | /* Assembling slave string */ | |
288 | GNUNET_log(GNUNET_ERROR_TYPE_INFO, | 356 | GNUNET_log(GNUNET_ERROR_TYPE_INFO, |
289 | "\t Slave [%u]: %u %u %u ; %u %u %u \n", plt->slave->no, | 357 | "\t Slave [%u]: %u %u %u ; %u %u %u rtt %u \n", plt->slave->no, |
290 | plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave, | 358 | plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave, |
291 | plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave); | 359 | plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave, plt->app_rtt); |
292 | 360 | ||
293 | 361 | ||
294 | GNUNET_asprintf(&slave_string_tmp, "%s%u;%u;%u;%u;%u;%u;",slave_string, | 362 | GNUNET_asprintf(&slave_string_tmp, "%s%u;%u;%u;%u;%u;%u;%.3f;",slave_string, |
295 | plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave, | 363 | plt->total_messages_sent, plt->total_bytes_sent, throughput_send_slave, |
296 | plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave); | 364 | plt->total_messages_received, plt->total_bytes_received, throughput_recv_slave, |
365 | (double) plt->app_rtt / 1000); | ||
297 | GNUNET_free (slave_string); | 366 | GNUNET_free (slave_string); |
298 | slave_string = slave_string_tmp; | 367 | slave_string = slave_string_tmp; |
299 | } | 368 | } |
300 | 369 | /* Assembling master string */ | |
301 | GNUNET_asprintf (&data, "%llu;%llu;%u;%u;%u;%u;%u;%u%s\n", | 370 | GNUNET_asprintf (&data, "%llu;%llu;%u;%u;%u;%u;%u;%u;%s\n", |
302 | cur_lt->timestamp, | 371 | cur_lt->timestamp, |
303 | GNUNET_TIME_absolute_get_difference(lp[c_m].start,cur_lt->timestamp).rel_value_us / 1000, | 372 | 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, | 373 | cur_lt->total_messages_sent, cur_lt->total_bytes_sent, throughput_send, |
@@ -317,7 +386,8 @@ write_to_file () | |||
317 | return; | 386 | return; |
318 | } | 387 | } |
319 | 388 | ||
320 | write_gnuplot_script (filename, lp); | 389 | write_throughput_gnuplot_script (filename, lp); |
390 | write_rtt_gnuplot_script (filename, lp); | ||
321 | 391 | ||
322 | GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data file successfully written to log file `%s'\n", filename); | 392 | GNUNET_log (GNUNET_ERROR_TYPE_INFO, "Data file successfully written to log file `%s'\n", filename); |
323 | GNUNET_free (filename); | 393 | GNUNET_free (filename); |
@@ -330,8 +400,10 @@ collect_log_now (struct LoggingPeer *bp) | |||
330 | { | 400 | { |
331 | struct PeerLoggingTimestep *mlt; | 401 | struct PeerLoggingTimestep *mlt; |
332 | struct PartnerLoggingTimestep *slt; | 402 | struct PartnerLoggingTimestep *slt; |
403 | struct PartnerLoggingTimestep *prev_log_slt; | ||
333 | struct BenchmarkPartner *p; | 404 | struct BenchmarkPartner *p; |
334 | int c_s; | 405 | int c_s; |
406 | unsigned int app_rtt; | ||
335 | 407 | ||
336 | mlt = GNUNET_malloc (sizeof (struct PeerLoggingTimestep)); | 408 | mlt = GNUNET_malloc (sizeof (struct PeerLoggingTimestep)); |
337 | GNUNET_CONTAINER_DLL_insert_tail(bp->head, bp->tail, mlt); | 409 | GNUNET_CONTAINER_DLL_insert_tail(bp->head, bp->tail, mlt); |
@@ -352,6 +424,7 @@ collect_log_now (struct LoggingPeer *bp) | |||
352 | { | 424 | { |
353 | p = &bp->peer->partners[c_s]; | 425 | p = &bp->peer->partners[c_s]; |
354 | slt = &mlt->slaves_log[c_s]; | 426 | slt = &mlt->slaves_log[c_s]; |
427 | |||
355 | slt->slave = p->dest; | 428 | slt->slave = p->dest; |
356 | /* Bytes sent from master to this slave */ | 429 | /* Bytes sent from master to this slave */ |
357 | slt->total_bytes_sent = p->bytes_sent; | 430 | slt->total_bytes_sent = p->bytes_sent; |
@@ -361,8 +434,48 @@ collect_log_now (struct LoggingPeer *bp) | |||
361 | slt->total_bytes_received = p->bytes_received; | 434 | slt->total_bytes_received = p->bytes_received; |
362 | /* Messages master received from this slave */ | 435 | /* Messages master received from this slave */ |
363 | slt->total_messages_received = p->messages_received; | 436 | slt->total_messages_received = p->messages_received; |
437 | slt->total_app_rtt = p->total_app_rtt; | ||
438 | |||
439 | /* Total application level rtt */ | ||
440 | /* | ||
441 | GNUNET_log(GNUNET_ERROR_TYPE_ERROR, | ||
442 | "Master [%u]: slave [%u]: partner total rtt %u / %u = %u\n", | ||
443 | bp->peer->no, p->dest->no, | ||
444 | p->total_app_rtt, p->messages_sent, (p->messages_sent != 0)?p->total_app_rtt / p->messages_sent : 0); | ||
445 | */ | ||
446 | if (NULL == mlt->prev) | ||
447 | { | ||
448 | if (0 != slt->total_messages_sent) | ||
449 | app_rtt = slt->total_app_rtt / slt->total_messages_sent; | ||
450 | else | ||
451 | app_rtt = 0; | ||
452 | } | ||
453 | else | ||
454 | { | ||
455 | prev_log_slt = &mlt->prev->slaves_log[c_s]; | ||
456 | /* | ||
457 | GNUNET_log(GNUNET_ERROR_TYPE_ERROR, | ||
458 | "Master [%u]: slave [%u]: %u - %u = %u ..... delta messages %u - %u = %u \n", | ||
459 | bp->peer->no, p->dest->no, | ||
460 | slt->total_app_rtt, prev_log_slt->total_app_rtt, slt->total_app_rtt - prev_log_slt->total_app_rtt, | ||
461 | slt->total_messages_sent, prev_log_slt->total_messages_sent, slt->total_messages_sent - prev_log_slt->total_messages_sent | ||
462 | ); | ||
463 | */ | ||
464 | |||
465 | app_rtt = (slt->total_app_rtt - prev_log_slt->total_app_rtt) / | ||
466 | (slt->total_messages_sent - prev_log_slt->total_messages_sent); | ||
467 | |||
468 | } | ||
364 | 469 | ||
365 | 470 | ||
471 | /* | ||
472 | GNUNET_log(GNUNET_ERROR_TYPE_ERROR, | ||
473 | "Master [%u]: slave [%u]: %u \ncurrent total rtt %u previous total rtt %u delta total rtt %u\n", | ||
474 | bp->peer->no, p->dest->no, | ||
475 | p->total_app_rtt, | ||
476 | slt->total_app_rtt, prev_log_slt->total_app_rtt, (slt->total_app_rtt - prev_log_slt->total_app_rtt) , | ||
477 | app_rtt);*/ | ||
478 | slt->app_rtt = app_rtt; | ||
366 | 479 | ||
367 | GNUNET_log(GNUNET_ERROR_TYPE_DEBUG, | 480 | GNUNET_log(GNUNET_ERROR_TYPE_DEBUG, |
368 | "Master [%u]: slave [%u]\n", | 481 | "Master [%u]: slave [%u]\n", |