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;
678 "%-24s IPv4 %3d %12" PRIu64
" %12" PRIu64
" %12" PRIu64
679 " %12" PRIu64
" %12s %-6.2f\n",
681 (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
685 for (
int p = 0; p < 256; p++) {
691 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
692 double percent = (
long double)pd->
tot /
693 (
long double)total * 100;
696 "%-24s IPv6 %3d %12" PRIu64
" %12" PRIu64
" %12" PRIu64
697 " %12" PRIu64
" %12s %-6.2f\n",
699 (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
703 fprintf(fp,
"\nGeneral detection engine stats:\n");
707 for (
int p = 0; p < 257; p++) {
715 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
716 "Detection phase",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot");
717 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
718 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------");
720 for (
int p = 0; p < 257; p++) {
726 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
727 double percent = (
long double)pd->
tot /
728 (
long double)total * 100;
730 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
735 for (
int p = 0; p < 257; p++) {
741 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
742 double percent = (
long double)pd->
tot /
743 (
long double)total * 100;
745 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
752 static void PrintCSVHeader(
void)
754 fprintf(packet_profile_csv_fp,
"pcap_cnt,total,receive,decode,flowworker,");
755 fprintf(packet_profile_csv_fp,
"threading,");
756 fprintf(packet_profile_csv_fp,
"proto detect,");
761 fprintf(packet_profile_csv_fp,
"loggers,");
773 fprintf(packet_profile_csv_fp,
"\n");
778 if (profiling_packets_csv_enabled == 0 || p == NULL ||
779 packet_profile_csv_fp == NULL || p->
profile == NULL) {
783 uint64_t tmm_total = 0;
784 uint64_t receive = 0;
789 fprintf(packet_profile_csv_fp,
"%"PRIu64
",%"PRIu64
",",
792 for (
int i = 0; i <
TMM_SIZE; i++) {
809 tmm_total += tmm_delta;
811 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", receive);
812 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", decode);
815 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", delta - tmm_total);
818 uint64_t app_total = 0;
822 if (p->
proto == IPPROTO_TCP) {
834 ticks_spent -= app_total;
836 ticks_spent = app_total;
839 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", ticks_spent);
843 uint64_t loggers = 0;
848 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", loggers);
854 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", pdt->
ticks_spent);
860 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", pd->
ticks_spent);
863 fprintf(packet_profile_csv_fp,
"\n");
889 static void SCProfilingUpdatePacketDetectRecords(
Packet *p)
897 SCProfilingUpdatePacketDetectRecord(i, p->
proto, pdt, 4);
899 SCProfilingUpdatePacketDetectRecord(i, p->
proto, pdt, 6);
905 static void SCProfilingUpdatePacketAppPdRecord(uint8_t ipproto, uint32_t ticks_spent,
int ipver)
913 if (pd->
min == 0 || ticks_spent < pd->min) {
914 pd->
min = ticks_spent;
916 if (pd->
max < ticks_spent) {
917 pd->
max = ticks_spent;
920 pd->
tot += ticks_spent;
924 static void SCProfilingUpdatePacketAppRecord(
int alproto, uint8_t ipproto,
PktProfilingAppData *pdt,
int ipver)
947 static void SCProfilingUpdatePacketAppRecords(
Packet *p)
955 SCProfilingUpdatePacketAppRecord(i, p->
proto, pdt, 4);
957 SCProfilingUpdatePacketAppRecord(i, p->
proto, pdt, 6);
984 if (pd->
min == 0 || delta < pd->min) {
987 if (pd->
max < delta) {
991 pd->
tot += (uint64_t)delta;
994 #ifdef PROFILE_LOCKING
995 pd->lock += pdt->mutex_lock_cnt;
996 pd->ticks += pdt->mutex_lock_wait_ticks;
997 pd->contention += pdt->mutex_lock_contention;
998 pd->slock += pdt->spin_lock_cnt;
999 pd->sticks += pdt->spin_lock_wait_ticks;
1000 pd->scontention += pdt->spin_lock_contention;
1004 static void SCProfilingUpdatePacketTmmRecords(
Packet *p)
1015 SCProfilingUpdatePacketTmmRecord(i, p->
proto, pdt, 4);
1017 SCProfilingUpdatePacketTmmRecord(i, p->
proto, pdt, 6);
1022 static inline void SCProfilingUpdatePacketGenericRecord(
PktProfilingData *pdt,
1025 if (pdt == NULL || pd == NULL) {
1030 if (pd->
min == 0 || delta < pd->min) {
1033 if (pd->
max < delta) {
1045 for (i = 0; i < size; i++) {
1061 SCProfilingUpdatePacketGenericRecord(pdt, store);
1065 static void SCProfilingUpdatePacketLogRecord(
LoggerId id,
1089 static void SCProfilingUpdatePacketLogRecords(
Packet *p)
1096 SCProfilingUpdatePacketLogRecord(i, p->
proto, pdt, 4);
1098 SCProfilingUpdatePacketLogRecord(i, p->
proto, pdt, 6);
1106 if (p == NULL || p->
profile == NULL ||
1111 pthread_mutex_lock(&packet_profile_lock);
1118 if (pd->
min == 0 || delta < pd->min) {
1121 if (pd->
max < delta) {
1131 if (pd->
min == 0 || delta < pd->min) {
1134 if (pd->
max < delta) {
1145 SCProfilingUpdatePacketTmmRecords(p);
1146 SCProfilingUpdatePacketAppRecords(p);
1147 SCProfilingUpdatePacketDetectRecords(p);
1148 SCProfilingUpdatePacketLogRecords(p);
1154 if (pd->
min == 0 || delta < pd->min) {
1157 if (pd->
max < delta) {
1167 if (pd->
min == 0 || delta < pd->min) {
1170 if (pd->
max < delta) {
1181 SCProfilingUpdatePacketTmmRecords(p);
1182 SCProfilingUpdatePacketAppRecords(p);
1183 SCProfilingUpdatePacketDetectRecords(p);
1184 SCProfilingUpdatePacketLogRecords(p);
1187 if (profiling_packets_csv_enabled)
1191 pthread_mutex_unlock(&packet_profile_lock);
1197 if (sample % rate == 0)
1206 #ifdef PROFILE_LOCKING
1213 if (sample % rate == 0) {
1223 #define CASE_CODE(E) case E: return #E
1299 ProfilingGenericTicksTest01(
void)
1301 #define TEST_RUNS 1024
1302 uint64_t ticks_start = 0;
1303 uint64_t ticks_end = 0;
1312 printf(
"malloc(1024) %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1319 printf(
"SCFree(1024) %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1328 printf(
"SCMutexInit() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1335 printf(
"SCMutexLock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1342 printf(
"SCMutexUnlock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1349 printf(
"SCMutexDestroy() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1358 printf(
"SCSpinInit() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1365 printf(
"SCSpinLock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1372 printf(
"SCSpinUnlock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1379 printf(
"SCSpinDestroy() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1387 printf(
"SC_ATOMIC_ADD %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1394 printf(
"SC_ATOMIC_CAS %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1404 UtRegisterTest(
"ProfilingGenericTicksTest01", ProfilingGenericTicksTest01);
1421 static uint64_t rate = 0;
1431 intmax_t rate_v = 0;
1433 (void)
ConfGetInt(
"profiling.sample-rate", &rate_v);
1434 if (rate_v > 0 && rate_v < INT_MAX) {
1435 int literal_rate = (int)rate_v;
1436 for (
int i = literal_rate; i >= 1; i--) {
1438 if ((i & (i - 1)) == 0) {
1444 SCLogInfo(
"profiling runs for every %luth packet", rate + 1);
1446 SCLogInfo(
"profiling runs for every packet");
1457 if ((sample & rate) == 0) {