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