Profiling: add per packet accounting of how much ticks are spend in protocol detection.

src/app-layer.c

@@ -155,8 +155,11 @@ int AppLayerHandleTCPData(AlpProtoDetectThreadCtx *dp_ctx, Flow *f,
             }
 #endif
 
+            PACKET_PROFILING_APP_PD_START(dp_ctx);
             alproto = AppLayerDetectGetProto(&alp_proto_ctx, dp_ctx, f,
                     data, data_len, flags, IPPROTO_TCP);
+            PACKET_PROFILING_APP_PD_END(dp_ctx);
+
             if (alproto != ALPROTO_UNKNOWN) {
                 /* store the proto and setup the L7 data array */
                 FlowL7DataPtrInit(f);

src/decode.h

@@ -285,6 +285,7 @@ typedef struct PktProfiling_ {
 
     PktProfilingTmmData tmm[TMM_SIZE];
     PktProfilingAppData app[ALPROTO_MAX];
+    uint32_t proto_detect;
 } PktProfiling;
 
 #endif /* PROFILING */
@@ -478,6 +479,9 @@ typedef struct AlpProtoDetectThreadCtx_ {
     uint64_t ticks_end;
     uint32_t ticks_spent;
     uint16_t alproto;
+    uint64_t proto_detect_ticks_start;
+    uint64_t proto_detect_ticks_end;
+    uint32_t proto_detect_ticks_spent;
 #endif
 } AlpProtoDetectThreadCtx;
 

src/util-profiling.c

@@ -98,6 +98,9 @@ SCProfilePacketData packet_profile_tmm_data6[TMM_SIZE][257];
 SCProfilePacketData packet_profile_app_data4[TMM_SIZE][257];
 SCProfilePacketData packet_profile_app_data6[TMM_SIZE][257];
 
+SCProfilePacketData packet_profile_app_pd_data4[257];
+SCProfilePacketData packet_profile_app_pd_data6[257];
+
 /**
  * Used for generating the summary data to print.
  */
@@ -237,6 +240,8 @@ SCProfilingInit(void)
             memset(&packet_profile_tmm_data6, 0, sizeof(packet_profile_tmm_data6));
             memset(&packet_profile_app_data4, 0, sizeof(packet_profile_app_data4));
             memset(&packet_profile_app_data6, 0, sizeof(packet_profile_app_data6));
+            memset(&packet_profile_app_pd_data4, 0, sizeof(packet_profile_app_pd_data4));
+            memset(&packet_profile_app_pd_data6, 0, sizeof(packet_profile_app_pd_data6));
 
             const char *filename = ConfNodeLookupChildValue(conf, "filename");
             if (filename != NULL) {
@@ -289,7 +294,7 @@ SCProfilingInit(void)
                 for (i = 0; i < ALPROTO_MAX; i++) {
                     fprintf(packet_profile_csv_fp, "%s,", TmModuleAlprotoToString(i));
                 }
-                fprintf(packet_profile_csv_fp, "STREAM (no app)\n");
+                fprintf(packet_profile_csv_fp, "STREAM (no app),proto detect,\n");
 
                 profiling_packets_csv_enabled = 1;
             }
@@ -763,6 +768,32 @@ void SCProfilingDumpPacketStats(void) {
         }
     }
 
+    /* proto detect output */
+    {
+        int p;
+        for (p = 0; p < 257; p++) {
+            SCProfilePacketData *pd = &packet_profile_app_pd_data4[p];
+
+            if (pd->cnt == 0) {
+                continue;
+            }
+
+            fprintf(fp, "%-20s    IPv4     %3d  %8u     %6u   %10u  %8"PRIu64"\n",
+                    "Proto detect", p, pd->cnt, pd->min, pd->max, pd->tot / pd->cnt);
+        }
+
+        for (p = 0; p < 257; p++) {
+            SCProfilePacketData *pd = &packet_profile_app_pd_data6[p];
+
+            if (pd->cnt == 0) {
+                continue;
+            }
+
+            fprintf(fp, "%-20s    IPv6     %3d  %8u     %6u   %10u  %8"PRIu64"\n",
+                    "Proto detect", p, pd->cnt, pd->min, pd->max, pd->tot / pd->cnt);
+        }
+    }
+
     fclose(fp);
 }
 
@@ -810,9 +841,29 @@ void SCProfilingPrintPacketProfile(Packet *p) {
     if (tmm_streamtcp_tcp > app_total)
         real_tcp = tmm_streamtcp_tcp - app_total;
     fprintf(packet_profile_csv_fp, "%"PRIu32",", real_tcp);
+
+    fprintf(packet_profile_csv_fp, "%"PRIu32",", p->profile.proto_detect);
     fprintf(packet_profile_csv_fp,"\n");
 }
 
+void SCProfilingUpdatePacketAppPdRecord(uint8_t ipproto, uint32_t ticks_spent, int ipver) {
+    SCProfilePacketData *pd;
+    if (ipver == 4)
+        pd = &packet_profile_app_pd_data4[ipproto];
+    else
+        pd = &packet_profile_app_pd_data6[ipproto];
+
+    if (pd->min == 0 || ticks_spent < pd->min) {
+        pd->min = ticks_spent;
+    }
+    if (pd->max < ticks_spent) {
+        pd->max = ticks_spent;
+    }
+
+    pd->tot += ticks_spent;
+    pd->cnt ++;
+}
+
 void SCProfilingUpdatePacketAppRecord(int alproto, uint8_t ipproto, PktProfilingAppData *pdt, int ipver) {
     if (pdt == NULL) {
         return;
@@ -840,10 +891,7 @@ void SCProfilingUpdatePacketAppRecords(Packet *p) {
     for (i = 0; i < ALPROTO_MAX; i++) {
         PktProfilingAppData *pdt = &p->profile.app[i];
 
-        if (pdt->ticks_spent == 0) {
+        if (pdt->ticks_spent > 0) {
-            continue;
-        }
-
             if (PKT_IS_IPV4(p)) {
                 SCProfilingUpdatePacketAppRecord(i, p->proto, pdt, 4);
             } else {
@@ -852,6 +900,15 @@ void SCProfilingUpdatePacketAppRecords(Packet *p) {
         }
     }
 
+    if (p->profile.proto_detect > 0) {
+        if (PKT_IS_IPV4(p)) {
+            SCProfilingUpdatePacketAppPdRecord(p->proto, p->profile.proto_detect, 4);
+        } else {
+            SCProfilingUpdatePacketAppPdRecord(p->proto, p->profile.proto_detect, 6);
+        }
+    }
+}
+
 void SCProfilingUpdatePacketTmmRecord(int module, uint8_t proto, PktProfilingTmmData *pdt, int ipver) {
     if (pdt == NULL) {
         return;

src/util-profiling.h

@@ -99,18 +99,34 @@ void SCProfilingAddPacket(Packet *);
         (dp)->ticks_spent = ((dp)->ticks_end - (dp)->ticks_start);  \
     }
 
+#define PACKET_PROFILING_APP_PD_START(dp)                           \
+    if (profiling_packets_enabled) {                                \
+        (dp)->proto_detect_ticks_start = UtilCpuGetTicks();         \
+    }
+
+#define PACKET_PROFILING_APP_PD_END(dp)                             \
+    if (profiling_packets_enabled) {                                \
+        (dp)->proto_detect_ticks_end = UtilCpuGetTicks();           \
+        (dp)->proto_detect_ticks_spent =                            \
+            ((dp)->proto_detect_ticks_end - (dp)->proto_detect_ticks_start);  \
+    }
+
 #define PACKET_PROFILING_APP_RESET(dp)                              \
     if (profiling_packets_enabled) {                                \
         (dp)->ticks_start = 0;                                      \
         (dp)->ticks_end = 0;                                        \
         (dp)->ticks_spent = 0;                                      \
         (dp)->alproto = 0;                                          \
+        (dp)->proto_detect_ticks_start = 0;                         \
+        (dp)->proto_detect_ticks_end = 0;                           \
+        (dp)->proto_detect_ticks_spent = 0;                         \
     }
 
 #define PACKET_PROFILING_APP_STORE(dp, p)                           \
     if (profiling_packets_enabled) {                                \
         if ((dp)->alproto < ALPROTO_MAX) {                          \
             (p)->profile.app[(dp)->alproto].ticks_spent += (dp)->ticks_spent;   \
+            (p)->profile.proto_detect += (dp)->proto_detect_ticks_spent;        \
         }                                                           \
     }