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