MemoryProfiling: Advanced flow usage logging.

* nDPId-test: disable #include <syslog.h> if NO_MAIN macro defined
 * nDPId-test: mock syslog flags and functions
 * gitlab-ci: force -Werror

Signed-off-by: Toni Uhlig <matzeton@googlemail.com>
This commit is contained in:
Toni Uhlig
2021-11-13 17:30:21 +01:00
parent 9075706714
commit d389f04135
6 changed files with 232 additions and 38 deletions

View File

@@ -19,7 +19,7 @@ build_and_test:
# static linked build
- mkdir build-cmake-submodule
- cd build-cmake-submodule
- cmake .. -DBUILD_EXAMPLES=ON -DBUILD_NDPI=ON -DENABLE_SANITIZER=ON -DENABLE_ZLIB=ON
- env CMAKE_C_FLAGS='-Werror' cmake .. -DBUILD_EXAMPLES=ON -DBUILD_NDPI=ON -DENABLE_SANITIZER=ON -DENABLE_ZLIB=ON
- make libnDPI
- tree libnDPI
- make install VERBOSE=1 DESTDIR="$(realpath ../_install)"
@@ -33,7 +33,7 @@ build_and_test:
- mkdir build
- cd build
- export PKG_CONFIG_PATH="$(realpath ../build-cmake-submodule/libnDPI/lib/pkgconfig)"
- cmake .. -DBUILD_EXAMPLES=ON -DENABLE_SANITIZER=ON -DENABLE_MEMORY_PROFILING=ON -DENABLE_ZLIB=ON
- env CMAKE_C_FLAGS='-Werror' cmake .. -DBUILD_EXAMPLES=ON -DENABLE_SANITIZER=ON -DENABLE_MEMORY_PROFILING=ON -DENABLE_ZLIB=ON
- make all VERBOSE=1
- cd ..
- ./build/nDPId-test || test $? -eq 1

View File

@@ -149,6 +149,7 @@ endif()
set(CMAKE_C_FLAGS "${CMAKE_C_FLAGS} -Wall -Wextra")
set(NDPID_DEFS -DJSMN_STATIC=1 -DJSMN_STRICT=1 -DJSMN_PARENT_LINKS=1)
if(ENABLE_MEMORY_PROFILING)
message(WARNING "ENABLE_MEMORY_PROFILING should not be used in production environments.")
add_definitions("-DENABLE_MEMORY_PROFILING=1"
"-Duthash_malloc=nDPIsrvd_uthash_malloc"
"-Duthash_free=nDPIsrvd_uthash_free")
@@ -255,7 +256,7 @@ target_compile_definitions(nDPId-test PRIVATE ${NDPID_DEFS})
target_include_directories(nDPId-test PRIVATE
"${STATIC_LIBNDPI_INC}" "${NDPI_INCLUDEDIR}" "${NDPI_INCLUDEDIR}/ndpi"
"${CMAKE_SOURCE_DIR}/dependencies/uthash/src")
target_compile_definitions(nDPId-test PRIVATE "-D_GNU_SOURCE=1" "-DNO_MAIN=1" "-Dsyslog=mock_syslog_stderr" ${NDPID_TEST_MPROF_DEFS})
target_compile_definitions(nDPId-test PRIVATE "-D_GNU_SOURCE=1" "-DNO_MAIN=1" ${NDPID_TEST_MPROF_DEFS})
target_link_libraries(nDPId-test "${STATIC_LIBNDPI_LIB}" "${pkgcfg_lib_NDPI_ndpi}"
"${pkgcfg_lib_PCRE_pcre}" "${pkgcfg_lib_MAXMINDDB_maxminddb}"
"${GCRYPT_LIBRARY}" "${GCRYPT_ERROR_LIBRARY}" "${PCAP_LIBRARY}" "${LIBM_LIB}"

View File

@@ -3,6 +3,19 @@
#include <stdarg.h>
#include <unistd.h>
/*
* Mock some syslog variables and functions.
* This way, we do not spam any syslog daemon on the host.
*/
#define LOG_DAEMON 0x1
#define LOG_ERR 0x2
#define LOG_CONS 0x4
#define LOG_PERROR 0x8
static void openlog(const char *ident, int option, int facility);
static void syslog(int p, const char * format, ...);
static void closelog(void);
#define NO_MAIN 1
#include "nDPIsrvd.c"
#include "nDPId.c"
@@ -63,7 +76,14 @@ static pthread_mutex_t log_mutex = PTHREAD_MUTEX_INITIALIZER;
goto error; \
} while (0);
void mock_syslog_stderr(int p, const char * format, ...)
static void openlog(const char *ident, int option, int facility)
{
(void)ident;
(void)option;
(void)facility;
}
static void syslog(int p, const char * format, ...)
{
va_list ap;
@@ -76,6 +96,10 @@ void mock_syslog_stderr(int p, const char * format, ...)
va_end(ap);
}
static void closelog(void)
{
}
static int setup_pipe(int pipefd[PIPE_COUNT])
{
if (pipe(pipefd) != 0)

232
nDPId.c
View File

@@ -16,7 +16,9 @@
#include <stdlib.h>
#include <sys/ioctl.h>
#include <sys/un.h>
#ifndef NO_MAIN
#include <syslog.h>
#endif
#include <unistd.h>
#ifdef ENABLE_ZLIB
#include <zlib.h>
@@ -930,46 +932,205 @@ static void ndpi_free_wrapper(void * const freeable)
free(p);
}
static void log_memory_usage(struct nDPId_reader_thread * const reader_thread)
static void log_memory_usage(struct nDPId_reader_thread const * const reader_thread)
{
struct nDPId_workflow * const workflow = reader_thread->workflow;
if (workflow->last_memory_usage_log_time + nDPId_options.memory_profiling_print_every < workflow->last_time)
if (reader_thread->array_index == 0)
{
if (reader_thread->array_index == 0)
{
uint64_t alloc_count = __sync_fetch_and_add(&ndpi_memory_alloc_count, 0);
uint64_t free_count = __sync_fetch_and_add(&ndpi_memory_free_count, 0);
uint64_t alloc_bytes = __sync_fetch_and_add(&ndpi_memory_alloc_bytes, 0);
uint64_t free_bytes = __sync_fetch_and_add(&ndpi_memory_free_bytes, 0);
uint64_t alloc_count = __sync_fetch_and_add(&ndpi_memory_alloc_count, 0);
uint64_t free_count = __sync_fetch_and_add(&ndpi_memory_free_count, 0);
uint64_t alloc_bytes = __sync_fetch_and_add(&ndpi_memory_alloc_bytes, 0);
uint64_t free_bytes = __sync_fetch_and_add(&ndpi_memory_free_bytes, 0);
syslog(LOG_DAEMON,
"MemoryProfiler: %llu allocs, %llu frees, %llu bytes allocated, %llu bytes freed, %llu blocks in "
"use, "
"%llu bytes in use",
(long long unsigned int)alloc_count,
(long long unsigned int)free_count,
(long long unsigned int)alloc_bytes,
(long long unsigned int)free_bytes,
(long long unsigned int)(alloc_count - free_count),
(long long unsigned int)(alloc_bytes - free_bytes));
syslog(LOG_DAEMON,
"MemoryProfiler: %llu allocs, %llu frees, %llu bytes allocated, %llu bytes freed, %llu blocks in "
"use, "
"%llu bytes in use",
(long long unsigned int)alloc_count,
(long long unsigned int)free_count,
(long long unsigned int)alloc_bytes,
(long long unsigned int)free_bytes,
(long long unsigned int)(alloc_count - free_count),
(long long unsigned int)(alloc_bytes - free_bytes));
#ifdef ENABLE_ZLIB
uint64_t zlib_compression_count = __sync_fetch_and_add(&zlib_compressions, 0);
uint64_t zlib_decompression_count = __sync_fetch_and_add(&zlib_decompressions, 0);
uint64_t zlib_bytes_diff = __sync_fetch_and_add(&zlib_compression_diff, 0);
uint64_t zlib_compression_count = __sync_fetch_and_add(&zlib_compressions, 0);
uint64_t zlib_decompression_count = __sync_fetch_and_add(&zlib_decompressions, 0);
uint64_t zlib_bytes_diff = __sync_fetch_and_add(&zlib_compression_diff, 0);
syslog(LOG_DAEMON,
"MemoryProfiler (zLib): %llu compressions, %llu decompressions, %llu compressed blocks in use, %llu "
"bytes "
"diff",
(long long unsigned int)zlib_compression_count,
(long long unsigned int)zlib_decompression_count,
(long long unsigned int)zlib_compression_count - (long long unsigned int)zlib_decompression_count,
(long long unsigned int)zlib_bytes_diff);
syslog(LOG_DAEMON,
"MemoryProfiler (zLib): %llu compressions, %llu decompressions, %llu compressed blocks in use, %llu "
"bytes "
"diff",
(long long unsigned int)zlib_compression_count,
(long long unsigned int)zlib_decompression_count,
(long long unsigned int)zlib_compression_count - (long long unsigned int)zlib_decompression_count,
(long long unsigned int)zlib_bytes_diff);
#endif
}
}
struct log_flows_user_data
{
struct nDPId_workflow * workflow;
unsigned long long int flows_ukn;
unsigned long long int flows_skp;
unsigned long long int flows_fin;
unsigned long long int flows_inf;
struct nDPId_flow_basic const * flows_active_fin[nDPId_MAX_FLOWS_PER_THREAD];
struct nDPId_flow_basic const * flows_active_inf[nDPId_MAX_FLOWS_PER_THREAD];
};
static void log_flows_flow_walker(void const * const A, ndpi_VISIT which, int depth, void * const user_data)
{
struct log_flows_user_data * const log_user_data = (struct log_flows_user_data *)user_data;
struct nDPId_flow_basic * const flow_basic = *(struct nDPId_flow_basic **)A;
(void)depth;
if (log_user_data->workflow == NULL || flow_basic == NULL)
{
return;
}
if (which == ndpi_preorder || which == ndpi_leaf)
{
switch (flow_basic->type)
{
case FT_UNKNOWN:
log_user_data->flows_ukn++;
break;
case FT_SKIPPED:
log_user_data->flows_skp++;
break;
case FT_FINISHED:
{
log_user_data->flows_fin++;
log_user_data->flows_active_fin[log_user_data->flows_fin - 1] = flow_basic;
break;
}
case FT_INFO:
{
log_user_data->flows_inf++;
log_user_data->flows_active_inf[log_user_data->flows_inf - 1] = flow_basic;
break;
}
}
}
}
static size_t log_flows_to_str(struct nDPId_flow_basic const * flows[nDPId_MAX_FLOWS_PER_THREAD],
unsigned long long int flows_used,
char output[BUFSIZ])
{
size_t output_used = 0;
int written;
output[0] = '\0';
for (size_t flow_index = 0; flow_index < flows_used; ++flow_index)
{
struct nDPId_flow_basic const * const flow_basic = flows[flow_index];
written = -1;
switch (flow_basic->type)
{
case FT_UNKNOWN:
case FT_SKIPPED:
break;
case FT_FINISHED:
{
struct nDPId_flow_finished const * const flow_finished = (struct nDPId_flow_finished const *)flow_basic;
#if 1
written = snprintf(output + output_used, BUFSIZ, "%u,", flow_finished->flow_info.flow_extended.flow_id);
#else
written =
snprintf(output + output_used,
BUFSIZ,
"[%u, %u, %llu],",
flow_finished->flow_info.flow_extended.flow_id,
flow_finished->flow_info.flow_extended.flow_basic.l4_protocol,
(unsigned long long int const)flow_finished->flow_info.flow_extended.flow_basic.last_seen);
#endif
break;
}
case FT_INFO:
{
struct nDPId_flow_info const * const flow_info = (struct nDPId_flow_info const *)flow_basic;
#if 1
written = snprintf(output + output_used, BUFSIZ, "%u,", flow_info->flow_extended.flow_id);
#else
written = snprintf(output + output_used,
BUFSIZ,
"[%u, %u, %llu],",
flow_info->flow_extended.flow_id,
flow_info->flow_extended.flow_basic.l4_protocol,
(unsigned long long int const)flow_info->flow_extended.flow_basic.last_seen);
#endif
break;
}
}
workflow->last_memory_usage_log_time = workflow->last_time;
if (written <= 0)
{
break;
}
output_used += written;
}
return (output_used > 0 ? output_used - 1 : 0);
}
static void log_flows(struct nDPId_reader_thread const * const reader_thread)
{
struct nDPId_workflow * const workflow = reader_thread->workflow;
struct log_flows_user_data log_user_data;
char flows_log_str[BUFSIZ];
size_t flows_log_str_used;
log_user_data.workflow = reader_thread->workflow;
log_user_data.flows_ukn = 0;
log_user_data.flows_skp = 0;
log_user_data.flows_fin = 0;
log_user_data.flows_inf = 0;
for (size_t scan_index = 0; scan_index < workflow->max_active_flows; ++scan_index)
{
ndpi_twalk(workflow->ndpi_flows_active[scan_index], log_flows_flow_walker, &log_user_data);
}
syslog(LOG_DAEMON,
"MemoryProfiler flow stats: [thread: %d][unknown: %llu][skipped: %llu][finished: %llu][info: %llu]",
reader_thread->array_index,
log_user_data.flows_ukn,
log_user_data.flows_skp,
log_user_data.flows_fin,
log_user_data.flows_inf);
flows_log_str_used = log_flows_to_str(log_user_data.flows_active_fin, log_user_data.flows_fin, flows_log_str);
if (flows_log_str_used > 0)
{
syslog(LOG_DAEMON,
"MemoryProfiler flows active (finished): [thread: %d][%.*s]",
reader_thread->array_index,
(int)flows_log_str_used,
flows_log_str);
}
flows_log_str_used = log_flows_to_str(log_user_data.flows_active_inf, log_user_data.flows_inf, flows_log_str);
if (flows_log_str_used > 0)
{
syslog(LOG_DAEMON,
"MemoryProfiler flows active (info): [thread: %d][%.*s]",
reader_thread->array_index,
(int)flows_log_str_used,
flows_log_str);
}
}
#endif
@@ -2591,7 +2752,12 @@ static void ndpi_process_packet(uint8_t * const args,
check_for_idle_flows(reader_thread);
#ifdef ENABLE_MEMORY_PROFILING
log_memory_usage(reader_thread);
if (workflow->last_memory_usage_log_time + nDPId_options.memory_profiling_print_every < workflow->last_time)
{
log_memory_usage(reader_thread);
log_flows(reader_thread);
workflow->last_memory_usage_log_time = workflow->last_time;
}
#endif
if (process_datalink_layer(reader_thread, header, packet, &ip_offset, &type) != 0)

View File

@@ -8,7 +8,9 @@
#include <stdlib.h>
#include <stdint.h>
#include <string.h>
#ifndef NO_MAIN
#include <syslog.h>
#endif
#include <sys/epoll.h>
#include <sys/signalfd.h>
#include <sys/socket.h>

View File

@@ -5,6 +5,7 @@
NUSER="nobody"
NSUFFIX="${NSUFFIX:-daemon-test}"
nDPId_THREADS="${nDPId_THREADS:-4}"
if [ x"${1}" = x -o x"${2}" = x ]; then
printf '%s\n' "usage: ${0} [nDPId-path] [nDPIsrvd-path]" >&2
@@ -39,7 +40,7 @@ else
${2} -p "/tmp/nDPIsrvd-${NSUFFIX}.pid" -c "/tmp/nDPIsrvd-${NSUFFIX}-collector.sock" -s "/tmp/nDPIsrvd-${NSUFFIX}-distributor.sock" -d
sudo chgrp "$(id -n -g "${NUSER}")" "/tmp/nDPIsrvd-${NSUFFIX}-collector.sock"
sudo chmod g+w "/tmp/nDPIsrvd-${NSUFFIX}-collector.sock"
sudo ${1} -p "/tmp/nDPId-${NSUFFIX}.pid" -c "/tmp/nDPIsrvd-${NSUFFIX}-collector.sock" -d -u "${NUSER}"
sudo ${1} -p "/tmp/nDPId-${NSUFFIX}.pid" -c "/tmp/nDPIsrvd-${NSUFFIX}-collector.sock" -d -u "${NUSER}" -o max-reader-threads=${nDPId_THREADS}
set +x
printf '%s\n' "daemons started" >&2
printf '%s\n' "You may now run examples e.g.: $(realpath --relative-to="$(pwd)" $(dirname "${0}")/../examples/py-flow-info/flow-info.py) --unix /tmp/nDPIsrvd-${NSUFFIX}-distributor.sock"