lttv/lttv/sync/event_processing_lttv_standard.c

   1 /* This file is part of the Linux Trace Toolkit viewer
   2  * Copyright (C) 2009 Benjamin Poirier <benjamin.poirier@polymtl.ca>
   3  *
   4  * This program is free software; you can redistribute it and/or modify
   5  * it under the terms of the GNU General Public License Version 2 as
   6  * published by the Free Software Foundation;
   7  *
   8  * This program is distributed in the hope that it will be useful,
   9  * but WITHOUT ANY WARRANTY; without even the implied warranty of
  10  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  11  * GNU General Public License for more details.
  12  *
  13  * You should have received a copy of the GNU General Public License
  14  * along with this program; if not, write to the Free Software
  15  * Foundation, Inc., 59 Temple Place - Suite 330, Boston,
  16  * MA 02111-1307, USA.
  17  */
  18
  19 #define _ISOC99_SOURCE
  20
  21 #ifdef HAVE_CONFIG_H
  22 #include <config.h>
  23 #endif
  24
  25 #include <linux/if_ether.h>
  26 #include <math.h>
  27 #include <netinet/in.h>
  28 #include <stdint.h>
  29 #include <stdlib.h>
  30
  31 #include "sync_chain.h"
  32 #include "event_processing_lttv_common.h"
  33
  34 #include "event_processing_lttv_standard.h"
  35
  36
  37 #ifndef g_info
  38 #define g_info(format...) g_log (G_LOG_DOMAIN, G_LOG_LEVEL_INFO, format)
  39 #endif
  40
  41
  42 // Functions common to all matching modules
  43 static void initProcessingLTTVStandard(SyncState* const syncState,
  44         LttvTracesetContext* const traceSetContext);
  45 static void destroyProcessingLTTVStandard(SyncState* const syncState);
  46
  47 static void finalizeProcessingLTTVStandard(SyncState* const syncState);
  48 static void printProcessingStatsLTTVStandard(SyncState* const syncState);
  49
  50 // Functions specific to this module
  51 static void registerProcessingLTTVStandard() __attribute__((constructor (102)));
  52 static gboolean processEventLTTVStandard(void* hookData, void* callData);
  53 static void partialDestroyProcessingLTTVStandard(SyncState* const syncState);
  54
  55
  56 static ProcessingModule processingModuleLTTVStandard = {
  57         .name= "LTTV-standard",
  58         .initProcessing= &initProcessingLTTVStandard,
  59         .destroyProcessing= &destroyProcessingLTTVStandard,
  60         .finalizeProcessing= &finalizeProcessingLTTVStandard,
  61         .printProcessingStats= &printProcessingStatsLTTVStandard,
  62 };
  63
  64
  65
  66 /*
  67  * Processing Module registering function
  68  */
  69 static void registerProcessingLTTVStandard()
  70 {
  71         g_queue_push_tail(&processingModules, &processingModuleLTTVStandard);
  72
  73         createQuarks();
  74 }
  75
  76
  77 /*
  78  * Allocate and initialize data structures for synchronizing a traceset.
  79  * Register event hooks.
  80  *
  81  * Args:
  82  *   syncState:    container for synchronization data.
  83  *                 This function allocates these processingData members:
  84  *                 traceNumTable
  85  *                 pendingRecv
  86  *                 hookListList
  87  *                 stats
  88  *   traceSetContext: set of LTTV traces
  89  */
  90 static void initProcessingLTTVStandard(SyncState* const syncState, LttvTracesetContext*
  91         const traceSetContext)
  92 {
  93         unsigned int i;
  94         ProcessingDataLTTVStandard* processingData;
  95
  96         processingData= malloc(sizeof(ProcessingDataLTTVStandard));
  97         syncState->processingData= processingData;
  98         processingData->traceSetContext= traceSetContext;
  99
 100         if (syncState->stats)
 101         {
 102                 processingData->stats= calloc(1, sizeof(ProcessingStatsLTTVStandard));
 103         }
 104         else
 105         {
 106                 processingData->stats= NULL;
 107         }
 108
 109         processingData->traceNumTable= g_hash_table_new(&g_direct_hash, NULL);
 110         processingData->hookListList= g_array_sized_new(FALSE, FALSE,
 111                 sizeof(GArray*), syncState->traceNb);
 112         processingData->pendingRecv= malloc(sizeof(GHashTable*) *
 113                 syncState->traceNb);
 114
 115         for(i= 0; i < syncState->traceNb; i++)
 116         {
 117                 g_hash_table_insert(processingData->traceNumTable,
 118                         processingData->traceSetContext->traces[i]->t, (gpointer) i);
 119         }
 120
 121         for(i= 0; i < syncState->traceNb; i++)
 122         {
 123                 processingData->pendingRecv[i]= g_hash_table_new_full(&g_direct_hash,
 124                         NULL, NULL, &gdnDestroyNetEvent);
 125         }
 126
 127         registerHooks(processingData->hookListList, traceSetContext,
 128                 syncState->traceNb, &processEventLTTVStandard, syncState);
 129 }
 130
 131
 132 /*
 133  * Call the partial processing destroyer, obtain and adjust the factors from
 134  * downstream
 135  *
 136  * Args:
 137  *   syncState     container for synchronization data.
 138  */
 139 static void finalizeProcessingLTTVStandard(SyncState* const syncState)
 140 {
 141         unsigned int i;
 142         GArray* factors;
 143         double minOffset, minDrift;
 144         unsigned int refFreqTrace;
 145         ProcessingDataLTTVStandard* processingData;
 146
 147         processingData= (ProcessingDataLTTVStandard*) syncState->processingData;
 148
 149         partialDestroyProcessingLTTVStandard(syncState);
 150
 151         factors= syncState->matchingModule->finalizeMatching(syncState);
 152
 153         /* The offsets are adjusted so the lowest one is 0. This is done because
 154          * of a Lttv specific limitation: events cannot have negative times. By
 155          * having non-negative offsets, events cannot be moved backwards to
 156          * negative times.
 157          */
 158         minOffset= 0;
 159         for (i= 0; i < syncState->traceNb; i++)
 160         {
 161                 minOffset= MIN(g_array_index(factors, Factors, i).offset, minOffset);
 162         }
 163
 164         for (i= 0; i < syncState->traceNb; i++)
 165         {
 166                 g_array_index(factors, Factors, i).offset-= minOffset;
 167         }
 168
 169         /* Because the timestamps are corrected at the TSC level (not at the
 170          * LttTime level) all trace frequencies must be made equal. We choose to
 171          * use the frequency of the system with the lowest drift
 172          */
 173         minDrift= INFINITY;
 174         refFreqTrace= 0;
 175         for (i= 0; i < syncState->traceNb; i++)
 176         {
 177                 if (g_array_index(factors, Factors, i).drift < minDrift)
 178                 {
 179                         minDrift= g_array_index(factors, Factors, i).drift;
 180                         refFreqTrace= i;
 181                 }
 182         }
 183         g_assert(syncState->traceNb == 0 || minDrift != INFINITY);
 184
 185         // Write the factors to the LttTrace structures
 186         for (i= 0; i < syncState->traceNb; i++)
 187         {
 188                 LttTrace* t;
 189                 Factors* traceFactors;
 190
 191                 t= processingData->traceSetContext->traces[i]->t;
 192                 traceFactors= &g_array_index(factors, Factors, i);
 193
 194                 t->drift= traceFactors->drift;
 195                 t->offset= traceFactors->offset;
 196                 t->start_freq=
 197                         processingData->traceSetContext->traces[refFreqTrace]->t->start_freq;
 198                 t->freq_scale=
 199                         processingData->traceSetContext->traces[refFreqTrace]->t->freq_scale;
 200                 t->start_time_from_tsc =
 201                         ltt_time_from_uint64(tsc_to_uint64(t->freq_scale, t->start_freq,
 202                                         t->drift * t->start_tsc + t->offset));
 203         }
 204
 205         g_array_free(factors, TRUE);
 206
 207         lttv_traceset_context_compute_time_span(processingData->traceSetContext,
 208                 &processingData->traceSetContext->time_span);
 209
 210         g_debug("traceset start %ld.%09ld end %ld.%09ld\n",
 211                 processingData->traceSetContext->time_span.start_time.tv_sec,
 212                 processingData->traceSetContext->time_span.start_time.tv_nsec,
 213                 processingData->traceSetContext->time_span.end_time.tv_sec,
 214                 processingData->traceSetContext->time_span.end_time.tv_nsec);
 215
 216         return;
 217 }
 218
 219
 220 /*
 221  * Print statistics related to processing and downstream modules. Must be
 222  * called after finalizeProcessing.
 223  *
 224  * Args:
 225  *   syncState     container for synchronization data.
 226  */
 227 static void printProcessingStatsLTTVStandard(SyncState* const syncState)
 228 {
 229         unsigned int i;
 230         ProcessingDataLTTVStandard* processingData;
 231
 232         if (!syncState->stats)
 233         {
 234                 return;
 235         }
 236
 237         processingData= (ProcessingDataLTTVStandard*) syncState->processingData;
 238
 239         printf("LTTV processing stats:\n");
 240         printf("\treceived frames: %d\n", processingData->stats->totRecv);
 241         printf("\treceived frames that are IP: %d\n",
 242                 processingData->stats->totRecvIp);
 243         printf("\treceived and processed packets that are TCP: %d\n",
 244                 processingData->stats->totInE);
 245         printf("\tsent packets that are TCP: %d\n",
 246                 processingData->stats->totOutE);
 247
 248         if (syncState->matchingModule->printMatchingStats != NULL)
 249         {
 250                 syncState->matchingModule->printMatchingStats(syncState);
 251         }
 252
 253         printf("Resulting synchronization factors:\n");
 254         for (i= 0; i < syncState->traceNb; i++)
 255         {
 256                 LttTrace* t;
 257
 258                 t= processingData->traceSetContext->traces[i]->t;
 259
 260                 printf("\ttrace %u drift= %g offset= %g (%f) start time= %ld.%09ld\n",
 261                         i, t->drift, t->offset, (double) tsc_to_uint64(t->freq_scale,
 262                                 t->start_freq, t->offset) / NANOSECONDS_PER_SECOND,
 263                         t->start_time_from_tsc.tv_sec, t->start_time_from_tsc.tv_nsec);
 264         }
 265 }
 266
 267
 268 /*
 269  * Unregister event hooks. Deallocate processingData.
 270  *
 271  * Args:
 272  *   syncState:    container for synchronization data.
 273  *                 This function deallocates these processingData members:
 274  *                 stats
 275  */
 276 static void destroyProcessingLTTVStandard(SyncState* const syncState)
 277 {
 278         ProcessingDataLTTVStandard* processingData;
 279
 280         processingData= (ProcessingDataLTTVStandard*) syncState->processingData;
 281
 282         if (processingData == NULL)
 283         {
 284                 return;
 285         }
 286
 287         partialDestroyProcessingLTTVStandard(syncState);
 288
 289         if (syncState->stats)
 290         {
 291                 free(processingData->stats);
 292         }
 293
 294         free(syncState->processingData);
 295         syncState->processingData= NULL;
 296 }
 297
 298
 299 /*
 300  * Unregister event hooks. Deallocate some of processingData.
 301  *
 302  * This function can be called right after the events have been processed to
 303  * free some data structures that are not needed for finalization.
 304  *
 305  * Args:
 306  *   syncState:    container for synchronization data.
 307  *                 This function deallocates these members:
 308  *                 traceNumTable
 309  *                 hookListList
 310  *                 pendingRecv
 311  */
 312 static void partialDestroyProcessingLTTVStandard(SyncState* const syncState)
 313 {
 314         unsigned int i;
 315         ProcessingDataLTTVStandard* processingData;
 316
 317         processingData= (ProcessingDataLTTVStandard*) syncState->processingData;
 318
 319         if (processingData == NULL || processingData->traceNumTable == NULL)
 320         {
 321                 return;
 322         }
 323
 324         g_hash_table_destroy(processingData->traceNumTable);
 325         processingData->traceNumTable= NULL;
 326
 327         for(i= 0; i < syncState->traceNb; i++)
 328         {
 329
 330                 g_debug("Cleaning up pendingRecv list\n");
 331                 g_hash_table_destroy(processingData->pendingRecv[i]);
 332         }
 333         free(processingData->pendingRecv);
 334
 335         unregisterHooks(processingData->hookListList,
 336                 processingData->traceSetContext, syncState->traceNb);
 337 }
 338
 339
 340 /*
 341  * Lttv hook function that will be called for network events
 342  *
 343  * Args:
 344  *   hookData:     LttvTraceHook* for the type of event that generated the call
 345  *   callData:     LttvTracefileContext* at the moment of the event
 346  *
 347  * Returns:
 348  *   FALSE         Always returns FALSE, meaning to keep processing hooks for
 349  *                 this event
 350  */
 351 static gboolean processEventLTTVStandard(void* hookData, void* callData)
 352 {
 353         LttvTraceHook* traceHook;
 354         LttvTracefileContext* tfc;
 355         LttEvent* event;
 356         LttTime time;
 357         LttCycleCount tsc;
 358         LttTrace* trace;
 359         unsigned long traceNum;
 360         struct marker_info* info;
 361         SyncState* syncState;
 362         ProcessingDataLTTVStandard* processingData;
 363
 364         traceHook= (LttvTraceHook*) hookData;
 365         tfc= (LttvTracefileContext*) callData;
 366         syncState= (SyncState*) traceHook->hook_data;
 367         processingData= (ProcessingDataLTTVStandard*) syncState->processingData;
 368         event= ltt_tracefile_get_event(tfc->tf);
 369         time= ltt_event_time(event);
 370         tsc= ltt_event_cycle_count(event);
 371         trace= tfc->t_context->t;
 372         info= marker_get_info_from_id(tfc->tf->mdata, event->event_id);
 373
 374         g_assert(g_hash_table_lookup_extended(processingData->traceNumTable,
 375                         trace, NULL, (gpointer*) &traceNum));
 376
 377         g_debug("XXXX process event: time: %ld.%09ld trace: %ld (%p) name: %s ",
 378                 (long) time.tv_sec, time.tv_nsec, traceNum, trace,
 379                 g_quark_to_string(info->name));
 380
 381         if (info->name == LTT_EVENT_DEV_XMIT)
 382         {
 383                 NetEvent* outE;
 384
 385                 if (!ltt_event_get_unsigned(event,
 386                                 lttv_trace_get_hook_field(traceHook, 1)) == ETH_P_IP ||
 387                         !ltt_event_get_unsigned(event,
 388                                 lttv_trace_get_hook_field(traceHook, 2)) == IPPROTO_TCP)
 389                 {
 390                         return FALSE;
 391                 }
 392
 393                 if (syncState->stats)
 394                 {
 395                         processingData->stats->totOutE++;
 396                 }
 397
 398                 outE= malloc(sizeof(NetEvent));
 399                 outE->packetKey= malloc(sizeof(PacketKey));
 400
 401                 outE->traceNum= traceNum;
 402                 outE->tsc= tsc;
 403                 outE->skb= NULL;
 404                 outE->packetKey->connectionKey.saddr= ltt_event_get_unsigned(event,
 405                         lttv_trace_get_hook_field(traceHook, 3));
 406                 outE->packetKey->connectionKey.daddr= ltt_event_get_unsigned(event,
 407                         lttv_trace_get_hook_field(traceHook, 4));
 408                 outE->packetKey->tot_len= ltt_event_get_unsigned(event,
 409                         lttv_trace_get_hook_field(traceHook, 5));
 410                 outE->packetKey->ihl= ltt_event_get_unsigned(event,
 411                         lttv_trace_get_hook_field(traceHook, 6));
 412                 outE->packetKey->connectionKey.source= ltt_event_get_unsigned(event,
 413                         lttv_trace_get_hook_field(traceHook, 7));
 414                 outE->packetKey->connectionKey.dest= ltt_event_get_unsigned(event,
 415                         lttv_trace_get_hook_field(traceHook, 8));
 416                 outE->packetKey->seq= ltt_event_get_unsigned(event,
 417                         lttv_trace_get_hook_field(traceHook, 9));
 418                 outE->packetKey->ack_seq= ltt_event_get_unsigned(event,
 419                         lttv_trace_get_hook_field(traceHook, 10));
 420                 outE->packetKey->doff= ltt_event_get_unsigned(event,
 421                         lttv_trace_get_hook_field(traceHook, 11));
 422                 outE->packetKey->ack= ltt_event_get_unsigned(event,
 423                         lttv_trace_get_hook_field(traceHook, 12));
 424                 outE->packetKey->rst= ltt_event_get_unsigned(event,
 425                         lttv_trace_get_hook_field(traceHook, 13));
 426                 outE->packetKey->syn= ltt_event_get_unsigned(event,
 427                         lttv_trace_get_hook_field(traceHook, 14));
 428                 outE->packetKey->fin= ltt_event_get_unsigned(event,
 429                         lttv_trace_get_hook_field(traceHook, 15));
 430
 431                 syncState->matchingModule->matchEvent(syncState, outE, OUT);
 432
 433                 g_debug("Output event done\n");
 434         }
 435         else if (info->name == LTT_EVENT_DEV_RECEIVE)
 436         {
 437                 guint32 protocol;
 438
 439                 if (syncState->stats)
 440                 {
 441                         processingData->stats->totRecv++;
 442                 }
 443
 444                 protocol= ltt_event_get_unsigned(event,
 445                         lttv_trace_get_hook_field(traceHook, 1));
 446
 447                 if (protocol == ETH_P_IP)
 448                 {
 449                         NetEvent* inE;
 450
 451                         if (syncState->stats)
 452                         {
 453                                 processingData->stats->totRecvIp++;
 454                         }
 455
 456                         inE= malloc(sizeof(NetEvent));
 457
 458                         inE->traceNum= traceNum;
 459                         inE->tsc= tsc;
 460                         inE->skb= (void*) (long) ltt_event_get_long_unsigned(event,
 461                                 lttv_trace_get_hook_field(traceHook, 0));
 462                         inE->packetKey= NULL;
 463
 464                         g_hash_table_replace(processingData->pendingRecv[traceNum],
 465                                 inE->skb, inE);
 466
 467                         g_debug("Adding inE %p for skb %p to pendingRecv\n", inE, inE->skb);
 468                 }
 469                 else
 470                 {
 471                         g_debug("\n");
 472                 }
 473         }
 474         else if (info->name == LTT_EVENT_TCPV4_RCV)
 475         {
 476                 NetEvent* inE;
 477                 void* skb;
 478
 479                 // Search pendingRecv for an event with the same skb
 480                 skb= (void*) (long) ltt_event_get_long_unsigned(event,
 481                         lttv_trace_get_hook_field(traceHook, 0));
 482
 483                 inE= (NetEvent*)
 484                         g_hash_table_lookup(processingData->pendingRecv[traceNum], skb);
 485                 if (inE == NULL)
 486                 {
 487                         // This should only happen in case of lost events
 488                         g_debug("No matching pending receive event found\n");
 489                 }
 490                 else
 491                 {
 492                         if (syncState->stats)
 493                         {
 494                                 processingData->stats->totInE++;
 495                         }
 496
 497                         // If it's there, remove it and proceed with a receive event
 498                         g_hash_table_steal(processingData->pendingRecv[traceNum], skb);
 499
 500                         inE->packetKey= malloc(sizeof(PacketKey));
 501
 502                         inE->packetKey->connectionKey.saddr= ltt_event_get_unsigned(event,
 503                                 lttv_trace_get_hook_field(traceHook, 1));
 504                         inE->packetKey->connectionKey.daddr= ltt_event_get_unsigned(event,
 505                                 lttv_trace_get_hook_field(traceHook, 2));
 506                         inE->packetKey->tot_len= ltt_event_get_unsigned(event,
 507                                 lttv_trace_get_hook_field(traceHook, 3));
 508                         inE->packetKey->ihl= ltt_event_get_unsigned(event,
 509                                 lttv_trace_get_hook_field(traceHook, 4));
 510                         inE->packetKey->connectionKey.source= ltt_event_get_unsigned(event,
 511                                 lttv_trace_get_hook_field(traceHook, 5));
 512                         inE->packetKey->connectionKey.dest= ltt_event_get_unsigned(event,
 513                                 lttv_trace_get_hook_field(traceHook, 6));
 514                         inE->packetKey->seq= ltt_event_get_unsigned(event,
 515                                 lttv_trace_get_hook_field(traceHook, 7));
 516                         inE->packetKey->ack_seq= ltt_event_get_unsigned(event,
 517                                 lttv_trace_get_hook_field(traceHook, 8));
 518                         inE->packetKey->doff= ltt_event_get_unsigned(event,
 519                                 lttv_trace_get_hook_field(traceHook, 9));
 520                         inE->packetKey->ack= ltt_event_get_unsigned(event,
 521                                 lttv_trace_get_hook_field(traceHook, 10));
 522                         inE->packetKey->rst= ltt_event_get_unsigned(event,
 523                                 lttv_trace_get_hook_field(traceHook, 11));
 524                         inE->packetKey->syn= ltt_event_get_unsigned(event,
 525                                 lttv_trace_get_hook_field(traceHook, 12));
 526                         inE->packetKey->fin= ltt_event_get_unsigned(event,
 527                                 lttv_trace_get_hook_field(traceHook, 13));
 528
 529                         syncState->matchingModule->matchEvent(syncState, inE, IN);
 530
 531                         g_debug("Input event %p for skb %p done\n", inE, skb);
 532                 }
 533         }
 534         else if (info->name == LTT_EVENT_NETWORK_IPV4_INTERFACE)
 535         {
 536                 char* name;
 537                 guint64 address;
 538                 gint64 up;
 539                 char addressString[17];
 540
 541                 address= ltt_event_get_long_unsigned(event,
 542                         lttv_trace_get_hook_field(traceHook, 1));
 543                 up= ltt_event_get_long_int(event, lttv_trace_get_hook_field(traceHook,
 544                                 2));
 545                 /* name must be the last field to get or else copy the string, see the
 546                  * doc for ltt_event_get_string()
 547                  */
 548                 name= ltt_event_get_string(event, lttv_trace_get_hook_field(traceHook,
 549                                 0));
 550
 551                 convertIP(addressString, address);
 552
 553                 g_debug("name \"%s\" address %s up %lld\n", name, addressString, up);
 554         }
 555         else
 556         {
 557                 g_assert_not_reached();
 558         }
 559
 560         return FALSE;
 561 }