suricata
util-profiling.c
Go to the documentation of this file.
1 /* Copyright (C) 2007-2023 Open Information Security Foundation
2  *
3  * You can copy, redistribute or modify this Program under the terms of
4  * the GNU General Public License version 2 as published by the Free
5  * Software Foundation.
6  *
7  * This program is distributed in the hope that it will be useful,
8  * but WITHOUT ANY WARRANTY; without even the implied warranty of
9  * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
10  * GNU General Public License for more details.
11  *
12  * You should have received a copy of the GNU General Public License
13  * version 2 along with this program; if not, write to the Free Software
14  * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA
15  * 02110-1301, USA.
16  */
17 
18 /**
19  * \file
20  *
21  * \author Endace Technology Limited.
22  * \author Victor Julien <victor@inliniac.net>
23  *
24  * An API for profiling operations.
25  *
26  * Really just a wrapper around the existing perf counters.
27  */
28 
29 #include "suricata-common.h"
30 #include "util-profiling.h"
31 
32 #ifdef PROFILING
33 #include "tm-threads.h"
34 #include "conf.h"
35 #include "util-unittest.h"
36 #include "util-byte.h"
37 #include "util-profiling-locks.h"
38 #include "util-conf.h"
39 
40 #ifndef MIN
41 #define MIN(a, b) (((a) < (b)) ? (a) : (b))
42 #endif
43 
44 #define DEFAULT_LOG_FILENAME "profile.log"
45 #define DEFAULT_LOG_MODE_APPEND "yes"
46 
47 static pthread_mutex_t packet_profile_lock;
48 static FILE *packet_profile_csv_fp = NULL;
49 
50 extern int profiling_locks_enabled;
52 extern char *profiling_locks_file_name;
53 extern const char *profiling_locks_file_mode;
54 
55 typedef struct SCProfilePacketData_ {
56  uint64_t min;
57  uint64_t max;
58  uint64_t tot;
59  uint64_t cnt;
60 #ifdef PROFILE_LOCKING
61  uint64_t lock;
62  uint64_t ticks;
63  uint64_t contention;
64 
65  uint64_t slock;
66  uint64_t sticks;
67  uint64_t scontention;
68 #endif
70 SCProfilePacketData packet_profile_data4[257]; /**< all proto's + tunnel */
71 SCProfilePacketData packet_profile_data6[257]; /**< all proto's + tunnel */
72 
73 /* each module, each proto */
76 
79 
82 
85 
88 
92 };
93 
95 
98 
99 static int profiling_packets_csv_enabled = 0;
100 static int profiling_packets_output_to_file = 0;
101 static char *profiling_file_name;
102 static char profiling_packets_file_name[PATH_MAX];
103 static char *profiling_csv_file_name;
104 static const char *profiling_packets_file_mode = "a";
105 
106 static int rate = 1;
107 static SC_ATOMIC_DECLARE(uint64_t, samples);
108 
109 /**
110  * Used as a check so we don't double enter a profiling run.
111  */
112 thread_local int profiling_rules_entered = 0;
113 
114 void SCProfilingDumpPacketStats(void);
117 static void PrintCSVHeader(void);
118 
119 static void FormatNumber(uint64_t num, char *str, size_t size)
120 {
121  if (num < 1000UL)
122  snprintf(str, size, "%"PRIu64, num);
123  else if (num < 1000000UL)
124  snprintf(str, size, "%3.1fk", (float)num/1000UL);
125  else if (num < 1000000000UL)
126  snprintf(str, size, "%3.1fm", (float)num/1000000UL);
127  else
128  snprintf(str, size, "%3.1fb", (float)num/1000000000UL);
129 }
130 
131 /**
132  * \brief Initialize profiling.
133  */
134 void
136 {
137  ConfNode *conf;
138 
139  SC_ATOMIC_INIT(samples);
140 
141  intmax_t rate_v = 0;
142  (void)ConfGetInt("profiling.sample-rate", &rate_v);
143  if (rate_v > 0 && rate_v < INT_MAX) {
144  rate = (int)rate_v;
145  if (rate != 1)
146  SCLogInfo("profiling runs for every %dth packet", rate);
147  else
148  SCLogInfo("profiling runs for every packet");
149  }
150 
151  conf = ConfGetNode("profiling.packets");
152  if (conf != NULL) {
153  if (ConfNodeChildValueIsTrue(conf, "enabled")) {
155 
156  if (pthread_mutex_init(&packet_profile_lock, NULL) != 0) {
157  FatalError("Failed to initialize packet profiling mutex.");
158  }
159  memset(&packet_profile_data4, 0, sizeof(packet_profile_data4));
160  memset(&packet_profile_data6, 0, sizeof(packet_profile_data6));
172 
173  const char *filename = ConfNodeLookupChildValue(conf, "filename");
174  if (filename != NULL) {
175  const char *log_dir;
176  log_dir = ConfigGetLogDirectory();
177 
178  snprintf(profiling_packets_file_name, sizeof(profiling_packets_file_name),
179  "%s/%s", log_dir, filename);
180 
181  const char *v = ConfNodeLookupChildValue(conf, "append");
182  if (v == NULL || ConfValIsTrue(v)) {
183  profiling_packets_file_mode = "a";
184  } else {
185  profiling_packets_file_mode = "w";
186  }
187 
188  profiling_packets_output_to_file = 1;
189  }
190  }
191 
192  conf = ConfGetNode("profiling.packets.csv");
193  if (conf != NULL) {
194  if (ConfNodeChildValueIsTrue(conf, "enabled")) {
195  const char *filename = ConfNodeLookupChildValue(conf, "filename");
196  if (filename == NULL) {
197  filename = "packet_profile.csv";
198  }
199 
200  const char *log_dir = ConfigGetLogDirectory();
201 
202  profiling_csv_file_name = SCMalloc(PATH_MAX);
203  if (unlikely(profiling_csv_file_name == NULL)) {
204  FatalError("out of memory");
205  }
206  snprintf(profiling_csv_file_name, PATH_MAX, "%s/%s", log_dir, filename);
207 
208  packet_profile_csv_fp = fopen(profiling_csv_file_name, "w");
209  if (packet_profile_csv_fp == NULL) {
210  SCFree(profiling_csv_file_name);
211  profiling_csv_file_name = NULL;
212  return;
213  }
214 
215  PrintCSVHeader();
216 
217  profiling_packets_csv_enabled = 1;
218  }
219  }
220  }
221 
222  conf = ConfGetNode("profiling.locks");
223  if (conf != NULL) {
224  if (ConfNodeChildValueIsTrue(conf, "enabled")) {
225 #ifndef PROFILE_LOCKING
226  SCLogWarning(
227  "lock profiling not compiled in. Add --enable-profiling-locks to configure.");
228 #else
230 
232 
233  const char *filename = ConfNodeLookupChildValue(conf, "filename");
234  if (filename != NULL) {
235  const char *log_dir = ConfigGetLogDirectory();
236 
238  if (unlikely(profiling_locks_file_name == NULL)) {
239  FatalError("can't duplicate file name");
240  }
241 
242  snprintf(profiling_locks_file_name, PATH_MAX, "%s/%s", log_dir, filename);
243 
244  const char *v = ConfNodeLookupChildValue(conf, "append");
245  if (v == NULL || ConfValIsTrue(v)) {
247  } else {
249  }
250 
252  }
253 #endif
254  }
255  }
256 
257 }
258 
259 /**
260  * \brief Free resources used by profiling.
261  */
262 void
264 {
266  pthread_mutex_destroy(&packet_profile_lock);
267  }
268 
269  if (profiling_packets_csv_enabled) {
270  if (packet_profile_csv_fp != NULL)
271  fclose(packet_profile_csv_fp);
272  packet_profile_csv_fp = NULL;
273  }
274 
275  if (profiling_csv_file_name != NULL)
276  SCFree(profiling_csv_file_name);
277  profiling_csv_file_name = NULL;
278 
279  if (profiling_file_name != NULL)
280  SCFree(profiling_file_name);
281  profiling_file_name = NULL;
282 
283 #ifdef PROFILE_LOCKING
285 #endif
286 }
287 
288 void
290 {
292  SCLogPerf("Done dumping profiling data.");
293 }
294 
295 static void DumpFlowWorkerIP(FILE *fp, int ipv, uint64_t total)
296 {
297  char totalstr[256];
298 
299  enum ProfileFlowWorkerId fwi;
300  for (fwi = 0; fwi < PROFILE_FLOWWORKER_SIZE; fwi++) {
302  for (int p = 0; p < 257; p++) {
303  SCProfilePacketData *pd = ipv == 4 ? &r->records4[p] : &r->records6[p];
304  if (pd->cnt == 0) {
305  continue;
306  }
307 
308  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
309  double percent = (long double)pd->tot /
310  (long double)total * 100;
311 
312  fprintf(fp, "%-20s IPv%d %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %-6.2f\n",
313  ProfileFlowWorkerIdToString(fwi), ipv, p, pd->cnt,
314  pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
315  }
316  }
317 }
318 
319 static void DumpFlowWorker(FILE *fp)
320 {
321  uint64_t total = 0;
322 
323  enum ProfileFlowWorkerId fwi;
324  for (fwi = 0; fwi < PROFILE_FLOWWORKER_SIZE; fwi++) {
326  for (int p = 0; p < 257; p++) {
327  SCProfilePacketData *pd = &r->records4[p];
328  total += pd->tot;
329  pd = &r->records6[p];
330  total += pd->tot;
331  }
332  }
333 
334  fprintf(fp, "\n%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
335  "Flow Worker", "IP ver", "Proto", "cnt", "min", "max", "avg");
336  fprintf(fp, "%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
337  "--------------------", "------", "-----", "----------", "------------", "------------", "-----------");
338  DumpFlowWorkerIP(fp, 4, total);
339  DumpFlowWorkerIP(fp, 6, total);
340  fprintf(fp, "Note: %s includes app-layer for TCP\n",
342 }
343 
345 {
346  FILE *fp;
347  char totalstr[256];
348  uint64_t total;
349 
350  if (profiling_packets_enabled == 0)
351  return;
352 
353  if (profiling_packets_output_to_file == 1) {
354  fp = fopen(profiling_packets_file_name, profiling_packets_file_mode);
355 
356  if (fp == NULL) {
357  SCLogError("failed to open %s: %s", profiling_packets_file_name, strerror(errno));
358  return;
359  }
360  } else {
361  fp = stdout;
362  }
363 
364  fprintf(fp, "\n\nPacket profile dump:\n");
365 
366  fprintf(fp, "\n%-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s\n",
367  "IP ver", "Proto", "cnt", "min", "max", "avg", "tot", "%%");
368  fprintf(fp, "%-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s\n",
369  "------", "-----", "----------", "------------", "------------", "-----------", "-----------", "---");
370  total = 0;
371  for (int i = 0; i < 257; i++) {
373  total += pd->tot;
374  pd = &packet_profile_data6[i];
375  total += pd->tot;
376  }
377 
378  for (int i = 0; i < 257; i++) {
380  if (pd->cnt == 0) {
381  continue;
382  }
383 
384  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
385  double percent = (long double)pd->tot /
386  (long double)total * 100;
387 
388  fprintf(fp, " IPv4 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %6.2f\n", i, pd->cnt,
389  pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
390  }
391 
392  for (int i = 0; i < 257; i++) {
394  if (pd->cnt == 0) {
395  continue;
396  }
397 
398  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
399  double percent = (long double)pd->tot /
400  (long double)total * 100;
401 
402  fprintf(fp, " IPv6 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %6.2f\n", i, pd->cnt,
403  pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
404  }
405  fprintf(fp, "Note: Protocol 256 tracks pseudo/tunnel packets.\n");
406 
407  fprintf(fp, "\nPer Thread module stats:\n");
408 
409  fprintf(fp, "\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
410  "Thread Module", "IP ver", "Proto", "cnt", "min", "max", "avg", "tot", "%%");
411 #ifdef PROFILE_LOCKING
412  fprintf(fp, " %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
413  "locks", "ticks", "cont.", "cont.avg", "slocks", "sticks", "scont.", "scont.avg");
414 #else
415  fprintf(fp, "\n");
416 #endif
417  fprintf(fp, "%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
418  "------------------------", "------", "-----", "----------", "------------", "------------", "-----------", "-----------", "---");
419 #ifdef PROFILE_LOCKING
420  fprintf(fp, " %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
421  "--------", "--------", "----------", "-----------", "--------", "--------", "------------", "-----------");
422 #else
423  fprintf(fp, "\n");
424 #endif
425  total = 0;
426  for (int m = 0; m < TMM_SIZE; m++) {
428  continue;
429 
430  for (int p = 0; p < 257; p++) {
432  total += pd->tot;
433 
434  pd = &packet_profile_tmm_data6[m][p];
435  total += pd->tot;
436  }
437  }
438 
439  for (int m = 0; m < TMM_SIZE; m++) {
441  continue;
442 
443  for (int p = 0; p < 257; p++) {
445  if (pd->cnt == 0) {
446  continue;
447  }
448 
449  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
450  double percent = (long double)pd->tot /
451  (long double)total * 100;
452 
453  fprintf(fp, "%-24s IPv4 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %6.2f",
454  TmModuleTmmIdToString(m), p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
455 #ifdef PROFILE_LOCKING
456  fprintf(fp, " %10.2f %12"PRIu64" %12"PRIu64" %10.2f %10.2f %12"PRIu64" %12"PRIu64" %10.2f\n",
457  (float)pd->lock/pd->cnt, (uint64_t)pd->ticks/pd->cnt, pd->contention, (float)pd->contention/pd->cnt, (float)pd->slock/pd->cnt, (uint64_t)pd->sticks/pd->cnt, pd->scontention, (float)pd->scontention/pd->cnt);
458 #else
459  fprintf(fp, "\n");
460 #endif
461  }
462  }
463 
464  for (int m = 0; m < TMM_SIZE; m++) {
466  continue;
467 
468  for (int p = 0; p < 257; p++) {
470  if (pd->cnt == 0) {
471  continue;
472  }
473 
474  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
475  double percent = (long double)pd->tot /
476  (long double)total * 100;
477 
478  fprintf(fp, "%-24s IPv6 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %6.2f\n",
479  TmModuleTmmIdToString(m), p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
480  }
481  }
482 
483  DumpFlowWorker(fp);
484 
485  fprintf(fp, "\nPer App layer parser stats:\n");
486 
487  fprintf(fp, "\n%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
488  "App Layer", "IP ver", "Proto", "cnt", "min", "max", "avg");
489  fprintf(fp, "%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
490  "--------------------", "------", "-----", "----------", "------------", "------------", "-----------");
491 
492  total = 0;
493  for (AppProto a = 0; a < ALPROTO_MAX; a++) {
494  for (int p = 0; p < 257; p++) {
496  total += pd->tot;
497 
498  pd = &packet_profile_app_data6[a][p];
499  total += pd->tot;
500  }
501  }
502  for (AppProto a = 0; a < ALPROTO_MAX; a++) {
503  for (int p = 0; p < 257; p++) {
505  if (pd->cnt == 0) {
506  continue;
507  }
508 
509  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
510  double percent = (long double)pd->tot /
511  (long double)total * 100;
512 
513  fprintf(fp,
514  "%-20s IPv4 %3d %12" PRIu64 " %12" PRIu64 " %12" PRIu64
515  " %12" PRIu64 " %12s %-6.2f\n",
516  AppProtoToString(a), p, pd->cnt, pd->min, pd->max,
517  (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
518  }
519  }
520 
521  for (AppProto a = 0; a < ALPROTO_MAX; a++) {
522  for (int p = 0; p < 257; p++) {
524  if (pd->cnt == 0) {
525  continue;
526  }
527 
528  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
529  double percent = (long double)pd->tot /
530  (long double)total * 100;
531 
532  fprintf(fp,
533  "%-20s IPv6 %3d %12" PRIu64 " %12" PRIu64 " %12" PRIu64
534  " %12" PRIu64 " %12s %-6.2f\n",
535  AppProtoToString(a), p, pd->cnt, pd->min, pd->max,
536  (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
537  }
538  }
539 
540  /* proto detect output */
541  {
542  for (int p = 0; p < 257; p++) {
544  if (pd->cnt == 0) {
545  continue;
546  }
547 
548  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
549  fprintf(fp, "%-20s IPv4 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s\n",
550  "Proto detect", p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr);
551  }
552 
553  for (int p = 0; p < 257; p++) {
555  if (pd->cnt == 0) {
556  continue;
557  }
558 
559  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
560  fprintf(fp, "%-20s IPv6 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s\n",
561  "Proto detect", p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr);
562  }
563  }
564 
565  total = 0;
566  for (int m = 0; m < PROF_DETECT_SIZE; m++) {
567  for (int p = 0; p < 257; p++) {
569  total += pd->tot;
570 
571  pd = &packet_profile_detect_data6[m][p];
572  total += pd->tot;
573  }
574  }
575 
576  fprintf(fp, "\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
577  "Log Thread Module", "IP ver", "Proto", "cnt", "min", "max", "avg", "tot", "%%");
578 #ifdef PROFILE_LOCKING
579  fprintf(fp, " %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
580  "locks", "ticks", "cont.", "cont.avg", "slocks", "sticks", "scont.", "scont.avg");
581 #else
582  fprintf(fp, "\n");
583 #endif
584  fprintf(fp, "%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
585  "------------------------", "------", "-----", "----------", "------------", "------------", "-----------", "-----------", "---");
586 #ifdef PROFILE_LOCKING
587  fprintf(fp, " %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
588  "--------", "--------", "----------", "-----------", "--------", "--------", "------------", "-----------");
589 #else
590  fprintf(fp, "\n");
591 #endif
592  total = 0;
593  for (int m = 0; m < TMM_SIZE; m++) {
595  continue;
596 
597  for (int p = 0; p < 257; p++) {
599  total += pd->tot;
600 
601  pd = &packet_profile_tmm_data6[m][p];
602  total += pd->tot;
603  }
604  }
605 
606  for (int m = 0; m < TMM_SIZE; m++) {
608  continue;
609 
610  for (int p = 0; p < 257; p++) {
612  if (pd->cnt == 0) {
613  continue;
614  }
615 
616  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
617  double percent = (long double)pd->tot /
618  (long double)total * 100;
619 
620  fprintf(fp, "%-24s IPv4 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %6.2f",
621  TmModuleTmmIdToString(m), p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
622 #ifdef PROFILE_LOCKING
623  fprintf(fp, " %10.2f %12"PRIu64" %12"PRIu64" %10.2f %10.2f %12"PRIu64" %12"PRIu64" %10.2f\n",
624  (float)pd->lock/pd->cnt, (uint64_t)pd->ticks/pd->cnt, pd->contention, (float)pd->contention/pd->cnt, (float)pd->slock/pd->cnt, (uint64_t)pd->sticks/pd->cnt, pd->scontention, (float)pd->scontention/pd->cnt);
625 #else
626  fprintf(fp, "\n");
627 #endif
628  }
629  }
630 
631  for (int m = 0; m < TMM_SIZE; m++) {
633  continue;
634 
635  for (int p = 0; p < 257; p++) {
637  if (pd->cnt == 0) {
638  continue;
639  }
640 
641  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
642  double percent = (long double)pd->tot /
643  (long double)total * 100;
644 
645  fprintf(fp, "%-24s IPv6 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %6.2f\n",
646  TmModuleTmmIdToString(m), p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
647  }
648  }
649 
650  fprintf(fp, "\nLogger/output stats:\n");
651 
652  total = 0;
653  for (int m = 0; m < LOGGER_SIZE; m++) {
654  for (int p = 0; p < 256; p++) {
656  total += pd->tot;
657  pd = &packet_profile_log_data6[m][p];
658  total += pd->tot;
659  }
660  }
661 
662  fprintf(fp, "\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
663  "Logger", "IP ver", "Proto", "cnt", "min", "max", "avg", "tot");
664  fprintf(fp, "%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
665  "------------------------", "------", "-----", "----------", "------------", "------------", "-----------", "-----------");
666  for (int m = 0; m < LOGGER_SIZE; m++) {
667  for (int p = 0; p < 256; p++) {
669  if (pd->cnt == 0) {
670  continue;
671  }
672 
673  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
674  double percent = (long double)pd->tot /
675  (long double)total * 100;
676 
677  fprintf(fp,
678  "%-24s IPv4 %3d %12" PRIu64 " %12" PRIu64 " %12" PRIu64
679  " %12" PRIu64 " %12s %-6.2f\n",
680  PacketProfileLoggerIdToString(m), p, pd->cnt, pd->min, pd->max,
681  (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
682  }
683  }
684  for (int m = 0; m < LOGGER_SIZE; m++) {
685  for (int p = 0; p < 256; p++) {
687  if (pd->cnt == 0) {
688  continue;
689  }
690 
691  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
692  double percent = (long double)pd->tot /
693  (long double)total * 100;
694 
695  fprintf(fp,
696  "%-24s IPv6 %3d %12" PRIu64 " %12" PRIu64 " %12" PRIu64
697  " %12" PRIu64 " %12s %-6.2f\n",
698  PacketProfileLoggerIdToString(m), p, pd->cnt, pd->min, pd->max,
699  (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
700  }
701  }
702 
703  fprintf(fp, "\nGeneral detection engine stats:\n");
704 
705  total = 0;
706  for (int m = 0; m < PROF_DETECT_SIZE; m++) {
707  for (int p = 0; p < 257; p++) {
709  total += pd->tot;
710  pd = &packet_profile_detect_data6[m][p];
711  total += pd->tot;
712  }
713  }
714 
715  fprintf(fp, "\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
716  "Detection phase", "IP ver", "Proto", "cnt", "min", "max", "avg", "tot");
717  fprintf(fp, "%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
718  "------------------------", "------", "-----", "----------", "------------", "------------", "-----------", "-----------");
719  for (int m = 0; m < PROF_DETECT_SIZE; m++) {
720  for (int p = 0; p < 257; p++) {
722  if (pd->cnt == 0) {
723  continue;
724  }
725 
726  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
727  double percent = (long double)pd->tot /
728  (long double)total * 100;
729 
730  fprintf(fp, "%-24s IPv4 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %-6.2f\n",
731  PacketProfileDetectIdToString(m), p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
732  }
733  }
734  for (int m = 0; m < PROF_DETECT_SIZE; m++) {
735  for (int p = 0; p < 257; p++) {
737  if (pd->cnt == 0) {
738  continue;
739  }
740 
741  FormatNumber(pd->tot, totalstr, sizeof(totalstr));
742  double percent = (long double)pd->tot /
743  (long double)total * 100;
744 
745  fprintf(fp, "%-24s IPv6 %3d %12"PRIu64" %12"PRIu64" %12"PRIu64" %12"PRIu64" %12s %-6.2f\n",
746  PacketProfileDetectIdToString(m), p, pd->cnt, pd->min, pd->max, (uint64_t)(pd->tot / pd->cnt), totalstr, percent);
747  }
748  }
749  fclose(fp);
750 }
751 
752 static void PrintCSVHeader(void)
753 {
754  fprintf(packet_profile_csv_fp, "pcap_cnt,total,receive,decode,flowworker,");
755  fprintf(packet_profile_csv_fp, "threading,");
756  fprintf(packet_profile_csv_fp, "proto detect,");
757 
758  for (enum ProfileFlowWorkerId fwi = 0; fwi < PROFILE_FLOWWORKER_SIZE; fwi++) {
759  fprintf(packet_profile_csv_fp, "%s,", ProfileFlowWorkerIdToString(fwi));
760  }
761  fprintf(packet_profile_csv_fp, "loggers,");
762 
763  /* detect stages */
764  for (int i = 0; i < PROF_DETECT_SIZE; i++) {
765  fprintf(packet_profile_csv_fp, "%s,", PacketProfileDetectIdToString(i));
766  }
767 
768  /* individual loggers */
769  for (LoggerId i = 0; i < LOGGER_SIZE; i++) {
770  fprintf(packet_profile_csv_fp, "%s,", PacketProfileLoggerIdToString(i));
771  }
772 
773  fprintf(packet_profile_csv_fp, "\n");
774 }
775 
777 {
778  if (profiling_packets_csv_enabled == 0 || p == NULL ||
779  packet_profile_csv_fp == NULL || p->profile == NULL) {
780  return;
781  }
782 
783  uint64_t tmm_total = 0;
784  uint64_t receive = 0;
785  uint64_t decode = 0;
786 
787  /* total cost from acquisition to return to packetpool */
788  uint64_t delta = p->profile->ticks_end - p->profile->ticks_start;
789  fprintf(packet_profile_csv_fp, "%"PRIu64",%"PRIu64",",
790  p->pcap_cnt, delta);
791 
792  for (int i = 0; i < TMM_SIZE; i++) {
793  const PktProfilingTmmData *pdt = &p->profile->tmm[i];
794  uint64_t tmm_delta = pdt->ticks_end - pdt->ticks_start;
795 
797  if (tmm_delta) {
798  receive = tmm_delta;
799  }
800  continue;
801 
802  } else if (tmm_modules[i].flags & TM_FLAG_DECODE_TM) {
803  if (tmm_delta) {
804  decode = tmm_delta;
805  }
806  continue;
807  }
808 
809  tmm_total += tmm_delta;
810  }
811  fprintf(packet_profile_csv_fp, "%"PRIu64",", receive);
812  fprintf(packet_profile_csv_fp, "%"PRIu64",", decode);
814  fprintf(packet_profile_csv_fp, "%"PRIu64",", fw_pdt->ticks_end - fw_pdt->ticks_start);
815  fprintf(packet_profile_csv_fp, "%"PRIu64",", delta - tmm_total);
816 
817  /* count ticks for app layer */
818  uint64_t app_total = 0;
819  for (AppProto i = 1; i < ALPROTO_FAILED; i++) {
820  const PktProfilingAppData *pdt = &p->profile->app[i];
821 
822  if (p->proto == IPPROTO_TCP) {
823  app_total += pdt->ticks_spent;
824  }
825  }
826 
827  fprintf(packet_profile_csv_fp, "%"PRIu64",", p->profile->proto_detect);
828 
829  /* print flowworker steps */
830  for (enum ProfileFlowWorkerId fwi = 0; fwi < PROFILE_FLOWWORKER_SIZE; fwi++) {
831  const PktProfilingData *pd = &p->profile->flowworker[fwi];
832  uint64_t ticks_spent = pd->ticks_end - pd->ticks_start;
833  if (fwi == PROFILE_FLOWWORKER_STREAM) {
834  ticks_spent -= app_total;
835  } else if (fwi == PROFILE_FLOWWORKER_APPLAYERUDP && app_total) {
836  ticks_spent = app_total;
837  }
838 
839  fprintf(packet_profile_csv_fp, "%"PRIu64",", ticks_spent);
840  }
841 
842  /* count loggers cost and print as a single cost */
843  uint64_t loggers = 0;
844  for (LoggerId i = 0; i < LOGGER_SIZE; i++) {
845  const PktProfilingLoggerData *pd = &p->profile->logger[i];
846  loggers += pd->ticks_spent;
847  }
848  fprintf(packet_profile_csv_fp, "%"PRIu64",", loggers);
849 
850  /* detect steps */
851  for (int i = 0; i < PROF_DETECT_SIZE; i++) {
852  const PktProfilingDetectData *pdt = &p->profile->detect[i];
853 
854  fprintf(packet_profile_csv_fp,"%"PRIu64",", pdt->ticks_spent);
855  }
856 
857  /* print individual loggers */
858  for (LoggerId i = 0; i < LOGGER_SIZE; i++) {
859  const PktProfilingLoggerData *pd = &p->profile->logger[i];
860  fprintf(packet_profile_csv_fp, "%"PRIu64",", pd->ticks_spent);
861  }
862 
863  fprintf(packet_profile_csv_fp,"\n");
864 }
865 
866 static void SCProfilingUpdatePacketDetectRecord(PacketProfileDetectId id, uint8_t ipproto, PktProfilingDetectData *pdt, int ipver)
867 {
868  if (pdt == NULL) {
869  return;
870  }
871 
873  if (ipver == 4)
874  pd = &packet_profile_detect_data4[id][ipproto];
875  else
876  pd = &packet_profile_detect_data6[id][ipproto];
877 
878  if (pd->min == 0 || pdt->ticks_spent < pd->min) {
879  pd->min = pdt->ticks_spent;
880  }
881  if (pd->max < pdt->ticks_spent) {
882  pd->max = pdt->ticks_spent;
883  }
884 
885  pd->tot += pdt->ticks_spent;
886  pd->cnt ++;
887 }
888 
889 static void SCProfilingUpdatePacketDetectRecords(Packet *p)
890 {
892  for (i = 0; i < PROF_DETECT_SIZE; i++) {
893  PktProfilingDetectData *pdt = &p->profile->detect[i];
894 
895  if (pdt->ticks_spent > 0) {
896  if (PacketIsIPv4(p)) {
897  SCProfilingUpdatePacketDetectRecord(i, p->proto, pdt, 4);
898  } else {
899  SCProfilingUpdatePacketDetectRecord(i, p->proto, pdt, 6);
900  }
901  }
902  }
903 }
904 
905 static void SCProfilingUpdatePacketAppPdRecord(uint8_t ipproto, uint32_t ticks_spent, int ipver)
906 {
908  if (ipver == 4)
909  pd = &packet_profile_app_pd_data4[ipproto];
910  else
911  pd = &packet_profile_app_pd_data6[ipproto];
912 
913  if (pd->min == 0 || ticks_spent < pd->min) {
914  pd->min = ticks_spent;
915  }
916  if (pd->max < ticks_spent) {
917  pd->max = ticks_spent;
918  }
919 
920  pd->tot += ticks_spent;
921  pd->cnt ++;
922 }
923 
924 static void SCProfilingUpdatePacketAppRecord(int alproto, uint8_t ipproto, PktProfilingAppData *pdt, int ipver)
925 {
926  if (pdt == NULL) {
927  return;
928  }
929 
931  if (ipver == 4)
932  pd = &packet_profile_app_data4[alproto][ipproto];
933  else
934  pd = &packet_profile_app_data6[alproto][ipproto];
935 
936  if (pd->min == 0 || pdt->ticks_spent < pd->min) {
937  pd->min = pdt->ticks_spent;
938  }
939  if (pd->max < pdt->ticks_spent) {
940  pd->max = pdt->ticks_spent;
941  }
942 
943  pd->tot += pdt->ticks_spent;
944  pd->cnt ++;
945 }
946 
947 static void SCProfilingUpdatePacketAppRecords(Packet *p)
948 {
949  int i;
950  for (i = 0; i < ALPROTO_MAX; i++) {
951  PktProfilingAppData *pdt = &p->profile->app[i];
952 
953  if (pdt->ticks_spent > 0) {
954  if (PacketIsIPv4(p)) {
955  SCProfilingUpdatePacketAppRecord(i, p->proto, pdt, 4);
956  } else {
957  SCProfilingUpdatePacketAppRecord(i, p->proto, pdt, 6);
958  }
959  }
960  }
961 
962  if (p->profile->proto_detect > 0) {
963  if (PacketIsIPv4(p)) {
964  SCProfilingUpdatePacketAppPdRecord(p->proto, p->profile->proto_detect, 4);
965  } else {
966  SCProfilingUpdatePacketAppPdRecord(p->proto, p->profile->proto_detect, 6);
967  }
968  }
969 }
970 
971 static void SCProfilingUpdatePacketTmmRecord(int module, uint8_t proto, PktProfilingTmmData *pdt, int ipver)
972 {
973  if (pdt == NULL) {
974  return;
975  }
976 
978  if (ipver == 4)
979  pd = &packet_profile_tmm_data4[module][proto];
980  else
981  pd = &packet_profile_tmm_data6[module][proto];
982 
983  uint32_t delta = (uint32_t)pdt->ticks_end - pdt->ticks_start;
984  if (pd->min == 0 || delta < pd->min) {
985  pd->min = delta;
986  }
987  if (pd->max < delta) {
988  pd->max = delta;
989  }
990 
991  pd->tot += (uint64_t)delta;
992  pd->cnt ++;
993 
994 #ifdef PROFILE_LOCKING
995  pd->lock += pdt->mutex_lock_cnt;
996  pd->ticks += pdt->mutex_lock_wait_ticks;
997  pd->contention += pdt->mutex_lock_contention;
998  pd->slock += pdt->spin_lock_cnt;
999  pd->sticks += pdt->spin_lock_wait_ticks;
1000  pd->scontention += pdt->spin_lock_contention;
1001 #endif
1002 }
1003 
1004 static void SCProfilingUpdatePacketTmmRecords(Packet *p)
1005 {
1006  int i;
1007  for (i = 0; i < TMM_SIZE; i++) {
1008  PktProfilingTmmData *pdt = &p->profile->tmm[i];
1009 
1010  if (pdt->ticks_start == 0 || pdt->ticks_end == 0 || pdt->ticks_start > pdt->ticks_end) {
1011  continue;
1012  }
1013 
1014  if (PacketIsIPv4(p)) {
1015  SCProfilingUpdatePacketTmmRecord(i, p->proto, pdt, 4);
1016  } else {
1017  SCProfilingUpdatePacketTmmRecord(i, p->proto, pdt, 6);
1018  }
1019  }
1020 }
1021 
1022 static inline void SCProfilingUpdatePacketGenericRecord(PktProfilingData *pdt,
1023  SCProfilePacketData *pd)
1024 {
1025  if (pdt == NULL || pd == NULL) {
1026  return;
1027  }
1028 
1029  uint64_t delta = pdt->ticks_end - pdt->ticks_start;
1030  if (pd->min == 0 || delta < pd->min) {
1031  pd->min = delta;
1032  }
1033  if (pd->max < delta) {
1034  pd->max = delta;
1035  }
1036 
1037  pd->tot += delta;
1038  pd->cnt ++;
1039 }
1040 
1041 static void SCProfilingUpdatePacketGenericRecords(Packet *p, PktProfilingData *pd,
1042  struct ProfileProtoRecords *records, int size)
1043 {
1044  int i;
1045  for (i = 0; i < size; i++) {
1046  PktProfilingData *pdt = &pd[i];
1047 
1048  if (pdt->ticks_start == 0 || pdt->ticks_end == 0 || pdt->ticks_start > pdt->ticks_end) {
1049  continue;
1050  }
1051 
1052  struct ProfileProtoRecords *r = &records[i];
1053  SCProfilePacketData *store = NULL;
1054 
1055  if (PacketIsIPv4(p)) {
1056  store = &(r->records4[p->proto]);
1057  } else {
1058  store = &(r->records6[p->proto]);
1059  }
1060 
1061  SCProfilingUpdatePacketGenericRecord(pdt, store);
1062  }
1063 }
1064 
1065 static void SCProfilingUpdatePacketLogRecord(LoggerId id,
1066  uint8_t ipproto, PktProfilingLoggerData *pdt, int ipver)
1067 {
1068  if (pdt == NULL) {
1069  return;
1070  }
1071 
1072  SCProfilePacketData *pd;
1073  if (ipver == 4)
1074  pd = &packet_profile_log_data4[id][ipproto];
1075  else
1076  pd = &packet_profile_log_data6[id][ipproto];
1077 
1078  if (pd->min == 0 || pdt->ticks_spent < pd->min) {
1079  pd->min = pdt->ticks_spent;
1080  }
1081  if (pd->max < pdt->ticks_spent) {
1082  pd->max = pdt->ticks_spent;
1083  }
1084 
1085  pd->tot += pdt->ticks_spent;
1086  pd->cnt++;
1087 }
1088 
1089 static void SCProfilingUpdatePacketLogRecords(Packet *p)
1090 {
1091  for (LoggerId i = 0; i < LOGGER_SIZE; i++) {
1092  PktProfilingLoggerData *pdt = &p->profile->logger[i];
1093 
1094  if (pdt->ticks_spent > 0) {
1095  if (PacketIsIPv4(p)) {
1096  SCProfilingUpdatePacketLogRecord(i, p->proto, pdt, 4);
1097  } else {
1098  SCProfilingUpdatePacketLogRecord(i, p->proto, pdt, 6);
1099  }
1100  }
1101  }
1102 }
1103 
1105 {
1106  if (p == NULL || p->profile == NULL ||
1107  p->profile->ticks_start == 0 || p->profile->ticks_end == 0 ||
1109  return;
1110 
1111  pthread_mutex_lock(&packet_profile_lock);
1112  {
1113 
1114  if (PacketIsIPv4(p)) {
1116 
1117  uint64_t delta = p->profile->ticks_end - p->profile->ticks_start;
1118  if (pd->min == 0 || delta < pd->min) {
1119  pd->min = delta;
1120  }
1121  if (pd->max < delta) {
1122  pd->max = delta;
1123  }
1124 
1125  pd->tot += delta;
1126  pd->cnt ++;
1127 
1128  if (PacketIsTunnel(p)) {
1129  pd = &packet_profile_data4[256];
1130 
1131  if (pd->min == 0 || delta < pd->min) {
1132  pd->min = delta;
1133  }
1134  if (pd->max < delta) {
1135  pd->max = delta;
1136  }
1137 
1138  pd->tot += delta;
1139  pd->cnt ++;
1140  }
1141 
1142  SCProfilingUpdatePacketGenericRecords(p, p->profile->flowworker,
1144 
1145  SCProfilingUpdatePacketTmmRecords(p);
1146  SCProfilingUpdatePacketAppRecords(p);
1147  SCProfilingUpdatePacketDetectRecords(p);
1148  SCProfilingUpdatePacketLogRecords(p);
1149 
1150  } else if (PacketIsIPv6(p)) {
1152 
1153  uint64_t delta = p->profile->ticks_end - p->profile->ticks_start;
1154  if (pd->min == 0 || delta < pd->min) {
1155  pd->min = delta;
1156  }
1157  if (pd->max < delta) {
1158  pd->max = delta;
1159  }
1160 
1161  pd->tot += delta;
1162  pd->cnt ++;
1163 
1164  if (PacketIsTunnel(p)) {
1165  pd = &packet_profile_data6[256];
1166 
1167  if (pd->min == 0 || delta < pd->min) {
1168  pd->min = delta;
1169  }
1170  if (pd->max < delta) {
1171  pd->max = delta;
1172  }
1173 
1174  pd->tot += delta;
1175  pd->cnt ++;
1176  }
1177 
1178  SCProfilingUpdatePacketGenericRecords(p, p->profile->flowworker,
1180 
1181  SCProfilingUpdatePacketTmmRecords(p);
1182  SCProfilingUpdatePacketAppRecords(p);
1183  SCProfilingUpdatePacketDetectRecords(p);
1184  SCProfilingUpdatePacketLogRecords(p);
1185  }
1186 
1187  if (profiling_packets_csv_enabled)
1189 
1190  }
1191  pthread_mutex_unlock(&packet_profile_lock);
1192 }
1193 
1195 {
1196  uint64_t sample = SC_ATOMIC_ADD(samples, 1);
1197  if (sample % rate == 0)
1198  return SCCalloc(1, sizeof(PktProfiling));
1199  else
1200  return NULL;
1201 }
1202 
1203 /* see if we want to profile rules for this packet */
1205 {
1206 #ifdef PROFILE_LOCKING
1207  if (p->profile != NULL) {
1208  p->flags |= PKT_PROFILE;
1209  return 1;
1210  }
1211 #endif
1212  if (p->flags & PKT_PROFILE) {
1213  return 1;
1214  }
1215 
1216  uint64_t sample = SC_ATOMIC_ADD(samples, 1);
1217  if ((sample % rate) == 0) {
1218  p->flags |= PKT_PROFILE;
1219  return 1;
1220  }
1221  return 0;
1222 }
1223 
1224 #define CASE_CODE(E) case E: return #E
1226 /**
1227  * \brief Maps the PacketProfileDetectId, to its string equivalent
1228  *
1229  * \param id PacketProfileDetectId id
1230  *
1231  * \retval string equivalent for the PacketProfileDetectId id
1232  */
1234 {
1235  switch (id) {
1251  default:
1252  return "UNKNOWN";
1253  }
1254 }
1255 
1256 /**
1257  * \brief Maps the LoggerId's to its string equivalent for profiling output.
1258  *
1259  * \param id LoggerId id
1260  *
1261  * \retval string equivalent for the LoggerId id
1262  */
1264 {
1265  switch (id) {
1291 
1292  case LOGGER_SIZE:
1293  return "UNKNOWN";
1294  }
1295  return "UNKNOWN";
1296 }
1297 
1298 #ifdef UNITTESTS
1299 
1300 static int
1301 ProfilingGenericTicksTest01(void)
1302 {
1303 #define TEST_RUNS 1024
1304  uint64_t ticks_start = 0;
1305  uint64_t ticks_end = 0;
1306  void *ptr[TEST_RUNS];
1307  unsigned int i;
1308 
1309  ticks_start = UtilCpuGetTicks();
1310  for (i = 0; i < TEST_RUNS; i++) {
1311  ptr[i] = SCMalloc(1024);
1312  }
1313  ticks_end = UtilCpuGetTicks();
1314  printf("malloc(1024) %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1315 
1316  ticks_start = UtilCpuGetTicks();
1317  for (i = 0; i < TEST_RUNS; i++) {
1318  SCFree(ptr[i]);
1319  }
1320  ticks_end = UtilCpuGetTicks();
1321  printf("SCFree(1024) %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1322 
1323  SCMutex m[TEST_RUNS];
1324 
1325  ticks_start = UtilCpuGetTicks();
1326  for (i = 0; i < TEST_RUNS; i++) {
1327  SCMutexInit(&m[i], NULL);
1328  }
1329  ticks_end = UtilCpuGetTicks();
1330  printf("SCMutexInit() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1331 
1332  ticks_start = UtilCpuGetTicks();
1333  for (i = 0; i < TEST_RUNS; i++) {
1334  SCMutexLock(&m[i]);
1335  }
1336  ticks_end = UtilCpuGetTicks();
1337  printf("SCMutexLock() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1338 
1339  ticks_start = UtilCpuGetTicks();
1340  for (i = 0; i < TEST_RUNS; i++) {
1341  SCMutexUnlock(&m[i]);
1342  }
1343  ticks_end = UtilCpuGetTicks();
1344  printf("SCMutexUnlock() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1345 
1346  ticks_start = UtilCpuGetTicks();
1347  for (i = 0; i < TEST_RUNS; i++) {
1348  SCMutexDestroy(&m[i]);
1349  }
1350  ticks_end = UtilCpuGetTicks();
1351  printf("SCMutexDestroy() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1352 
1353  SCSpinlock s[TEST_RUNS];
1354 
1355  ticks_start = UtilCpuGetTicks();
1356  for (i = 0; i < TEST_RUNS; i++) {
1357  SCSpinInit(&s[i], 0);
1358  }
1359  ticks_end = UtilCpuGetTicks();
1360  printf("SCSpinInit() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1361 
1362  ticks_start = UtilCpuGetTicks();
1363  for (i = 0; i < TEST_RUNS; i++) {
1364  SCSpinLock(&s[i]);
1365  }
1366  ticks_end = UtilCpuGetTicks();
1367  printf("SCSpinLock() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1368 
1369  ticks_start = UtilCpuGetTicks();
1370  for (i = 0; i < TEST_RUNS; i++) {
1371  SCSpinUnlock(&s[i]);
1372  }
1373  ticks_end = UtilCpuGetTicks();
1374  printf("SCSpinUnlock() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1375 
1376  ticks_start = UtilCpuGetTicks();
1377  for (i = 0; i < TEST_RUNS; i++) {
1378  SCSpinDestroy(&s[i]);
1379  }
1380  ticks_end = UtilCpuGetTicks();
1381  printf("SCSpinDestroy() %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1382 
1383  SC_ATOMIC_DECL_AND_INIT(unsigned int, test);
1384  ticks_start = UtilCpuGetTicks();
1385  for (i = 0; i < TEST_RUNS; i++) {
1386  (void) SC_ATOMIC_ADD(test,1);
1387  }
1388  ticks_end = UtilCpuGetTicks();
1389  printf("SC_ATOMIC_ADD %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1390 
1391  ticks_start = UtilCpuGetTicks();
1392  for (i = 0; i < TEST_RUNS; i++) {
1393  SC_ATOMIC_CAS(&test,i,i+1);
1394  }
1395  ticks_end = UtilCpuGetTicks();
1396  printf("SC_ATOMIC_CAS %"PRIu64"\n", (ticks_end - ticks_start)/TEST_RUNS);
1397  return 1;
1398 }
1399 
1400 #endif /* UNITTESTS */
1401 
1402 void
1404 {
1405 #ifdef UNITTESTS
1406  UtRegisterTest("ProfilingGenericTicksTest01", ProfilingGenericTicksTest01);
1407 #endif /* UNITTESTS */
1408 }
1409 
1411 {
1412 }
1413 
1415 {
1416 }
1417 
1418 #elif PROFILE_RULES
1419 
1420 thread_local int profiling_rules_entered = 0;
1421 int profiling_output_to_file = 0;
1422 static SC_ATOMIC_DECLARE(uint64_t, samples);
1423 static uint64_t rate = 0;
1424 static SC_ATOMIC_DECLARE(bool, profiling_rules_active);
1425 
1426 /**
1427  * \brief Initialize profiling.
1428  */
1429 void SCProfilingInit(void)
1430 {
1431  SC_ATOMIC_INIT(profiling_rules_active);
1432  SC_ATOMIC_INIT(samples);
1433  intmax_t rate_v = 0;
1434 
1435  (void)ConfGetInt("profiling.sample-rate", &rate_v);
1436  if (rate_v > 0 && rate_v < INT_MAX) {
1437  int literal_rate = (int)rate_v;
1438  for (int i = literal_rate; i >= 1; i--) {
1439  /* If i is a power of 2 */
1440  if ((i & (i - 1)) == 0) {
1441  rate = i - 1;
1442  break;
1443  }
1444  }
1445  if (rate != 0)
1446  SCLogInfo("profiling runs for every %luth packet", rate + 1);
1447  else
1448  SCLogInfo("profiling runs for every packet");
1449  }
1450 }
1451 
1452 /* see if we want to profile rules for this packet */
1453 int SCProfileRuleStart(Packet *p)
1454 {
1455  /* Move first so we'll always finish even if dynamically disabled */
1456  if (p->flags & PKT_PROFILE)
1457  return 1;
1458 
1459  if (!SC_ATOMIC_GET(profiling_rules_active)) {
1460  return 0;
1461  }
1462 
1463  uint64_t sample = SC_ATOMIC_ADD(samples, 1);
1464  if ((sample & rate) == 0) {
1465  p->flags |= PKT_PROFILE;
1466  return 1;
1467  }
1468 
1469  return 0;
1470 }
1471 
1473 {
1474  SC_ATOMIC_SET(profiling_rules_active, true);
1475 }
1476 
1477 void SCProfileRuleStopCollection(void)
1478 {
1479  SC_ATOMIC_SET(profiling_rules_active, false);
1480 }
1481 
1482 #endif /* PROFILING */
SCProfilePacketData
struct SCProfilePacketData_ SCProfilePacketData
util-byte.h
tm-threads.h
ConfGetInt
int ConfGetInt(const char *name, intmax_t *val)
Retrieve a configuration value as an integer.
Definition: conf.c:399
Packet_::proto
uint8_t proto
Definition: decode.h:504
PROF_DETECT_GETSGH
@ PROF_DETECT_GETSGH
Definition: suricata-common.h:441
SCSpinDestroy
#define SCSpinDestroy
Definition: threads-debug.h:239
PktProfilingData_::ticks_end
uint64_t ticks_end
Definition: decode.h:332
ConfNodeChildValueIsTrue
int ConfNodeChildValueIsTrue(const ConfNode *node, const char *key)
Test if a configuration node has a true value.
Definition: conf.c:859
LockRecordInitHash
int LockRecordInitHash(void)
profiling_locks_file_mode
const char * profiling_locks_file_mode
SC_ATOMIC_INIT
#define SC_ATOMIC_INIT(name)
wrapper for initializing an atomic variable.
Definition: util-atomic.h:314
PktProfiling_
Per pkt stats storage.
Definition: decode.h:352
TmModuleTmmIdToString
const char * TmModuleTmmIdToString(TmmId id)
Maps the TmmId, to its string equivalent.
Definition: tm-modules.c:193
unlikely
#define unlikely(expr)
Definition: util-optimize.h:35
SC_ATOMIC_SET
#define SC_ATOMIC_SET(name, val)
Set the value for the atomic variable.
Definition: util-atomic.h:386
PktProfilingTmmData_
Per TMM stats storage.
Definition: decode.h:311
SCProfilePacketData_::max
uint64_t max
Definition: util-profiling.c:57
PROF_DETECT_PF_PAYLOAD
@ PROF_DETECT_PF_PAYLOAD
Definition: suricata-common.h:446
ProfileFlowWorkerIdToString
const char * ProfileFlowWorkerIdToString(enum ProfileFlowWorkerId fwi)
Definition: flow-worker.c:698
UtRegisterTest
void UtRegisterTest(const char *name, int(*TestFn)(void))
Register unit test.
Definition: util-unittest.c:103
LOGGER_ALERT_SYSLOG
@ LOGGER_ALERT_SYSLOG
Definition: suricata-common.h:478
packet_profile_flowworker_data
struct ProfileProtoRecords packet_profile_flowworker_data[PROFILE_FLOWWORKER_SIZE]
Definition: util-profiling.c:94
LOGGER_FILEDATA
@ LOGGER_FILEDATA
Definition: suricata-common.h:469
LOGGER_JSON_STATS
@ LOGGER_JSON_STATS
Definition: suricata-common.h:488
SCProfileRuleStopCollection
void SCProfileRuleStopCollection(void)
Definition: util-profiling.c:1414
Packet_::pcap_cnt
uint64_t pcap_cnt
Definition: decode.h:609
PktProfiling_::ticks_end
uint64_t ticks_end
Definition: decode.h:354
AppProto
uint16_t AppProto
Definition: app-layer-protos.h:82
Packet_::flags
uint32_t flags
Definition: decode.h:519
ConfGetNode
ConfNode * ConfGetNode(const char *name)
Get a ConfNode by name.
Definition: conf.c:181
LOGGER_JSON_ALERT
@ LOGGER_JSON_ALERT
Definition: suricata-common.h:479
ProfileProtoRecords
Definition: util-profiling.c:89
LOGGER_JSON_ARP
@ LOGGER_JSON_ARP
Definition: suricata-common.h:494
PROF_DETECT_ALERT
@ PROF_DETECT_ALERT
Definition: suricata-common.h:452
LoggerId
LoggerId
Definition: suricata-common.h:460
AppProtoToString
const char * AppProtoToString(AppProto alproto)
Maps the ALPROTO_*, to its string equivalent.
Definition: app-layer-protos.c:76
SC_ATOMIC_ADD
#define SC_ATOMIC_ADD(name, val)
add a value to our atomic variable
Definition: util-atomic.h:332
PROF_DETECT_SIZE
@ PROF_DETECT_SIZE
Definition: suricata-common.h:456
packet_profile_data6
SCProfilePacketData packet_profile_data6[257]
Definition: util-profiling.c:71
PktProfilingTmmData_::ticks_end
uint64_t ticks_end
Definition: decode.h:313
PROF_DETECT_PF_TX
@ PROF_DETECT_PF_TX
Definition: suricata-common.h:447
SC_ATOMIC_CAS
#define SC_ATOMIC_CAS(name, cmpval, newval)
atomic Compare and Switch
Definition: util-atomic.h:367
PROF_DETECT_CLEANUP
@ PROF_DETECT_CLEANUP
Definition: suricata-common.h:454
SCMutexLock
#define SCMutexLock(mut)
Definition: threads-debug.h:117
SCSpinLock
#define SCSpinLock
Definition: threads-debug.h:235
packet_profile_log_data6
SCProfilePacketData packet_profile_log_data6[LOGGER_SIZE][256]
Definition: util-profiling.c:87
SCProfileRuleStart
int SCProfileRuleStart(Packet *p)
Definition: util-profiling.c:1204
SCProfilingAddPacket
void SCProfilingAddPacket(Packet *p)
Definition: util-profiling.c:1104
packet_profile_app_pd_data4
SCProfilePacketData packet_profile_app_pd_data4[257]
Definition: util-profiling.c:80
proto
uint8_t proto
Definition: decode-template.h:0
m
SCMutex m
Definition: flow-hash.h:6
LOGGER_STATS
@ LOGGER_STATS
Definition: suricata-common.h:487
PROFILE_FLOWWORKER_STREAM
@ PROFILE_FLOWWORKER_STREAM
Definition: flow-worker.h:23
SCProfilingDestroy
void SCProfilingDestroy(void)
Free resources used by profiling.
Definition: util-profiling.c:263
ALPROTO_MAX
@ ALPROTO_MAX
Definition: app-layer-protos.h:77
PktProfiling_::app
PktProfilingAppData app[ALPROTO_MAX]
Definition: decode.h:358
PktProfiling_::ticks_start
uint64_t ticks_start
Definition: decode.h:353
profiling_locks_output_to_file
int profiling_locks_output_to_file
util-unittest.h
TEST_RUNS
#define TEST_RUNS
ConfValIsTrue
int ConfValIsTrue(const char *val)
Check if a value is true.
Definition: conf.c:537
PROF_DETECT_PF_SORT2
@ PROF_DETECT_PF_SORT2
Definition: suricata-common.h:450
PktProfilingAppData_::ticks_spent
uint64_t ticks_spent
Definition: decode.h:342
UtilCpuGetTicks
uint64_t UtilCpuGetTicks(void)
Definition: util-cpu.c:161
PacketProfileLoggerIdToString
const char * PacketProfileLoggerIdToString(LoggerId id)
Maps the LoggerId's to its string equivalent for profiling output.
Definition: util-profiling.c:1263
PROF_DETECT_PF_SORT1
@ PROF_DETECT_PF_SORT1
Definition: suricata-common.h:449
PROF_DETECT_TX_UPDATE
@ PROF_DETECT_TX_UPDATE
Definition: suricata-common.h:453
Packet_::profile
PktProfiling * profile
Definition: decode.h:656
LOGGER_JSON_FLOW
@ LOGGER_JSON_FLOW
Definition: suricata-common.h:485
LOGGER_HTTP
@ LOGGER_HTTP
Definition: suricata-common.h:464
lock
HRLOCK_TYPE lock
Definition: host.h:0
SCProfilingPrintPacketProfile
void SCProfilingPrintPacketProfile(Packet *p)
Definition: util-profiling.c:776
ProfileProtoRecords::records4
SCProfilePacketData records4[257]
Definition: util-profiling.c:90
packet_profile_tmm_data6
SCProfilePacketData packet_profile_tmm_data6[TMM_SIZE][257]
Definition: util-profiling.c:75
packet_profile_detect_data4
SCProfilePacketData packet_profile_detect_data4[PROF_DETECT_SIZE][257]
Definition: util-profiling.c:83
LOGGER_TCP_DATA
@ LOGGER_TCP_DATA
Definition: suricata-common.h:484
packet_profile_tmm_data4
SCProfilePacketData packet_profile_tmm_data4[TMM_SIZE][257]
Definition: util-profiling.c:74
ProfileProtoRecords::records6
SCProfilePacketData records6[257]
Definition: util-profiling.c:91
SCProfileRuleStartCollection
void SCProfileRuleStartCollection(void)
Definition: util-profiling.c:1410
LOGGER_JSON_FILE
@ LOGGER_JSON_FILE
Definition: suricata-common.h:483
packet_profile_app_data6
SCProfilePacketData packet_profile_app_data6[TMM_SIZE][257]
Definition: util-profiling.c:78
PacketProfileDetectId
enum PacketProfileDetectId_ PacketProfileDetectId
SCMutexUnlock
#define SCMutexUnlock(mut)
Definition: threads-debug.h:119
ProfileFlowWorkerId
ProfileFlowWorkerId
Definition: flow-worker.h:21
PROF_DETECT_PF_PKT
@ PROF_DETECT_PF_PKT
Definition: suricata-common.h:445
LOGGER_UNDEFINED
@ LOGGER_UNDEFINED
Definition: suricata-common.h:461
PktProfilingData_
Definition: decode.h:330
packet_profile_log_data4
SCProfilePacketData packet_profile_log_data4[LOGGER_SIZE][256]
Definition: util-profiling.c:86
PktProfiling_::logger
PktProfilingLoggerData logger[LOGGER_SIZE]
Definition: decode.h:360
SCSpinUnlock
#define SCSpinUnlock
Definition: threads-debug.h:237
PROFILE_FLOWWORKER_APPLAYERUDP
@ PROFILE_FLOWWORKER_APPLAYERUDP
Definition: flow-worker.h:24
PktProfilingDetectData_
Definition: decode.h:335
SCLogWarning
#define SCLogWarning(...)
Macro used to log WARNING messages.
Definition: util-debug.h:249
LOGGER_TLS
@ LOGGER_TLS
Definition: suricata-common.h:466
util-profiling.h
LOGGER_SIZE
@ LOGGER_SIZE
Definition: suricata-common.h:493
SC_ATOMIC_DECLARE
#define SC_ATOMIC_DECLARE(type, name)
wrapper for declaring atomic variables.
Definition: util-atomic.h:280
SCProfilePacketData_
Definition: util-profiling.c:55
profiling_packets_enabled
int profiling_packets_enabled
Definition: util-profiling.c:96
packet_profile_app_pd_data6
SCProfilePacketData packet_profile_app_pd_data6[257]
Definition: util-profiling.c:81
Packet_
Definition: decode.h:482
LOGGER_JSON_NETFLOW
@ LOGGER_JSON_NETFLOW
Definition: suricata-common.h:486
TM_FLAG_DECODE_TM
#define TM_FLAG_DECODE_TM
Definition: tm-modules.h:33
tmm_modules
TmModule tmm_modules[TMM_SIZE]
Definition: tm-modules.c:33
conf.h
TMM_SIZE
@ TMM_SIZE
Definition: tm-threads-common.h:79
PROF_DETECT_IPONLY
@ PROF_DETECT_IPONLY
Definition: suricata-common.h:442
TM_FLAG_LOGAPI_TM
#define TM_FLAG_LOGAPI_TM
Definition: tm-modules.h:36
SCLogInfo
#define SCLogInfo(...)
Macro used to log INFORMATIONAL messages.
Definition: util-debug.h:224
PacketProfileDetectIdToString
const char * PacketProfileDetectIdToString(PacketProfileDetectId id)
Maps the PacketProfileDetectId, to its string equivalent.
Definition: util-profiling.c:1233
SCMutexInit
#define SCMutexInit(mut, mutattrs)
Definition: threads-debug.h:116
TM_FLAG_RECEIVE_TM
#define TM_FLAG_RECEIVE_TM
Definition: tm-modules.h:32
PktProfilingData_::ticks_start
uint64_t ticks_start
Definition: decode.h:331
SCProfilePacketData_::tot
uint64_t tot
Definition: util-profiling.c:58
TMM_FLOWWORKER
@ TMM_FLOWWORKER
Definition: tm-threads-common.h:34
PktProfiling_::detect
PktProfilingDetectData detect[PROF_DETECT_SIZE]
Definition: decode.h:359
util-conf.h
LOGGER_PCAP
@ LOGGER_PCAP
Definition: suricata-common.h:489
LOGGER_JSON_METADATA
@ LOGGER_JSON_METADATA
Definition: suricata-common.h:490
flags
uint8_t flags
Definition: decode-gre.h:0
suricata-common.h
SC_ATOMIC_DECL_AND_INIT
#define SC_ATOMIC_DECL_AND_INIT(type, name)
wrapper for declaring an atomic variable and initializing it.
Definition: util-atomic.h:308
PROF_DETECT_PF_RECORD
@ PROF_DETECT_PF_RECORD
Definition: suricata-common.h:448
PROFILE_FLOWWORKER_SIZE
@ PROFILE_FLOWWORKER_SIZE
Definition: flow-worker.h:29
LOGGER_JSON_DROP
@ LOGGER_JSON_DROP
Definition: suricata-common.h:481
SCLogPerf
#define SCLogPerf(...)
Definition: util-debug.h:230
PROF_DETECT_SETUP
@ PROF_DETECT_SETUP
Definition: suricata-common.h:440
LOGGER_ALERT_DEBUG
@ LOGGER_ALERT_DEBUG
Definition: suricata-common.h:476
FatalError
#define FatalError(...)
Definition: util-debug.h:502
SCProfilingDump
void SCProfilingDump(void)
Definition: util-profiling.c:289
packet_profile_app_data4
SCProfilePacketData packet_profile_app_data4[TMM_SIZE][257]
Definition: util-profiling.c:77
packet_profile_detect_data6
SCProfilePacketData packet_profile_detect_data6[PROF_DETECT_SIZE][257]
Definition: util-profiling.c:84
SCSpinInit
#define SCSpinInit
Definition: threads-debug.h:238
LOGGER_FILE
@ LOGGER_FILE
Definition: suricata-common.h:468
SCMalloc
#define SCMalloc(sz)
Definition: util-mem.h:47
ConfigGetLogDirectory
const char * ConfigGetLogDirectory(void)
Definition: util-conf.c:38
PROF_DETECT_RULES
@ PROF_DETECT_RULES
Definition: suricata-common.h:443
LOGGER_JSON_TX
@ LOGGER_JSON_TX
Definition: suricata-common.h:467
PROF_DETECT_NONMPMLIST
@ PROF_DETECT_NONMPMLIST
Definition: suricata-common.h:451
str
#define str(s)
Definition: suricata-common.h:291
SCLogError
#define SCLogError(...)
Macro used to log ERROR messages.
Definition: util-debug.h:261
SCFree
#define SCFree(p)
Definition: util-mem.h:61
ConfNode_
Definition: conf.h:32
packet_profile_data4
SCProfilePacketData packet_profile_data4[257]
Definition: util-profiling.c:70
profiling_locks_file_name
char * profiling_locks_file_name
PktProfilingLoggerData_
Definition: decode.h:345
PktProfiling_::tmm
PktProfilingTmmData tmm[TMM_SIZE]
Definition: decode.h:356
PKT_PROFILE
#define PKT_PROFILE
Definition: decode.h:1303
LockRecordFreeHash
void LockRecordFreeHash(void)
ALPROTO_FAILED
@ ALPROTO_FAILED
Definition: app-layer-protos.h:72
SCSpinlock
#define SCSpinlock
Definition: threads-debug.h:234
LOGGER_FILE_STORE
@ LOGGER_FILE_STORE
Definition: suricata-common.h:482
SCProfilePacketData_::min
uint64_t min
Definition: util-profiling.c:56
LOGGER_JSON_FRAME
@ LOGGER_JSON_FRAME
Definition: suricata-common.h:491
profiling_output_to_file
int profiling_output_to_file
Definition: util-profiling.c:97
SCProfilingDumpPacketStats
void SCProfilingDumpPacketStats(void)
Definition: util-profiling.c:344
PROF_DETECT_TX
@ PROF_DETECT_TX
Definition: suricata-common.h:444
PktProfilingTmmData_::ticks_start
uint64_t ticks_start
Definition: decode.h:312
LOGGER_TLS_STORE
@ LOGGER_TLS_STORE
Definition: suricata-common.h:465
PktProfilingLoggerData_::ticks_spent
uint64_t ticks_spent
Definition: decode.h:348
SCProfilingRegisterTests
void SCProfilingRegisterTests(void)
Definition: util-profiling.c:1403
SCProfilePacketData_::cnt
uint64_t cnt
Definition: util-profiling.c:59
SC_ATOMIC_GET
#define SC_ATOMIC_GET(name)
Get the value from the atomic variable.
Definition: util-atomic.h:375
CASE_CODE
#define CASE_CODE(E)
Definition: util-profiling.c:1224
PktProfiling_::flowworker
PktProfilingData flowworker[PROFILE_FLOWWORKER_SIZE]
Definition: decode.h:357
util-profiling-locks.h
PktProfilingAppData_
Definition: decode.h:341
SCCalloc
#define SCCalloc(nm, sz)
Definition: util-mem.h:53
LOGGER_JSON_STREAM
@ LOGGER_JSON_STREAM
Definition: suricata-common.h:492
SCMutexDestroy
#define SCMutexDestroy
Definition: threads-debug.h:120
PktProfiling_::proto_detect
uint64_t proto_detect
Definition: decode.h:361
profiling_rules_entered
thread_local int profiling_rules_entered
Definition: util-profiling.c:112
LOGGER_ALERT_FAST
@ LOGGER_ALERT_FAST
Definition: suricata-common.h:477
SCMutex
#define SCMutex
Definition: threads-debug.h:114
SCProfilingInit
void SCProfilingInit(void)
Initialize profiling.
Definition: util-profiling.c:135
SCProfilePacketStart
PktProfiling * SCProfilePacketStart(void)
Definition: util-profiling.c:1194
PktProfilingDetectData_::ticks_spent
uint64_t ticks_spent
Definition: decode.h:338
profiling_locks_enabled
int profiling_locks_enabled
LOGGER_JSON_ANOMALY
@ LOGGER_JSON_ANOMALY
Definition: suricata-common.h:480
ConfNodeLookupChildValue
const char * ConfNodeLookupChildValue(const ConfNode *node, const char *name)
Lookup the value of a child configuration node by name.
Definition: conf.c:814