46 #define MIN(a, b) (((a) < (b)) ? (a) : (b))
49 #define DEFAULT_LOG_FILENAME "profile.log"
50 #define DEFAULT_LOG_MODE_APPEND "yes"
52 static pthread_mutex_t packet_profile_lock;
53 static FILE *packet_profile_csv_fp = NULL;
65 #ifdef PROFILE_LOCKING
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";
122 static void PrintCSVHeader(
void);
124 static void FormatNumber(uint64_t num,
char *
str,
size_t size)
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);
133 snprintf(
str, size,
"%3.1fb", (
float)num/1000000000UL);
147 (void)
ConfGetInt(
"profiling.sample-rate", &rate_v);
148 if (rate_v > 0 && rate_v < INT_MAX) {
151 SCLogInfo(
"profiling runs for every %dth packet", rate);
153 SCLogInfo(
"profiling runs for every packet");
161 if (pthread_mutex_init(&packet_profile_lock, NULL) != 0) {
163 "Failed to initialize packet profiling mutex.");
180 if (filename != NULL) {
184 snprintf(profiling_packets_file_name,
sizeof(profiling_packets_file_name),
185 "%s/%s", log_dir, filename);
189 profiling_packets_file_mode =
"a";
191 profiling_packets_file_mode =
"w";
194 profiling_packets_output_to_file = 1;
202 if (filename == NULL) {
203 filename =
"packet_profile.csv";
208 profiling_csv_file_name =
SCMalloc(PATH_MAX);
209 if (
unlikely(profiling_csv_file_name == NULL)) {
212 snprintf(profiling_csv_file_name, PATH_MAX,
"%s/%s", log_dir, filename);
214 packet_profile_csv_fp = fopen(profiling_csv_file_name,
"w");
215 if (packet_profile_csv_fp == NULL) {
216 SCFree(profiling_csv_file_name);
217 profiling_csv_file_name = NULL;
223 profiling_packets_csv_enabled = 1;
231 #ifndef PROFILE_LOCKING
239 if (filename != NULL) {
271 pthread_mutex_destroy(&packet_profile_lock);
274 if (profiling_packets_csv_enabled) {
275 if (packet_profile_csv_fp != NULL)
276 fclose(packet_profile_csv_fp);
277 packet_profile_csv_fp = NULL;
280 if (profiling_csv_file_name != NULL)
281 SCFree(profiling_csv_file_name);
282 profiling_csv_file_name = NULL;
284 if (profiling_file_name != NULL)
285 SCFree(profiling_file_name);
286 profiling_file_name = NULL;
288 #ifdef PROFILE_LOCKING
297 SCLogPerf(
"Done dumping profiling data.");
300 static void DumpFlowWorkerIP(FILE *fp,
int ipv, uint64_t total)
307 for (
int p = 0; p < 257; p++) {
313 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
314 double percent = (
long double)pd->
tot /
315 (
long double)total * 100;
317 fprintf(fp,
"%-20s IPv%d %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
319 pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
324 static void DumpFlowWorker(FILE *fp)
331 for (
int p = 0; p < 257; p++) {
339 fprintf(fp,
"\n%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
340 "Flow Worker",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg");
341 fprintf(fp,
"%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
342 "--------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------");
343 DumpFlowWorkerIP(fp, 4, total);
344 DumpFlowWorkerIP(fp, 6, total);
345 fprintf(fp,
"Note: %s includes app-layer for TCP\n",
359 if (profiling_packets_output_to_file == 1) {
360 fp = fopen(profiling_packets_file_name, profiling_packets_file_mode);
364 profiling_packets_file_name, strerror(errno));
371 fprintf(fp,
"\n\nPacket profile dump:\n");
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 "------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------",
"---");
378 for (i = 0; i < 257; i++) {
385 for (i = 0; i < 257; i++) {
392 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
393 double percent = (
long double)pd->
tot /
394 (
long double)total * 100;
396 fprintf(fp,
" IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n", i, pd->
cnt,
397 pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
400 for (i = 0; i < 257; i++) {
407 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
408 double percent = (
long double)pd->
tot /
409 (
long double)total * 100;
411 fprintf(fp,
" IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n", i, pd->
cnt,
412 pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr, percent);
414 fprintf(fp,
"Note: Protocol 256 tracks pseudo/tunnel packets.\n");
416 fprintf(fp,
"\nPer Thread module stats:\n");
418 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
419 "Thread Module",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot",
"%%");
420 #ifdef PROFILE_LOCKING
421 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
422 "locks",
"ticks",
"cont.",
"cont.avg",
"slocks",
"sticks",
"scont.",
"scont.avg");
426 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
427 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------",
"---");
428 #ifdef PROFILE_LOCKING
429 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
430 "--------",
"--------",
"----------",
"-----------",
"--------",
"--------",
"------------",
"-----------");
441 for (p = 0; p < 257; p++) {
455 for (p = 0; p < 257; p++) {
462 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
463 double percent = (
long double)pd->
tot /
464 (
long double)total * 100;
466 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f",
468 #ifdef PROFILE_LOCKING
469 fprintf(fp,
" %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f\n",
470 (
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);
482 for (p = 0; p < 257; p++) {
489 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
490 double percent = (
long double)pd->
tot /
491 (
long double)total * 100;
493 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n",
500 fprintf(fp,
"\nPer App layer parser stats:\n");
502 fprintf(fp,
"\n%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
503 "App Layer",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg");
504 fprintf(fp,
"%-20s %-6s %-5s %-12s %-12s %-12s %-12s\n",
505 "--------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------");
510 for (p = 0; p < 257; p++) {
520 for (p = 0; p < 257; p++) {
527 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
528 double percent = (
long double)pd->
tot /
529 (
long double)total * 100;
531 fprintf(fp,
"%-20s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
538 for (p = 0; p < 257; p++) {
545 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
546 double percent = (
long double)pd->
tot /
547 (
long double)total * 100;
549 fprintf(fp,
"%-20s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
557 for (p = 0; p < 257; p++) {
564 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
565 fprintf(fp,
"%-20s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s\n",
566 "Proto detect", p, pd->
cnt, pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr);
569 for (p = 0; p < 257; p++) {
576 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
577 fprintf(fp,
"%-20s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s\n",
578 "Proto detect", p, pd->
cnt, pd->
min, pd->
max, (uint64_t)(pd->
tot / pd->
cnt), totalstr);
585 for (p = 0; p < 257; p++) {
595 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
596 "Log Thread Module",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot",
"%%");
597 #ifdef PROFILE_LOCKING
598 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
599 "locks",
"ticks",
"cont.",
"cont.avg",
"slocks",
"sticks",
"scont.",
"scont.avg");
603 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s %-3s",
604 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------",
"---");
605 #ifdef PROFILE_LOCKING
606 fprintf(fp,
" %-10s %-10s %-12s %-12s %-10s %-10s %-12s %-12s\n",
607 "--------",
"--------",
"----------",
"-----------",
"--------",
"--------",
"------------",
"-----------");
617 for (p = 0; p < 257; p++) {
631 for (p = 0; p < 257; p++) {
638 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
639 double percent = (
long double)pd->
tot /
640 (
long double)total * 100;
642 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f",
644 #ifdef PROFILE_LOCKING
645 fprintf(fp,
" %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f %10.2f %12"PRIu64
" %12"PRIu64
" %10.2f\n",
646 (
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);
658 for (p = 0; p < 257; p++) {
665 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
666 double percent = (
long double)pd->
tot /
667 (
long double)total * 100;
669 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %6.2f\n",
674 fprintf(fp,
"\nLogger/output stats:\n");
679 for (p = 0; p < 256; p++) {
687 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
688 "Logger",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot");
689 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
690 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------");
693 for (p = 0; p < 256; p++) {
700 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
701 double percent = (
long double)pd->
tot /
702 (
long double)total * 100;
704 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
710 for (p = 0; p < 256; p++) {
717 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
718 double percent = (
long double)pd->
tot /
719 (
long double)total * 100;
721 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
726 fprintf(fp,
"\nGeneral detection engine stats:\n");
731 for (p = 0; p < 257; p++) {
739 fprintf(fp,
"\n%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
740 "Detection phase",
"IP ver",
"Proto",
"cnt",
"min",
"max",
"avg",
"tot");
741 fprintf(fp,
"%-24s %-6s %-5s %-12s %-12s %-12s %-12s %-12s\n",
742 "------------------------",
"------",
"-----",
"----------",
"------------",
"------------",
"-----------",
"-----------");
745 for (p = 0; p < 257; p++) {
752 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
753 double percent = (
long double)pd->
tot /
754 (
long double)total * 100;
756 fprintf(fp,
"%-24s IPv4 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
762 for (p = 0; p < 257; p++) {
769 FormatNumber(pd->
tot, totalstr,
sizeof(totalstr));
770 double percent = (
long double)pd->
tot /
771 (
long double)total * 100;
773 fprintf(fp,
"%-24s IPv6 %3d %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12"PRIu64
" %12s %-6.2f\n",
780 static void PrintCSVHeader(
void)
782 fprintf(packet_profile_csv_fp,
"pcap_cnt,total,receive,decode,flowworker,");
783 fprintf(packet_profile_csv_fp,
"threading,");
784 fprintf(packet_profile_csv_fp,
"proto detect,");
789 fprintf(packet_profile_csv_fp,
"loggers,");
801 fprintf(packet_profile_csv_fp,
"\n");
806 if (profiling_packets_csv_enabled == 0 || p == NULL ||
807 packet_profile_csv_fp == NULL || p->
profile == NULL) {
811 uint64_t tmm_total = 0;
812 uint64_t receive = 0;
817 fprintf(packet_profile_csv_fp,
"%"PRIu64
",%"PRIu64
",",
820 for (
int i = 0; i <
TMM_SIZE; i++) {
837 tmm_total += tmm_delta;
839 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", receive);
840 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", decode);
843 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", delta - tmm_total);
846 uint64_t app_total = 0;
850 if (p->
proto == IPPROTO_TCP) {
862 ticks_spent -= app_total;
864 ticks_spent = app_total;
867 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", ticks_spent);
871 uint64_t loggers = 0;
876 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", loggers);
882 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", pdt->
ticks_spent);
888 fprintf(packet_profile_csv_fp,
"%"PRIu64
",", pd->
ticks_spent);
891 fprintf(packet_profile_csv_fp,
"\n");
917 static void SCProfilingUpdatePacketDetectRecords(
Packet *p)
925 SCProfilingUpdatePacketDetectRecord(i, p->
proto, pdt, 4);
927 SCProfilingUpdatePacketDetectRecord(i, p->
proto, pdt, 6);
933 static void SCProfilingUpdatePacketAppPdRecord(uint8_t ipproto, uint32_t ticks_spent,
int ipver)
941 if (pd->
min == 0 || ticks_spent < pd->min) {
942 pd->
min = ticks_spent;
944 if (pd->
max < ticks_spent) {
945 pd->
max = ticks_spent;
948 pd->
tot += ticks_spent;
952 static void SCProfilingUpdatePacketAppRecord(
int alproto, uint8_t ipproto,
PktProfilingAppData *pdt,
int ipver)
975 static void SCProfilingUpdatePacketAppRecords(
Packet *p)
983 SCProfilingUpdatePacketAppRecord(i, p->
proto, pdt, 4);
985 SCProfilingUpdatePacketAppRecord(i, p->
proto, pdt, 6);
1012 if (pd->
min == 0 || delta < pd->min) {
1015 if (pd->
max < delta) {
1019 pd->
tot += (uint64_t)delta;
1022 #ifdef PROFILE_LOCKING
1023 pd->lock += pdt->mutex_lock_cnt;
1024 pd->ticks += pdt->mutex_lock_wait_ticks;
1025 pd->contention += pdt->mutex_lock_contention;
1026 pd->slock += pdt->spin_lock_cnt;
1027 pd->sticks += pdt->spin_lock_wait_ticks;
1028 pd->scontention += pdt->spin_lock_contention;
1032 static void SCProfilingUpdatePacketTmmRecords(
Packet *p)
1043 SCProfilingUpdatePacketTmmRecord(i, p->
proto, pdt, 4);
1045 SCProfilingUpdatePacketTmmRecord(i, p->
proto, pdt, 6);
1050 static inline void SCProfilingUpdatePacketGenericRecord(
PktProfilingData *pdt,
1053 if (pdt == NULL || pd == NULL) {
1058 if (pd->
min == 0 || delta < pd->min) {
1061 if (pd->
max < delta) {
1073 for (i = 0; i < size; i++) {
1089 SCProfilingUpdatePacketGenericRecord(pdt, store);
1093 static void SCProfilingUpdatePacketLogRecord(
LoggerId id,
1117 static void SCProfilingUpdatePacketLogRecords(
Packet *p)
1124 SCProfilingUpdatePacketLogRecord(i, p->
proto, pdt, 4);
1126 SCProfilingUpdatePacketLogRecord(i, p->
proto, pdt, 6);
1134 if (p == NULL || p->
profile == NULL ||
1139 pthread_mutex_lock(&packet_profile_lock);
1146 if (pd->
min == 0 || delta < pd->min) {
1149 if (pd->
max < delta) {
1159 if (pd->
min == 0 || delta < pd->min) {
1162 if (pd->
max < delta) {
1173 SCProfilingUpdatePacketTmmRecords(p);
1174 SCProfilingUpdatePacketAppRecords(p);
1175 SCProfilingUpdatePacketDetectRecords(p);
1176 SCProfilingUpdatePacketLogRecords(p);
1182 if (pd->
min == 0 || delta < pd->min) {
1185 if (pd->
max < delta) {
1195 if (pd->
min == 0 || delta < pd->min) {
1198 if (pd->
max < delta) {
1209 SCProfilingUpdatePacketTmmRecords(p);
1210 SCProfilingUpdatePacketAppRecords(p);
1211 SCProfilingUpdatePacketDetectRecords(p);
1212 SCProfilingUpdatePacketLogRecords(p);
1215 if (profiling_packets_csv_enabled)
1219 pthread_mutex_unlock(&packet_profile_lock);
1225 if (sample % rate == 0)
1234 #ifdef PROFILE_LOCKING
1241 if (sample % rate == 0) {
1251 #define CASE_CODE(E) case E: return #E
1348 ProfilingGenericTicksTest01(
void)
1350 #define TEST_RUNS 1024
1351 uint64_t ticks_start = 0;
1352 uint64_t ticks_end = 0;
1361 printf(
"malloc(1024) %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1368 printf(
"SCFree(1024) %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1377 printf(
"SCMutexInit() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1384 printf(
"SCMutexLock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1391 printf(
"SCMutexUnlock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1398 printf(
"SCMutexDestroy() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1407 printf(
"SCSpinInit() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1414 printf(
"SCSpinLock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1421 printf(
"SCSpinUnlock() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1428 printf(
"SCSpinDestroy() %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1436 printf(
"SC_ATOMIC_ADD %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1443 printf(
"SC_ATOMIC_CAS %"PRIu64
"\n", (ticks_end - ticks_start)/
TEST_RUNS);
1453 UtRegisterTest(
"ProfilingGenericTicksTest01", ProfilingGenericTicksTest01);