ivampiresp/Spdk
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

log: add deprecated tracking API

Browse Source 
When use of deprecated featues is encountered, SPDK now calls
SPDK_LOG_DEPRECATED(). This logs the use of deprecated functionality in
a consistent way, making it easy to add further instrumentation to catch
code paths that trigger deprecated behavior.

Change-Id: Idfd33ade171307e5e8235a7aa0d969dc5d93e33d
Signed-off-by: Mike Gerdts <mgerdts@nvidia.com>
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/15689
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>
Reviewed-by: Jim Harris <james.r.harris@intel.com>
Reviewed-by: Aleksey Marchuk <alexeymar@nvidia.com>
Community-CI: Mellanox Build Bot
This commit is contained in:
Mike Gerdts 2022-11-29 11:02:14 -06:00 committed by Jim Harris
parent d0cdaf0fd8
commit 5b50d3e8b7
8 changed files with 415 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
CHANGELOG.md
View File

@ -90,6 +90,15 @@ its exit process has started using `spdk_thread_exit`.
Added API `spdk_spin_init`, `spdk_spin_destroy`, `spdk_spin_lock`, `spdk_spin_unlock`, and
`spdk_spin_held` to support spinlocks that are aware of the SPDK concurrency model.
### log
Added consistent tracking of use of deprecated behavior. Deprecations continue to be
listed in deprecation.md and now are in subsections with headers matching a tag
used in `SPDK_LOG_DEPRECATED()` calls. When deprecated behavior is used, these
tags will appear in SPDK's log at the warn level. As the SPDK application exits, it
will log a summary of how many times `SPDK_LOG_DEPRECATED()` was called for each
tag that was logged at least once.
## v22.09
### accel

5
deprecation.md
View File

@ -12,6 +12,11 @@ Each entry must describe what will be removed and can suggest the future use or
Specific future SPDK release for the removal must be provided.
ABI cannot be removed without providing deprecation notice for at least single SPDK release.
Deprecated code paths must be registered with `SPDK_DEPRECATION_REGISTER()` and logged with
`SPDK_LOG_DEPRECATED()`. The tag used with these macros will appear in the SPDK
log at the warn level when `SPDK_LOG_DEPRECATED()` is called, subject to rate limits.
The tags can be matched with the level 4 headers below.
## Deprecation Notices {#deprecation-notices}
### nvme

96
include/spdk/log.h
View File

@ -1,6 +1,7 @@
/* SPDX-License-Identifier: BSD-3-Clause
* Copyright (C) 2016 Intel Corporation.
* All rights reserved.
* Copyright (c) 2022, NVIDIA CORPORATION & AFFILIATES. All rights reserved.
*/
/**
@ -252,6 +253,101 @@ int spdk_log_clear_flag(const char *flag);
*/
void spdk_log_usage(FILE *f, const char *log_arg);
struct spdk_deprecation;
/**
* Register a deprecation. Most consumers will use SPDK_LOG_DEPRECATION_REGISTER() instead.
*
* \param tag A unique string that will appear in each log message and should appear in
* documentation.
* \param description A descriptive string that will also be logged.
* \param rate_limit_seconds If non-zero, log messages related to this deprecation will appear no
* more frequently than this interval.
* \param remove_release The release when the deprecated support will be removed.
* \param reg Pointer to storage for newly allocated deprecation handle.
* \return 0 on success or negative errno on failure.
*/
int spdk_log_deprecation_register(const char *tag, const char *description,
const char *remove_release, uint32_t rate_limit_seconds,
struct spdk_deprecation **reg);
#define SPDK_LOG_DEPRECATION_REGISTER(tag, desc, release, rate) \
static struct spdk_deprecation *_deprecated_##tag; \
static void __attribute__((constructor)) _spdk_deprecation_register_##tag(void) \
{ \
int rc; \
rc = spdk_log_deprecation_register(#tag, desc, release, rate, &_deprecated_##tag); \
(void)rc; \
assert(rc == 0); \
}
/**
* Indicate that a deprecated feature was used. Most consumers will use SPDK_LOG_DEPRECATED()
* instead.
*
* \param deprecation The deprecated feature that was used.
* \param file The name of the source file where the deprecated feature was used.
* \param line The line in file where where the deprecated feature was used.
* \param func The name of the function where where the deprecated feature was used.
*/
void spdk_log_deprecated(struct spdk_deprecation *deprecation, const char *file, uint32_t line,
const char *func);
#define SPDK_LOG_DEPRECATED(tag) \
spdk_log_deprecated(_deprecated_##tag, __FILE__, __LINE__, __func__)
/**
* Callback function for spdk_log_for_each_deprecation().
*
* \param ctx Context passed via spdk_log_for_each_deprecation().
* \param deprecation Pointer to a deprecation structure.
* \return 0 to continue iteration or non-zero to stop iteration.
*/
typedef int (*spdk_log_for_each_deprecation_fn)(void *ctx, struct spdk_deprecation *deprecation);
/**
* Iterate over all deprecations, calling a callback on each of them.
*
* Iteration will stop early if the callback function returns non-zero.
*
* \param ctx Context to pass to the callback.
* \param fn Callback function
* \return The value from the last callback called or 0 if there are no deprecations.
*/
int spdk_log_for_each_deprecation(void *ctx, spdk_log_for_each_deprecation_fn fn);
/**
* Get a deprecation's tag.
*
* \param deprecation A pointer to an spdk_deprecation.
* \return The deprecation's tag.
*/
const char *spdk_deprecation_get_tag(const struct spdk_deprecation *deprecation);
/**
* Get a deprecation's description.
*
* \param deprecation A pointer to an spdk_deprecation.
* \return The deprecation's description.
*/
const char *spdk_deprecation_get_description(const struct spdk_deprecation *deprecation);
/**
* Get a deprecation's planned removal release.
*
* \param deprecation A pointer to an spdk_deprecation.
* \return The deprecation's planned removal release.
*/
const char *spdk_deprecation_get_remove_release(const struct spdk_deprecation *deprecation);
/**
* Get the number of times that a deprecation's code has been executed.
*
* \param deprecation A pointer to an spdk_deprecation.
* \return The deprecation's planned removal release.
*/
uint64_t spdk_deprecation_get_hits(const struct spdk_deprecation *deprecation);
#ifdef __cplusplus
}
#endif

16
lib/event/app.c
View File

@ -772,6 +772,21 @@ _start_subsystem_fini(void *arg1)
spdk_subsystem_fini(spdk_reactors_stop, NULL);
}
static int
log_deprecation_hits(void *ctx, struct spdk_deprecation *dep)
{
uint64_t hits = spdk_deprecation_get_hits(dep);
if (hits == 0) {
return 0;
}
SPDK_WARNLOG("%s: deprecation '%s' scheduled for removal in %s hit %" PRIu64 " times\n",
spdk_deprecation_get_tag(dep), spdk_deprecation_get_remove_release(dep),
spdk_deprecation_get_description(dep), hits);
return 0;
}
static void
app_stop(void *arg1)
{
@ -786,6 +801,7 @@ app_stop(void *arg1)
spdk_rpc_finish();
g_spdk_app.stopped = true;
spdk_log_for_each_deprecation(NULL, log_deprecation_hits);
_start_subsystem_fini(NULL);
}

4
lib/log/Makefile
View File

@ -7,10 +7,10 @@ SPDK_ROOT_DIR := $(abspath $(CURDIR)/../..)
include $(SPDK_ROOT_DIR)/mk/spdk.common.mk
SO_VER := 5
SO_MINOR := 0
SO_MINOR := 1
SO_SUFFIX := $(SO_VER).$(SO_MINOR)
C_SRCS = log.c log_flags.c
C_SRCS = log.c log_flags.c log_deprecated.c
LIBNAME = log
SPDK_MAP_FILE = $(abspath $(CURDIR)/spdk_log.map)

144
lib/log/log_deprecated.c Normal file
View File

@ -0,0 +1,144 @@
/* SPDX-License-Identifier: BSD-3-Clause
* Copyright (c) 2022, NVIDIA CORPORATION & AFFILIATES. All rights reserved.
*/
#include "spdk/stdinc.h"
#include "spdk/string.h"
#include "spdk/thread.h"
#include "spdk/util.h"
#include "spdk/log.h"
struct spdk_deprecation {
const char tag[32];
const char desc[64];
const char remove[16];
TAILQ_ENTRY(spdk_deprecation) link;
uint64_t hits;
/* How often (nanoseconds) to log. */
uint64_t interval;
/* How many messages were not logged due to rate limiting */
uint32_t deferred;
/* CLOCK_MONOTONIC microseconds since g_deprecation_epoch when last warning was logged */
uint64_t last_log;
};
static TAILQ_HEAD(, spdk_deprecation) g_deprecations = TAILQ_HEAD_INITIALIZER(g_deprecations);
struct timespec g_deprecation_epoch;
static void
__attribute__((constructor))
deprecation_init(void)
{
clock_gettime(CLOCK_MONOTONIC, &g_deprecation_epoch);
}
static inline uint64_t
get_ns_since_epoch(void)
{
struct timespec now;
clock_gettime(CLOCK_MONOTONIC, &now);
return (now.tv_sec - g_deprecation_epoch.tv_sec) * SPDK_SEC_TO_NSEC +
now.tv_nsec - g_deprecation_epoch.tv_nsec;
}
int
spdk_log_deprecation_register(const char *tag, const char *description, const char *remove_release,
uint32_t rate_limit_seconds, struct spdk_deprecation **depp)
{
struct spdk_deprecation *dep;
assert(strnlen(tag, sizeof(dep->tag)) < sizeof(dep->tag));
assert(strnlen(description, sizeof(dep->desc)) < sizeof(dep->desc));
assert(strnlen(remove_release, sizeof(dep->remove)) < sizeof(dep->remove));
dep = calloc(1, sizeof(*dep));
if (dep == NULL) {
return -ENOMEM;
}
snprintf((char *)dep->tag, sizeof(dep->tag), "%s", tag);
snprintf((char *)dep->desc, sizeof(dep->desc), "%s", description);
snprintf((char *)dep->remove, sizeof(dep->remove), "%s", remove_release);
dep->interval = rate_limit_seconds * SPDK_SEC_TO_NSEC;
TAILQ_INSERT_TAIL(&g_deprecations, dep, link);
*depp = dep;
return 0;
}
/*
* There is potential for races between pthreads leading to over or under reporting of times that
* deprecated code was hit. If this function is called in a hot path where that is likely, we care
* more about performance than accuracy of the error counts. The important thing is that at least
* one of the racing updates the hits counter to non-zero and the warning is logged at least once.
*/
void
spdk_log_deprecated(struct spdk_deprecation *dep, const char *file, uint32_t line, const char *func)
{
uint64_t now = get_ns_since_epoch();
if (dep == NULL) {
SPDK_ERRLOG("NULL deprecation passed from %s:%u:%s\n", file, line, func);
assert(false);
return;
}
dep->hits++;
if (dep->interval != 0) {
if (dep->last_log != 0 && now < dep->last_log + dep->interval) {
dep->deferred++;
return;
}
}
dep->last_log = now;
spdk_log(SPDK_LOG_WARN, file, line, func, "%s: deprecated feature %s to be removed in %s\n",
dep->tag, dep->desc, dep->remove);
if (dep->deferred != 0) {
SPDK_WARNLOG("%s: %u messages suppressed\n", dep->tag, dep->deferred);
dep->deferred = 0;
}
}
int
spdk_log_for_each_deprecation(void *ctx, spdk_log_for_each_deprecation_fn fn)
{
struct spdk_deprecation *dep;
int rc = 0;
TAILQ_FOREACH(dep, &g_deprecations, link) {
rc = fn(ctx, dep);
if (rc != 0) {
break;
}
}
return rc;
}
const char *
spdk_deprecation_get_tag(const struct spdk_deprecation *deprecation)
{
return deprecation->tag;
}
const char *
spdk_deprecation_get_description(const struct spdk_deprecation *deprecation)
{
return deprecation->desc;
}
const char *
spdk_deprecation_get_remove_release(const struct spdk_deprecation *deprecation)
{
return deprecation->remove;
}
uint64_t
spdk_deprecation_get_hits(const struct spdk_deprecation *deprecation)
{
return deprecation->hits;
}

7
lib/log/spdk_log.map
View File

@ -17,6 +17,13 @@
spdk_log_clear_flag;
spdk_log_usage;
spdk_log_enable_timestamps;
spdk_log_deprecation_register;
spdk_log_deprecated;
spdk_log_for_each_deprecation;
spdk_deprecation_get_tag;
spdk_deprecation_get_description;
spdk_deprecation_get_remove_release;
spdk_deprecation_get_hits;
# functions used by other SPDK libraries
spdk_log_register_flag;

136
test/unit/lib/log/log.c/log_ut.c
View File

@ -7,9 +7,12 @@
#include "spdk_cunit.h"
#include "spdk/log.h"
#include "spdk/env.h"
#include "spdk/string.h"
#include "log/log.c"
#include "log/log_flags.c"
#include "log/log_deprecated.c"
static void
log_test(void)
@ -58,6 +61,138 @@ log_test(void)
spdk_log_close();
}
SPDK_LOG_DEPRECATION_REGISTER(unit_test_not_limited, "not rate limited", "never", 0)
SPDK_LOG_DEPRECATION_REGISTER(unit_test_limited, "with rate limit", "sometime", 1)
SPDK_LOG_DEPRECATION_REGISTER(unit_test_never_called, "not called", "maybe", 0)
int g_ut_dep_expect_line;
const char *g_ut_dep_expect_func;
const char *g_ut_dep_expect_msg;
uint32_t g_ut_dep_log_times;
bool g_ut_dep_saw_suppressed_log;
static void
log_deprecations(int level, const char *file, const int line, const char *func,
const char *format, va_list args)
{
char *msg;
g_ut_dep_log_times++;
CU_ASSERT(level == SPDK_LOG_WARN);
if (strcmp("spdk_log_deprecated", func) == 0) {
g_ut_dep_saw_suppressed_log = true;
} else {
CU_ASSERT(strcmp(g_ut_dep_expect_func, func) == 0);
CU_ASSERT(g_ut_dep_expect_line == line);
}
/* A "starts with" check */
msg = spdk_vsprintf_alloc(format, args);
SPDK_CU_ASSERT_FATAL(msg != NULL);
CU_ASSERT(strncmp(g_ut_dep_expect_msg, msg, strlen(g_ut_dep_expect_msg)) == 0)
free(msg);
}
bool g_found_not_limited;
bool g_found_limited;
bool g_found_never_called;
static int
iter_dep_cb(void *ctx, struct spdk_deprecation *dep)
{
/* The getters work from the callback. */
if (dep == _deprecated_unit_test_not_limited) {
CU_ASSERT(!g_found_not_limited);
g_found_not_limited = true;
CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_not_limited") == 0);
CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "not rate limited") == 0);
CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "never") == 0);
CU_ASSERT(spdk_deprecation_get_hits(dep) != 0);
} else if (dep == _deprecated_unit_test_limited) {
CU_ASSERT(!g_found_limited);
g_found_limited = true;
CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_limited") == 0);
CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "with rate limit") == 0);
CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "sometime") == 0);
CU_ASSERT(spdk_deprecation_get_hits(dep) != 0);
} else if (dep == _deprecated_unit_test_never_called) {
CU_ASSERT(!g_found_never_called);
g_found_never_called = true;
CU_ASSERT(strcmp(spdk_deprecation_get_tag(dep), "unit_test_never_called") == 0);
CU_ASSERT(strcmp(spdk_deprecation_get_description(dep), "not called") == 0);
CU_ASSERT(strcmp(spdk_deprecation_get_remove_release(dep), "maybe") == 0);
CU_ASSERT(spdk_deprecation_get_hits(dep) == 0);
} else {
CU_ASSERT(false);
}
return 0;
}
static void
deprecation(void)
{
int rc;
spdk_log_open(log_deprecations);
/* A log message is emitted for every message without rate limiting. */
g_ut_dep_saw_suppressed_log = false;
g_ut_dep_log_times = 0;
g_ut_dep_expect_func = __func__;
g_ut_dep_expect_msg = "unit_test_not_limited:";
g_ut_dep_expect_line = __LINE__ + 1;
SPDK_LOG_DEPRECATED(unit_test_not_limited);
CU_ASSERT(_deprecated_unit_test_not_limited->hits == 1);
CU_ASSERT(_deprecated_unit_test_not_limited->deferred == 0);
CU_ASSERT(g_ut_dep_log_times == 1);
g_ut_dep_expect_line = __LINE__ + 1;
SPDK_LOG_DEPRECATED(unit_test_not_limited);
CU_ASSERT(_deprecated_unit_test_not_limited->hits == 2);
CU_ASSERT(_deprecated_unit_test_not_limited->deferred == 0);
CU_ASSERT(g_ut_dep_log_times == 2);
CU_ASSERT(!g_ut_dep_saw_suppressed_log);
/* Rate limiting keeps track of deferred messages */
g_ut_dep_saw_suppressed_log = false;
g_ut_dep_log_times = 0;
g_ut_dep_expect_msg = "unit_test_limited:";
g_ut_dep_expect_line = __LINE__ + 1;
SPDK_LOG_DEPRECATED(unit_test_limited);
CU_ASSERT(_deprecated_unit_test_limited->hits == 1);
CU_ASSERT(_deprecated_unit_test_limited->deferred == 0);
CU_ASSERT(g_ut_dep_log_times == 1);
SPDK_LOG_DEPRECATED(unit_test_limited);
CU_ASSERT(_deprecated_unit_test_limited->hits == 2);
CU_ASSERT(_deprecated_unit_test_limited->deferred == 1);
CU_ASSERT(g_ut_dep_log_times == 1);
CU_ASSERT(!g_ut_dep_saw_suppressed_log);
/* After a delay, the next log message prints the normal message followed by one that says
* that some messages were suppressed.
*/
g_ut_dep_saw_suppressed_log = false;
sleep(1);
g_ut_dep_expect_line = __LINE__ + 1;
SPDK_LOG_DEPRECATED(unit_test_limited);
CU_ASSERT(_deprecated_unit_test_limited->hits == 3);
CU_ASSERT(_deprecated_unit_test_limited->deferred == 0);
CU_ASSERT(g_ut_dep_log_times == 3);
CU_ASSERT(g_ut_dep_saw_suppressed_log);
/* spdk_log_for_each_deprecation() visits each registered deprecation */
rc = spdk_log_for_each_deprecation(NULL, iter_dep_cb);
CU_ASSERT(rc == 0);
CU_ASSERT(g_found_not_limited);
CU_ASSERT(g_found_limited);
CU_ASSERT(g_found_never_called);
g_log = NULL;
}
int
main(int argc, char **argv)
{
@ -70,6 +205,7 @@ main(int argc, char **argv)
suite = CU_add_suite("log", NULL, NULL);
CU_ADD_TEST(suite, log_test);
CU_ADD_TEST(suite, deprecation);
CU_basic_set_mode(CU_BRM_VERBOSE);
CU_basic_run_tests();