41 #define MIN(a, b) (((a) < (b)) ? (a) : (b))
44 #define DEFAULT_LOG_FILENAME "profile.log"
45 #define DEFAULT_LOG_MODE_APPEND "yes"
47 static pthread_mutex_t packet_profile_lock;
48 static FILE *packet_profile_csv_fp = NULL;
60 #ifdef PROFILE_LOCKING
99 static int profiling_packets_csv_enabled = 0;
100 static int profiling_packets_output_to_file = 0;
101 static char *profiling_file_name;
102 static char profiling_packets_file_name[PATH_MAX];
103 static char *profiling_csv_file_name;
104 static const char *profiling_packets_file_mode =
"a";
117 static void PrintCSVHeader(
void);
119 static void FormatNumber(uint64_t num,
char *
str,
size_t size)
122 snprintf(
str, size,
"%"PRIu64, num);
123 else if (num < 1000000UL)
124 snprintf(
str, size,
"%3.1fk", (
float)num/1000UL);
125 else if (num < 1000000000UL)
126 snprintf(
str, size,
"%3.1fm", (
float)num/1000000UL);
128 snprintf(
str, size,
"%3.1fb", (
float)num/1000000000UL);
142 (void)
ConfGetInt(
"profiling.sample-rate", &rate_v);
143 if (rate_v > 0 && rate_v < INT_MAX) {
146 SCLogInfo(
"profiling runs for every %dth packet", rate);
148 SCLogInfo(
"profiling runs for every packet");
156 if (pthread_mutex_init(&packet_profile_lock, NULL) != 0) {
157 FatalError(
"Failed to initialize packet profiling mutex.");
174 if (filename != NULL) {
178 snprintf(profiling_packets_file_name,
sizeof(profiling_packets_file_name),
179 "%s/%s", log_dir, filename);
183 profiling_packets_file_mode =
"a";
185 profiling_packets_file_mode =
"w";
188 profiling_packets_output_to_file = 1;
196 if (filename == NULL) {
197 filename =
"packet_profile.csv";
202 profiling_csv_file_name =
SCMalloc(PATH_MAX);
203 if (
unlikely(profiling_csv_file_name == NULL)) {
206 snprintf(profiling_csv_file_name, PATH_MAX,
"%s/%s", log_dir, filename);
208 packet_profile_csv_fp = fopen(profiling_csv_file_name,
"w");
209 if (packet_profile_csv_fp == NULL) {
210 SCFree(profiling_csv_file_name);
211 profiling_csv_file_name = NULL;
217 profiling_packets_csv_enabled = 1;
225 #ifndef PROFILE_LOCKING
227 "lock profiling not compiled in. Add --enable-profiling-locks to configure.");
234 if (filename != NULL) {
266 pthread_mutex_destroy(&packet_profile_lock);
269 if (profiling_packets_csv_enabled) {
270 if (packet_profile_csv_fp != NULL)
271 fclose(packet_profile_csv_fp);
272 packet_profile_csv_fp = NULL;
275 if (profiling_csv_file_name != NULL)
276 SCFree(profiling_csv_file_name);
277 profiling_csv_file_name = NULL;
279 if (profiling_file_name != NULL)
280 SCFree(profiling_file_name);
281 profiling_file_name = NULL;
283 #ifdef PROFILE_LOCKING
292 SCLogPerf(
"Done dumping profiling data.");
295 static void DumpFlowWorkerIP(FILE *fp,
int ipv, uint64_t total)
302 for (
int p = 0; p < 257; p++) {
308 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
309 double percent = (
long double)pd->
tot /
310 (
long double)total * 100;
312 fprintf(fp,
"%-20s IPv%d %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
314 pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
319 static void DumpFlowWorker(FILE *fp)
326 for (
int p = 0; p < 257; p++) {
334 fprintf(fp,
"\n%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
335 "Flow Worker",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg");
336 fprintf(fp,
"%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
337 "--------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------");
338 DumpFlowWorkerIP(fp, 4, total);
339 DumpFlowWorkerIP(fp, 6, total);
340 fprintf(fp,
"Note: %s includes app-layer for TCP\n",
353 if (profiling_packets_output_to_file == 1) {
354 fp = fopen(profiling_packets_file_name, profiling_packets_file_mode);
357 SCLogError(
"failed to open %s: %s", profiling_packets_file_name, strerror(errno));
364 fprintf(fp,
"\n\nPacket profile dump:\n");
366 fprintf(fp,
"\n%-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s\n",
367 "IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot",
"%%");
368 fprintf(fp,
"%-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s\n",
369 "------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------",
"---");
371 for (
int i = 0; i < 257; i++) {
378 for (
int i = 0; i < 257; i++) {
384 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
385 double percent = (
long double)pd->
tot /
386 (
long double)total * 100;
388 fprintf(fp,
" IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n", i, pd->
cnt,
389 pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
392 for (
int i = 0; i < 257; i++) {
398 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
399 double percent = (
long double)pd->
tot /
400 (
long double)total * 100;
402 fprintf(fp,
" IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n", i, pd->
cnt,
403 pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
405 fprintf(fp,
"Note: Protocol 256 tracks pseudo/tunnel packets.\n");
407 fprintf(fp,
"\nPer Thread module stats:\n");
409 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
410 "Thread Module",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot",
"%%");
411 #ifdef PROFILE_LOCKING
412 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
413 "locks",
"ticks",
"cont.",
"cont.avg",
"slocks",
"sticks",
"scont.",
"scont.avg");
417 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
418 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------",
"---");
419 #ifdef PROFILE_LOCKING
420 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
421 "--------",
"--------",
"----------",
"-----------",
"--------",
"--------",
"------------",
"-----------");
430 for (
int p = 0; p < 257; p++) {
443 for (
int p = 0; p < 257; p++) {
449 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
450 double percent = (
long double)pd->
tot /
451 (
long double)total * 100;
453 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f",
455 #ifdef PROFILE_LOCKING
456 fprintf(fp,
" %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f\n",
457 (
float)pd->lock/pd->
cnt, (uint64_t)pd->ticks/pd->
cnt, pd->contention, (
float)pd->contention/pd->
cnt, (
float)pd->slock/pd->
cnt, (uint64_t)pd->sticks/pd->
cnt, pd->scontention, (
float)pd->scontention/pd->
cnt);
468 for (
int p = 0; p < 257; p++) {
474 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
475 double percent = (
long double)pd->
tot /
476 (
long double)total * 100;
478 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n",
485 fprintf(fp,
"\nPer App layer parser stats:\n");
487 fprintf(fp,
"\n%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
488 "App Layer",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg");
489 fprintf(fp,
"%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
490 "--------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------");
494 for (
int p = 0; p < 257; p++) {
503 for (
int p = 0; p < 257; p++) {
509 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
510 double percent = (
long double)pd->
tot /
511 (
long double)total * 100;
514 "%-20s IPv4 %3d %12" PRIu64
" %12" PRIu64
" %12" PRIu64
515 " %12" PRIu64
" %12s %-6.2f\n",
517 (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
522 for (
int p = 0; p < 257; p++) {
528 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
529 double percent = (
long double)pd->
tot /
530 (
long double)total * 100;
533 "%-20s IPv6 %3d %12" PRIu64
" %12" PRIu64
" %12" PRIu64
534 " %12" PRIu64
" %12s %-6.2f\n",
536 (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
542 for (
int p = 0; p < 257; p++) {
548 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
549 fprintf(fp,
"%-20s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s\n",
550 "Proto detect", p, pd->
cnt, pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr);
553 for (
int p = 0; p < 257; p++) {
559 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
560 fprintf(fp,
"%-20s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s\n",
561 "Proto detect", p, pd->
cnt, pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr);
567 for (
int p = 0; p < 257; p++) {
576 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
577 "Log Thread Module",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot",
"%%");
578 #ifdef PROFILE_LOCKING
579 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
580 "locks",
"ticks",
"cont.",
"cont.avg",
"slocks",
"sticks",
"scont.",
"scont.avg");
584 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
585 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------",
"---");
586 #ifdef PROFILE_LOCKING
587 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
588 "--------",
"--------",
"----------",
"-----------",
"--------",
"--------",
"------------",
"-----------");
597 for (
int p = 0; p < 257; p++) {
610 for (
int p = 0; p < 257; p++) {
616 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
617 double percent = (
long double)pd->
tot /
618 (
long double)total * 100;
620 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f",
622 #ifdef PROFILE_LOCKING
623 fprintf(fp,
" %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f\n",
624 (
float)pd->lock/pd->
cnt, (uint64_t)pd->ticks/pd->
cnt, pd->contention, (
float)pd->contention/pd->
cnt, (
float)pd->slock/pd->
cnt, (uint64_t)pd->sticks/pd->
cnt, pd->scontention, (
float)pd->scontention/pd->
cnt);
635 for (
int p = 0; p < 257; p++) {
641 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
642 double percent = (
long double)pd->
tot /
643 (
long double)total * 100;
645 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n",
650 fprintf(fp,
"\nLogger/output stats:\n");
654 for (
int p = 0; p < 256; p++) {
662 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
663 "Logger",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot");
664 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
665 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------");
667 for (
int p = 0; p < 256; p++) {
673 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
674 double percent = (
long double)pd->
tot /
675 (
long double)total * 100;
677 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
682 for (
int p = 0; p < 256; p++) {
688 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
689 double percent = (
long double)pd->
tot /
690 (
long double)total * 100;
692 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
697 fprintf(fp,
"\nGeneral detection engine stats:\n");
701 for (
int p = 0; p < 257; p++) {
709 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
710 "Detection phase",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot");
711 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
712 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------");
714 for (
int p = 0; p < 257; p++) {
720 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
721 double percent = (
long double)pd->
tot /
722 (
long double)total * 100;
724 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
729 for (
int p = 0; p < 257; p++) {
735 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
736 double percent = (
long double)pd->
tot /
737 (
long double)total * 100;
739 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
746 static void PrintCSVHeader(
void)
748 fprintf(packet_profile_csv_fp,
"pcap_cnt,total,receive,decode,flowworker,");
749 fprintf(packet_profile_csv_fp,
"threading,");
750 fprintf(packet_profile_csv_fp,
"proto detect,");
755 fprintf(packet_profile_csv_fp,
"loggers,");
767 fprintf(packet_profile_csv_fp,
"\n");
772 if (profiling_packets_csv_enabled == 0 || p == NULL ||
773 packet_profile_csv_fp == NULL || p->
profile == NULL) {
777 uint64_t tmm_total = 0;
778 uint64_t receive = 0;
783 fprintf(packet_profile_csv_fp,
"%"PRIu64
",%"PRIu64
",",
786 for (
int i = 0; i <
TMM_SIZE; i++) {
803 tmm_total += tmm_delta;
805 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", receive);
806 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", decode);
809 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", delta - tmm_total);
812 uint64_t app_total = 0;
816 if (p->
proto == IPPROTO_TCP) {
828 ticks_spent -= app_total;
830 ticks_spent = app_total;
833 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", ticks_spent);
837 uint64_t loggers = 0;
842 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", loggers);
848 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", pdt->
ticks_spent);
854 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", pd->
ticks_spent);
857 fprintf(packet_profile_csv_fp,
"\n");
883 static void SCProfilingUpdatePacketDetectRecords(
Packet *p)
891 SCProfilingUpdatePacketDetectRecord(i, p->
proto, pdt, 4);
893 SCProfilingUpdatePacketDetectRecord(i, p->
proto, pdt, 6);
899 static void SCProfilingUpdatePacketAppPdRecord(uint8_t ipproto, uint32_t ticks_spent,
int ipver)
907 if (pd->
min == 0 || ticks_spent < pd->min) {
908 pd->
min = ticks_spent;
910 if (pd->
max < ticks_spent) {
911 pd->
max = ticks_spent;
914 pd->
tot += ticks_spent;
918 static void SCProfilingUpdatePacketAppRecord(
int alproto, uint8_t ipproto,
PktProfilingAppData *pdt,
int ipver)
941 static void SCProfilingUpdatePacketAppRecords(
Packet *p)
949 SCProfilingUpdatePacketAppRecord(i, p->
proto, pdt, 4);
951 SCProfilingUpdatePacketAppRecord(i, p->
proto, pdt, 6);
978 if (pd->
min == 0 || delta < pd->min) {
981 if (pd->
max < delta) {
985 pd->
tot += (uint64_t)delta;
988 #ifdef PROFILE_LOCKING
989 pd->lock += pdt->mutex_lock_cnt;
990 pd->ticks += pdt->mutex_lock_wait_ticks;
991 pd->contention += pdt->mutex_lock_contention;
992 pd->slock += pdt->spin_lock_cnt;
993 pd->sticks += pdt->spin_lock_wait_ticks;
994 pd->scontention += pdt->spin_lock_contention;
998 static void SCProfilingUpdatePacketTmmRecords(
Packet *p)
1009 SCProfilingUpdatePacketTmmRecord(i, p->
proto, pdt, 4);
1011 SCProfilingUpdatePacketTmmRecord(i, p->
proto, pdt, 6);
1016 static inline void SCProfilingUpdatePacketGenericRecord(
PktProfilingData *pdt,
1019 if (pdt == NULL || pd == NULL) {
1024 if (pd->
min == 0 || delta < pd->min) {
1027 if (pd->
max < delta) {
1039 for (i = 0; i < size; i++) {
1055 SCProfilingUpdatePacketGenericRecord(pdt, store);
1059 static void SCProfilingUpdatePacketLogRecord(
LoggerId id,
1083 static void SCProfilingUpdatePacketLogRecords(
Packet *p)
1090 SCProfilingUpdatePacketLogRecord(i, p->
proto, pdt, 4);
1092 SCProfilingUpdatePacketLogRecord(i, p->
proto, pdt, 6);
1100 if (p == NULL || p->
profile == NULL ||
1105 pthread_mutex_lock(&packet_profile_lock);
1112 if (pd->
min == 0 || delta < pd->min) {
1115 if (pd->
max < delta) {
1125 if (pd->
min == 0 || delta < pd->min) {
1128 if (pd->
max < delta) {
1139 SCProfilingUpdatePacketTmmRecords(p);
1140 SCProfilingUpdatePacketAppRecords(p);
1141 SCProfilingUpdatePacketDetectRecords(p);
1142 SCProfilingUpdatePacketLogRecords(p);
1148 if (pd->
min == 0 || delta < pd->min) {
1151 if (pd->
max < delta) {
1161 if (pd->
min == 0 || delta < pd->min) {
1164 if (pd->
max < delta) {
1175 SCProfilingUpdatePacketTmmRecords(p);
1176 SCProfilingUpdatePacketAppRecords(p);
1177 SCProfilingUpdatePacketDetectRecords(p);
1178 SCProfilingUpdatePacketLogRecords(p);
1181 if (profiling_packets_csv_enabled)
1185 pthread_mutex_unlock(&packet_profile_lock);
1191 if (sample % rate == 0)
1200 #ifdef PROFILE_LOCKING
1207 if (sample % rate == 0) {
1217 #define CASE_CODE(E) case E: return #E
1292 ProfilingGenericTicksTest01(
void)
1294 #define TEST_RUNS 1024
1295 uint64_t ticks_start = 0;
1296 uint64_t ticks_end = 0;
1305 printf(
"malloc(1024) %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1312 printf(
"SCFree(1024) %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1321 printf(
"SCMutexInit() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1328 printf(
"SCMutexLock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1335 printf(
"SCMutexUnlock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1342 printf(
"SCMutexDestroy() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1351 printf(
"SCSpinInit() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1358 printf(
"SCSpinLock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1365 printf(
"SCSpinUnlock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1372 printf(
"SCSpinDestroy() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1380 printf(
"SC_ATOMIC_ADD %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1387 printf(
"SC_ATOMIC_CAS %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1397 UtRegisterTest(
"ProfilingGenericTicksTest01", ProfilingGenericTicksTest01);