From: Benjamin Poirier Date: Mon, 2 Nov 2009 19:58:49 +0000 (-0500) Subject: Adds wall time field to events X-Git-Tag: v0.12.26~43 X-Git-Url: https://git.lttng.org./?a=commitdiff_plain;h=76be6fc24daf61767bf7f0c2e64f4691fbb56c63;p=lttv.git Adds wall time field to events Also analyze more events in the eval module. Signed-off-by: Benjamin Poirier --- diff --git a/lttv/lttv/sync/data_structures.c b/lttv/lttv/sync/data_structures.c index 70eb22c7..d4c804b6 100644 --- a/lttv/lttv/sync/data_structures.c +++ b/lttv/lttv/sync/data_structures.c @@ -563,3 +563,18 @@ void gfDestroyEvent(gpointer data, gpointer user_data) event->destroy(event); } + + +/* Subtract two WallTime structs + * + * Args: + * tA, tB: WallTime + * + * Returns: + * The result of tA - tB, as a double. This may incur a loss of + * precision. + */ +double wallTimeSub(const WallTime const* tA, const WallTime const* tB) +{ + return tA->seconds - tB->seconds + (tA->nanosec - tB->nanosec) / 1e9; +} diff --git a/lttv/lttv/sync/data_structures.h b/lttv/lttv/sync/data_structures.h index 719f664d..1f70ade4 100644 --- a/lttv/lttv/sync/data_structures.h +++ b/lttv/lttv/sync/data_structures.h @@ -79,10 +79,17 @@ typedef struct bool unicast; } UDPEvent; +typedef struct +{ + uint32_t seconds; + uint32_t nanosec; +} WallTime; + typedef struct _Event { unsigned long traceNum; - uint64_t time; + uint64_t cpuTime; + WallTime wallTime; // specific event structures and functions could be in separate files and // type could be an int @@ -146,6 +153,7 @@ void destroyEvent(Event* const event); void destroyTCPEvent(Event* const event); void destroyUDPEvent(Event* const event); void gfDestroyEvent(gpointer data, gpointer user_data); +double wallTimeSub(const WallTime const* tA, const WallTime const* tB); // Message-related functions void printTCPSegment(const Message* const segment); diff --git a/lttv/lttv/sync/event_analysis_chull.c b/lttv/lttv/sync/event_analysis_chull.c index 6f6e3090..0bea74a8 100644 --- a/lttv/lttv/sync/event_analysis_chull.c +++ b/lttv/lttv/sync/event_analysis_chull.c @@ -397,8 +397,8 @@ static void analyzeMessageCHull(SyncState* const syncState, Message* const messa if (message->inE->traceNum < message->outE->traceNum) { // CA is inE->traceNum - newPoint->x= message->inE->time; - newPoint->y= message->outE->time; + newPoint->x= message->inE->cpuTime; + newPoint->y= message->outE->cpuTime; hullType= UPPER; g_debug("Reception point hullArray[%lu][%lu] x= inE->time= %llu y= outE->time= %llu", message->inE->traceNum, message->outE->traceNum, newPoint->x, @@ -407,8 +407,8 @@ static void analyzeMessageCHull(SyncState* const syncState, Message* const messa else { // CA is outE->traceNum - newPoint->x= message->outE->time; - newPoint->y= message->inE->time; + newPoint->x= message->outE->cpuTime; + newPoint->y= message->inE->cpuTime; hullType= LOWER; g_debug("Send point hullArray[%lu][%lu] x= inE->time= %llu y= outE->time= %llu", message->inE->traceNum, message->outE->traceNum, newPoint->x, diff --git a/lttv/lttv/sync/event_analysis_eval.c b/lttv/lttv/sync/event_analysis_eval.c index 05a49acc..49f3e177 100644 --- a/lttv/lttv/sync/event_analysis_eval.c +++ b/lttv/lttv/sync/event_analysis_eval.c @@ -24,6 +24,7 @@ #include #include +#include #include #include #include @@ -59,6 +60,9 @@ static void gdnDestroyDouble(gpointer data); static void readRttInfo(GHashTable* rttInfo, FILE* rttFile); static void positionStream(FILE* stream); +static void gfSum(gpointer data, gpointer userData); +static void gfSumSquares(gpointer data, gpointer userData); + static AnalysisModule analysisModuleEval= { .name= "eval", @@ -133,15 +137,15 @@ static void initAnalysisEval(SyncState* const syncState) if (syncState->stats) { - analysisData->stats= malloc(sizeof(AnalysisStatsEval)); + analysisData->stats= calloc(1, sizeof(AnalysisStatsEval)); analysisData->stats->broadcastDiffSum= 0.; - analysisData->stats->allStats= malloc(syncState->traceNb * - sizeof(TracePairStats*)); + analysisData->stats->messageStats= malloc(syncState->traceNb * + sizeof(MessageStats*)); for (i= 0; i < syncState->traceNb; i++) { - analysisData->stats->allStats[i]= calloc(syncState->traceNb, - sizeof(TracePairStats)); + analysisData->stats->messageStats[i]= calloc(syncState->traceNb, + sizeof(MessageStats)); } } } @@ -174,9 +178,9 @@ static void destroyAnalysisEval(SyncState* const syncState) { for (i= 0; i < syncState->traceNb; i++) { - free(analysisData->stats->allStats[i]); + free(analysisData->stats->messageStats[i]); } - free(analysisData->stats->allStats); + free(analysisData->stats->messageStats); free(analysisData->stats); } @@ -188,6 +192,8 @@ static void destroyAnalysisEval(SyncState* const syncState) /* * Perform analysis on an event pair. * + * Check if there is message inversion or messages that are too fast. + * * Args: * syncState container for synchronization data * message structure containing the events @@ -195,14 +201,52 @@ static void destroyAnalysisEval(SyncState* const syncState) static void analyzeMessageEval(SyncState* const syncState, Message* const message) { AnalysisDataEval* analysisData; + MessageStats* messageStats; + double* rttInfo; + double tt; + struct RttKey rttKey; + + if (!syncState->stats) + { + return; + } analysisData= (AnalysisDataEval*) syncState->analysisData; + messageStats= + &analysisData->stats->messageStats[message->outE->traceNum][message->inE->traceNum]; + + messageStats->total++; + + tt= wallTimeSub(&message->inE->wallTime, &message->outE->wallTime); + if (tt <= 0) + { + messageStats->inversionNb++; + } + + g_assert(message->inE->type == UDP); + rttKey.saddr= message->inE->event.udpEvent->datagramKey->saddr; + rttKey.daddr= message->inE->event.udpEvent->datagramKey->daddr; + rttInfo= g_hash_table_lookup(analysisData->rttInfo, &rttKey); + + if (rttInfo) + { + if (tt < *rttInfo / 2.) + { + messageStats->tooFastNb++; + } + } + else + { + messageStats->noRTTInfoNb++; + } } /* * Perform analysis on multiple messages * + * Measure the RTT + * * Args: * syncState container for synchronization data * exchange structure containing the messages @@ -218,6 +262,8 @@ static void analyzeExchangeEval(SyncState* const syncState, Exchange* const exch /* * Perform analysis on muliple events * + * Sum the broadcast differential delays + * * Args: * syncState container for synchronization data * broadcast structure containing the events @@ -225,8 +271,27 @@ static void analyzeExchangeEval(SyncState* const syncState, Exchange* const exch static void analyzeBroadcastEval(SyncState* const syncState, Broadcast* const broadcast) { AnalysisDataEval* analysisData; + double sum= 0, squaresSum= 0; + double y; + + if (!syncState->stats) + { + return; + } analysisData= (AnalysisDataEval*) syncState->analysisData; + + g_queue_foreach(broadcast->events, &gfSum, &sum); + g_queue_foreach(broadcast->events, &gfSumSquares, &squaresSum); + + analysisData->stats->broadcastNb++; + // Because of numerical errors, this can at times be < 0 + y= squaresSum / g_queue_get_length(broadcast->events) - pow(sum / + g_queue_get_length(broadcast->events), 2.); + if (y > 0) + { + analysisData->stats->broadcastDiffSum+= sqrt(y); + } } @@ -285,26 +350,29 @@ static void printAnalysisStatsEval(SyncState* const syncState) printf("Synchronization evaluation analysis stats:\n"); printf("\tsum of broadcast differential delays: %g\n", analysisData->stats->broadcastDiffSum); + printf("\taverage broadcast differential delays: %g\n", + analysisData->stats->broadcastDiffSum / + analysisData->stats->broadcastNb); printf("\tIndividual evaluation:\n" - "\t\tTrace pair Inversions Too fast (No RTT info)\n"); + "\t\tTrace pair Inversions Too fast (No RTT info) Total\n"); for (i= 0; i < syncState->traceNb; i++) { for (j= i + 1; j < syncState->traceNb; j++) { - TracePairStats* tpStats; - const char* format= "\t\t%3d - %-3d %-10u %-10u %u\n"; + MessageStats* messageStats; + const char* format= "\t\t%3d - %-3d %-10u %-10u %-10u %u\n"; - tpStats= &analysisData->stats->allStats[i][j]; + messageStats= &analysisData->stats->messageStats[i][j]; - printf(format, i, j, tpStats->inversionNb, tpStats->tooFastNb, - tpStats->noRTTInfoNb); + printf(format, i, j, messageStats->inversionNb, messageStats->tooFastNb, + messageStats->noRTTInfoNb, messageStats->total); - tpStats= &analysisData->stats->allStats[j][i]; + messageStats= &analysisData->stats->messageStats[j][i]; - printf(format, j, i, tpStats->inversionNb, tpStats->tooFastNb, - tpStats->noRTTInfoNb); + printf(format, j, i, messageStats->inversionNb, messageStats->tooFastNb, + messageStats->noRTTInfoNb, messageStats->total); } } } @@ -451,6 +519,7 @@ static void readRttInfo(GHashTable* rttInfo, FILE* rttStream) addr.s_addr; } + *rtt/= 1e3; g_hash_table_insert(rttInfo, rttKey, rtt); positionStream(rttStream); @@ -520,3 +589,41 @@ outEof: free(line); } } + + +/* + * A GFunc for g_queue_foreach() + * + * Args: + * data Event*, a UDP broadcast event + * user_data double*, the running sum + * + * Returns: + * Adds the time of the event to the sum + */ +static void gfSum(gpointer data, gpointer userData) +{ + Event* event= (Event*) data; + + *(double*) userData+= event->wallTime.seconds + event->wallTime.nanosec / + 1e9; +} + + +/* + * A GFunc for g_queue_foreach() + * + * Args: + * data Event*, a UDP broadcast event + * user_data double*, the running sum + * + * Returns: + * Adds the square of the time of the event to the sum + */ +static void gfSumSquares(gpointer data, gpointer userData) +{ + Event* event= (Event*) data; + + *(double*) userData+= pow(event->wallTime.seconds + event->wallTime.nanosec + / 1e9, 2.); +} diff --git a/lttv/lttv/sync/event_analysis_eval.h b/lttv/lttv/sync/event_analysis_eval.h index 06e6cab3..1515bec9 100644 --- a/lttv/lttv/sync/event_analysis_eval.h +++ b/lttv/lttv/sync/event_analysis_eval.h @@ -28,13 +28,16 @@ typedef struct { unsigned int inversionNb, tooFastNb, - noRTTInfoNb; -} TracePairStats; + noRTTInfoNb, + total; +} MessageStats; typedef struct { double broadcastDiffSum; - TracePairStats** allStats; + unsigned int broadcastNb; + + MessageStats** messageStats; } AnalysisStatsEval; struct RttKey diff --git a/lttv/lttv/sync/event_analysis_linreg.c b/lttv/lttv/sync/event_analysis_linreg.c index cae90936..cdff7f37 100644 --- a/lttv/lttv/sync/event_analysis_linreg.c +++ b/lttv/lttv/sync/event_analysis_linreg.c @@ -193,14 +193,14 @@ static void analyzeExchangeLinReg(SyncState* const syncState, Exchange* const ex // Calculate the intermediate values for the // least-squares analysis - dji= ((double) ackedMessage->inE->time - (double) ackedMessage->outE->time - + (double) exchange->message->outE->time - (double) - exchange->message->inE->time) / 2; - eji= fabs((double) ackedMessage->inE->time - (double) - ackedMessage->outE->time - (double) exchange->message->outE->time + - (double) exchange->message->inE->time) / 2; - timoy= ((double) ackedMessage->outE->time + (double) - exchange->message->inE->time) / 2; + dji= ((double) ackedMessage->inE->cpuTime - (double) ackedMessage->outE->cpuTime + + (double) exchange->message->outE->cpuTime - (double) + exchange->message->inE->cpuTime) / 2; + eji= fabs((double) ackedMessage->inE->cpuTime - (double) + ackedMessage->outE->cpuTime - (double) exchange->message->outE->cpuTime + + (double) exchange->message->inE->cpuTime) / 2; + timoy= ((double) ackedMessage->outE->cpuTime + (double) + exchange->message->inE->cpuTime) / 2; ni= ackedMessage->outE->traceNum; nj= ackedMessage->inE->traceNum; fit= &analysisData->fitArray[nj][ni]; diff --git a/lttv/lttv/sync/event_matching_broadcast.c b/lttv/lttv/sync/event_matching_broadcast.c index 3db88e58..fbec98ec 100644 --- a/lttv/lttv/sync/event_matching_broadcast.c +++ b/lttv/lttv/sync/event_matching_broadcast.c @@ -306,9 +306,9 @@ static void printMatchingStatsBroadcast(SyncState* const syncState) matchingData->stats->totTransmit); printf("\ttotal broadcasts datagrams received: %u\n", matchingData->stats->totReceive); - printf("\ttotal broadcast groups for which all emissions were identified: %u\n", + printf("\ttotal broadcast groups for which all receptions were identified: %u\n", matchingData->stats->totComplete); - printf("\ttotal broadcast groups missing some emissions: %u\n", + printf("\ttotal broadcast groups missing some receptions: %u\n", matchingData->stats->totIncomplete); if (matchingData->stats->totIncomplete > 0) { diff --git a/lttv/lttv/sync/event_matching_tcp.c b/lttv/lttv/sync/event_matching_tcp.c index 98a15827..a8fdf5f0 100644 --- a/lttv/lttv/sync/event_matching_tcp.c +++ b/lttv/lttv/sync/event_matching_tcp.c @@ -646,14 +646,14 @@ static void writeMessagePoint(FILE* stream, const Message* const message) if (message->inE->traceNum < message->outE->traceNum) { // CA is inE->traceNum - x= message->inE->time; - y= message->outE->time; + x= message->inE->cpuTime; + y= message->outE->cpuTime; } else { // CA is outE->traceNum - x= message->outE->time; - y= message->inE->time; + x= message->outE->cpuTime; + y= message->inE->cpuTime; } fprintf(stream, "%20llu %20llu\n", x, y); diff --git a/lttv/lttv/sync/event_processing_lttng_standard.c b/lttv/lttv/sync/event_processing_lttng_standard.c index 1ee27c76..af1c93bb 100644 --- a/lttv/lttv/sync/event_processing_lttng_standard.c +++ b/lttv/lttv/sync/event_processing_lttng_standard.c @@ -370,8 +370,9 @@ static gboolean processEventLTTVStandard(void* hookData, void* callData) LttvTraceHook* traceHook; LttvTracefileContext* tfc; LttEvent* event; - LttTime time; LttCycleCount tsc; + LttTime time; + WallTime wTime; LttTrace* trace; unsigned long traceNum; struct marker_info* info; @@ -384,15 +385,17 @@ static gboolean processEventLTTVStandard(void* hookData, void* callData) syncState= (SyncState*) traceHook->hook_data; processingData= (ProcessingDataLTTVStandard*) syncState->processingData; event= ltt_tracefile_get_event(tfc->tf); - time= ltt_event_time(event); - tsc= trace->drift * ltt_event_cycle_count(event) + trace->offset; info= marker_get_info_from_id(tfc->tf->mdata, event->event_id); + tsc= ltt_event_cycle_count(event); + time= ltt_event_time(event); + wTime.seconds= time.tv_sec; + wTime.nanosec= time.tv_nsec; g_assert(g_hash_table_lookup_extended(processingData->traceNumTable, trace, NULL, (gpointer*) &traceNum)); g_debug("XXXX process event: time: %ld.%09ld trace: %ld (%p) name: %s ", - (long) time.tv_sec, time.tv_nsec, traceNum, trace, + time.tv_sec, time.tv_nsec, traceNum, trace, g_quark_to_string(info->name)); if (info->name == LTT_EVENT_DEV_XMIT_EXTENDED) @@ -419,7 +422,8 @@ static gboolean processEventLTTVStandard(void* hookData, void* callData) outE= malloc(sizeof(Event)); outE->traceNum= traceNum; - outE->time= tsc; + outE->cpuTime= tsc; + outE->wallTime= wTime; outE->type= TCP; outE->destroy= &destroyTCPEvent; outE->event.tcpEvent= malloc(sizeof(TCPEvent)); @@ -486,7 +490,8 @@ static gboolean processEventLTTVStandard(void* hookData, void* callData) inE= malloc(sizeof(Event)); inE->traceNum= traceNum; - inE->time= tsc; + inE->cpuTime= tsc; + inE->wallTime= wTime; inE->event.tcpEvent= NULL; inE->destroy= &destroyEvent;