From 17e7d179d0abe76a1aea5c2fe586536069df2500 Mon Sep 17 00:00:00 2001 From: Victor Julien Date: Sat, 22 Sep 2018 18:14:56 +0200 Subject: [PATCH] profiling/csv: update output format Update output to be: pcap_cnt,total,receive,decode,flowworker,threading,proto detect,flow, stream,app-layer,detect,tcp-prune,loggers,, For TCP, the app-layer cost is not part of stream anymore. --- src/util-profiling.c | 125 +++++++++++++++++++++++++++++++------------ 1 file changed, 91 insertions(+), 34 deletions(-) diff --git a/src/util-profiling.c b/src/util-profiling.c index e70de4effd..f68b835870 100644 --- a/src/util-profiling.c +++ b/src/util-profiling.c @@ -119,6 +119,7 @@ __thread int profiling_rules_entered = 0; void SCProfilingDumpPacketStats(void); const char * PacketProfileDetectIdToString(PacketProfileDetectId id); const char * PacketProfileLoggertIdToString(LoggerId id); +static void PrintCSVHeader(void); static void FormatNumber(uint64_t num, char *str, size_t size) { @@ -198,14 +199,12 @@ SCProfilingInit(void) conf = ConfGetNode("profiling.packets.csv"); if (conf != NULL) { if (ConfNodeChildValueIsTrue(conf, "enabled")) { - const char *filename = ConfNodeLookupChildValue(conf, "filename"); if (filename == NULL) { filename = "packet_profile.csv"; } - const char *log_dir; - log_dir = ConfigGetLogDirectory(); + const char *log_dir = ConfigGetLogDirectory(); profiling_csv_file_name = SCMalloc(PATH_MAX); if (unlikely(profiling_csv_file_name == NULL)) { @@ -216,22 +215,12 @@ SCProfilingInit(void) packet_profile_csv_fp = fopen(profiling_csv_file_name, "w"); if (packet_profile_csv_fp == NULL) { + SCFree(profiling_csv_file_name); + profiling_csv_file_name = NULL; return; } - fprintf(packet_profile_csv_fp, "pcap_cnt,ipver,ipproto,total,"); - int i; - for (i = 0; i < TMM_SIZE; i++) { - fprintf(packet_profile_csv_fp, "%s,", TmModuleTmmIdToString(i)); - } - fprintf(packet_profile_csv_fp, "threading,"); - for (i = 0; i < ALPROTO_MAX; i++) { - fprintf(packet_profile_csv_fp, "%s,", AppProtoToString(i)); - } - fprintf(packet_profile_csv_fp, "proto detect,"); - for (i = 0; i < PROF_DETECT_SIZE; i++) { - fprintf(packet_profile_csv_fp, "%s,", PacketProfileDetectIdToString(i)); - } - fprintf(packet_profile_csv_fp, "\n"); + + PrintCSVHeader(); profiling_packets_csv_enabled = 1; } @@ -791,36 +780,75 @@ void SCProfilingDumpPacketStats(void) fclose(fp); } +static void PrintCSVHeader(void) +{ + fprintf(packet_profile_csv_fp, "pcap_cnt,total,receive,decode,flowworker,"); + fprintf(packet_profile_csv_fp, "threading,"); + fprintf(packet_profile_csv_fp, "proto detect,"); + + for (enum ProfileFlowWorkerId fwi = 0; fwi < PROFILE_FLOWWORKER_SIZE; fwi++) { + fprintf(packet_profile_csv_fp, "%s,", ProfileFlowWorkerIdToString(fwi)); + } + fprintf(packet_profile_csv_fp, "loggers,"); + + /* detect stages */ + for (int i = 0; i < PROF_DETECT_SIZE; i++) { + fprintf(packet_profile_csv_fp, "%s,", PacketProfileDetectIdToString(i)); + } + + /* individual loggers */ + for (LoggerId i = 0; i < LOGGER_SIZE; i++) { + fprintf(packet_profile_csv_fp, "%s,", PacketProfileLoggertIdToString(i)); + } + + fprintf(packet_profile_csv_fp, "\n"); +} + void SCProfilingPrintPacketProfile(Packet *p) { - if (profiling_packets_csv_enabled == 0 || p == NULL || packet_profile_csv_fp == NULL || p->profile == NULL) { + if (profiling_packets_csv_enabled == 0 || p == NULL || + packet_profile_csv_fp == NULL || p->profile == NULL) { return; } + uint64_t tmm_total = 0; + uint64_t receive = 0; + uint64_t decode = 0; + + /* total cost from acquisition to return to packetpool */ uint64_t delta = p->profile->ticks_end - p->profile->ticks_start; + fprintf(packet_profile_csv_fp, "%"PRIu64",%"PRIu64",", + p->pcap_cnt, delta); - fprintf(packet_profile_csv_fp, "%"PRIu64",%c,%"PRIu8",%"PRIu64",", - p->pcap_cnt, PKT_IS_IPV4(p) ? '4' : (PKT_IS_IPV6(p) ? '6' : '?'), p->proto, - delta); + for (int i = 0; i < TMM_SIZE; i++) { + const PktProfilingTmmData *pdt = &p->profile->tmm[i]; + uint64_t tmm_delta = pdt->ticks_end - pdt->ticks_start; - int i; - uint64_t tmm_total = 0; + if (tmm_modules[i].flags & TM_FLAG_RECEIVE_TM) { + if (tmm_delta) { + receive = tmm_delta; + } + continue; - for (i = 0; i < TMM_SIZE; i++) { - PktProfilingTmmData *pdt = &p->profile->tmm[i]; + } else if (tmm_modules[i].flags & TM_FLAG_DECODE_TM) { + if (tmm_delta) { + decode = tmm_delta; + } + continue; + } - uint64_t tmm_delta = pdt->ticks_end - pdt->ticks_start; - fprintf(packet_profile_csv_fp, "%"PRIu64",", tmm_delta); tmm_total += tmm_delta; } - + fprintf(packet_profile_csv_fp, "%"PRIu64",", receive); + fprintf(packet_profile_csv_fp, "%"PRIu64",", decode); + PktProfilingTmmData *fw_pdt = &p->profile->tmm[TMM_FLOWWORKER]; + fprintf(packet_profile_csv_fp, "%"PRIu64",", fw_pdt->ticks_end - fw_pdt->ticks_start); fprintf(packet_profile_csv_fp, "%"PRIu64",", delta - tmm_total); + /* count ticks for app layer */ uint64_t app_total = 0; - for (i = 0; i < ALPROTO_MAX; i++) { - PktProfilingAppData *pdt = &p->profile->app[i]; - - fprintf(packet_profile_csv_fp,"%"PRIu64",", pdt->ticks_spent); + for (AppProto i = 1; i < ALPROTO_FAILED; i++) { + const PktProfilingAppData *pdt = &p->profile->app[i]; if (p->proto == IPPROTO_TCP) { app_total += pdt->ticks_spent; @@ -829,11 +857,40 @@ void SCProfilingPrintPacketProfile(Packet *p) fprintf(packet_profile_csv_fp, "%"PRIu64",", p->profile->proto_detect); - for (i = 0; i < PROF_DETECT_SIZE; i++) { - PktProfilingDetectData *pdt = &p->profile->detect[i]; + /* print flowworker steps */ + for (enum ProfileFlowWorkerId fwi = 0; fwi < PROFILE_FLOWWORKER_SIZE; fwi++) { + const PktProfilingData *pd = &p->profile->flowworker[fwi]; + uint64_t ticks_spent = pd->ticks_end - pd->ticks_start; + if (fwi == PROFILE_FLOWWORKER_STREAM) { + ticks_spent -= app_total; + } else if (fwi == PROFILE_FLOWWORKER_APPLAYERUDP && app_total) { + ticks_spent = app_total; + } + + fprintf(packet_profile_csv_fp, "%"PRIu64",", ticks_spent); + } + + /* count loggers cost and print as a single cost */ + uint64_t loggers = 0; + for (LoggerId i = 0; i < LOGGER_SIZE; i++) { + const PktProfilingLoggerData *pd = &p->profile->logger[i]; + loggers += pd->ticks_spent; + } + fprintf(packet_profile_csv_fp, "%"PRIu64",", loggers); + + /* detect steps */ + for (int i = 0; i < PROF_DETECT_SIZE; i++) { + const PktProfilingDetectData *pdt = &p->profile->detect[i]; fprintf(packet_profile_csv_fp,"%"PRIu64",", pdt->ticks_spent); } + + /* print individual loggers */ + for (LoggerId i = 0; i < LOGGER_SIZE; i++) { + const PktProfilingLoggerData *pd = &p->profile->logger[i]; + fprintf(packet_profile_csv_fp, "%"PRIu64",", pd->ticks_spent); + } + fprintf(packet_profile_csv_fp,"\n"); }