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

lib/thread: spdk_thread_poll() measures run time per call by reading end TSC

Browse Source 
Update spdk_thread_poll() to count SPDK thread stats correctly on multiple
SPDK threads per reactor configuration.

spdk_thread_poll() gets start time and reads TSC at end as end time,
and then gets delta between them as run time. Run time is added to idle
time or busy time according to the result of polling.

Reactor overhead is included into the next thread which calls
spdk_thread_poll() now.

spdk_thread_poll() saves the end time to the current thread to use it
as the start time of the next thread.

Unit test framework for this patch and the next patch need to access
thread->tsc_last. In the next patch, reactor will use the end time of
the current thread to the start time of the next thread in reactor_run()
to realize the idea.

Hence add an new API spdk_thread_get_last_tsc(). The corresponding
variable is named as tsc_last and it is good and is aligned with
DPDK (DPDK has used tsc_start and tsc_end as variable name). But
last_tsc will be better as API name because the last TSC value is
easier to understand.

Then add necessary unit test and update the unit test framework.

Signed-off-by: Shuhei Matsumoto <shuhei.matsumoto.xt@hitachi.com>
Change-Id: I5e465e9283c032acb427576d0c90f9e1414f2271
Reviewed-on: https://review.spdk.io/gerrit/c/spdk/spdk/+/1048
Tested-by: SPDK CI Jenkins <sys_sgci@intel.com>
Reviewed-by: Aleksey Marchuk <alexeymar@mellanox.com>
Reviewed-by: Jim Harris <james.r.harris@intel.com>
Reviewed-by: Changpeng Liu <changpeng.liu@intel.com>
Reviewed-by: Paul Luse <paul.e.luse@intel.com>
This commit is contained in:
Shuhei Matsumoto 2020-03-13 11:53:00 +09:00 committed by Tomasz Zawadzki
parent e7615cbe51
commit 2139be1598
4 changed files with 120 additions and 9 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

14
include/spdk/thread.h
View File

@ -345,7 +345,10 @@ struct spdk_thread *spdk_thread_get_from_ctx(void *ctx);
* \param max_msgs The maximum number of messages that will be processed.
* Use 0 to process the default number of messages (8).
* \param now The current time, in ticks. Optional. If 0 is passed, this
* function may call spdk_get_ticks() to get the current time.
* function will call spdk_get_ticks() to get the current time.
* The current time is used as start time and this function
* will call spdk_get_ticks() at its end to know end time to
* measure run time of this function.
*
* \return 1 if work was done. 0 if no work was done.
*/
@ -448,6 +451,15 @@ struct spdk_thread_stats {
*/
int spdk_thread_get_stats(struct spdk_thread_stats *stats);
/**
* Return the TSC value from the end of the last time this thread was polled.
*
* \param thread Thread to query.
*
* \return TSC value from the end of the last time this thread was polled.
*/
uint64_t spdk_thread_get_last_tsc(struct spdk_thread *thread);
/**
* Send a message to the given thread.
*

18
lib/thread/thread.c
View File

@ -520,16 +520,18 @@ _spdk_thread_insert_poller(struct spdk_thread *thread, struct spdk_poller *polle
}
static inline void
_spdk_thread_update_stats(struct spdk_thread *thread, uint64_t now, int rc)
_spdk_thread_update_stats(struct spdk_thread *thread, uint64_t end,
uint64_t start, int rc)
{
if (rc == 0) {
/* Poller status idle */
thread->stats.idle_tsc += now - thread->tsc_last;
thread->stats.idle_tsc += end - start;
} else if (rc > 0) {
/* Poller status busy */
thread->stats.busy_tsc += now - thread->tsc_last;
thread->stats.busy_tsc += end - start;
}
thread->tsc_last = now;
/* Store end time to use it as start time of the next spdk_thread_poll(). */
thread->tsc_last = end;
}
static int
@ -650,7 +652,7 @@ spdk_thread_poll(struct spdk_thread *thread, uint32_t max_msgs, uint64_t now)
rc = _spdk_thread_poll(thread, max_msgs, now);
_spdk_thread_update_stats(thread, now, rc);
_spdk_thread_update_stats(thread, spdk_get_ticks(), now, rc);
tls_thread = orig_thread;
@ -777,6 +779,12 @@ spdk_thread_get_stats(struct spdk_thread_stats *stats)
return 0;
}
uint64_t
spdk_thread_get_last_tsc(struct spdk_thread *thread)
{
return thread->tsc_last;
}
int
spdk_thread_send_msg(const struct spdk_thread *thread, spdk_msg_fn fn, void *ctx)
{

10
test/common/lib/ut_multithread.c
View File

@ -129,6 +129,7 @@ poll_thread_times(uintptr_t thread_id, uint32_t max_polls)
struct ut_thread *thread = &g_ut_threads[thread_id];
uintptr_t original_thread_id;
uint32_t polls_executed = 0;
uint64_t now;
if (max_polls == 0) {
/* If max_polls is set to 0,
@ -141,10 +142,12 @@ poll_thread_times(uintptr_t thread_id, uint32_t max_polls)
original_thread_id = g_ut_thread_id;
set_thread(INVALID_THREAD);
now = spdk_get_ticks();
while (polls_executed < max_polls) {
if (spdk_thread_poll(thread->thread, 1, 0) > 0) {
if (spdk_thread_poll(thread->thread, 1, now) > 0) {
busy = true;
}
now = spdk_thread_get_last_tsc(thread->thread);
polls_executed++;
}
@ -159,6 +162,7 @@ poll_thread(uintptr_t thread_id)
bool busy = false;
struct ut_thread *thread = &g_ut_threads[thread_id];
uintptr_t original_thread_id;
uint64_t now;
assert(thread_id != (uintptr_t)INVALID_THREAD);
assert(thread_id < g_ut_num_threads);
@ -166,7 +170,9 @@ poll_thread(uintptr_t thread_id)
original_thread_id = g_ut_thread_id;
set_thread(INVALID_THREAD);
while (spdk_thread_poll(thread->thread, 0, 0) > 0) {
now = spdk_get_ticks();
while (spdk_thread_poll(thread->thread, 0, now) > 0) {
now = spdk_thread_get_last_tsc(thread->thread);
busy = true;
}

87
test/unit/lib/thread/thread.c/thread_ut.c
View File

@ -916,6 +916,90 @@ thread_exit(void)
free_threads();
}
static int
poller_run_idle(void *ctx)
{
uint64_t delay_us = (uint64_t)ctx;
spdk_delay_us(delay_us);
return 0;
}
static int
poller_run_busy(void *ctx)
{
uint64_t delay_us = (uint64_t)ctx;
spdk_delay_us(delay_us);
return 1;
}
static void
thread_update_stats(void)
{
struct spdk_poller *poller;
struct spdk_thread *thread;
MOCK_SET(spdk_get_ticks, 10);
allocate_threads(1);
set_thread(0);
thread = spdk_get_thread();
CU_ASSERT(thread->tsc_last == 10);
CU_ASSERT(thread->stats.idle_tsc == 0);
CU_ASSERT(thread->stats.busy_tsc == 0);
/* Test if idle_tsc is updated expectedly. */
poller = spdk_poller_register(poller_run_idle, (void *)1000, 0);
CU_ASSERT(poller != NULL);
spdk_delay_us(100);
poll_thread_times(0, 1);
CU_ASSERT(thread->tsc_last == 1110);
CU_ASSERT(thread->stats.idle_tsc == 1000);
CU_ASSERT(thread->stats.busy_tsc == 0);
spdk_delay_us(100);
poll_thread_times(0, 1);
CU_ASSERT(thread->tsc_last == 2210);
CU_ASSERT(thread->stats.idle_tsc == 2000);
CU_ASSERT(thread->stats.busy_tsc == 0);
spdk_poller_unregister(&poller);
/* Test if busy_tsc is updated expectedly. */
poller = spdk_poller_register(poller_run_busy, (void *)100000, 0);
CU_ASSERT(poller != NULL);
spdk_delay_us(10000);
poll_thread_times(0, 1);
CU_ASSERT(thread->tsc_last == 112210);
CU_ASSERT(thread->stats.idle_tsc == 2000);
CU_ASSERT(thread->stats.busy_tsc == 100000);
spdk_delay_us(10000);
poll_thread_times(0, 1);
CU_ASSERT(thread->tsc_last == 222210);
CU_ASSERT(thread->stats.idle_tsc == 2000);
CU_ASSERT(thread->stats.busy_tsc == 200000);
spdk_poller_unregister(&poller);
free_threads();
}
int
main(int argc, char **argv)
{
@ -943,7 +1027,8 @@ main(int argc, char **argv)
CU_add_test(suite, "thread_name", thread_name) == NULL ||
CU_add_test(suite, "channel", channel) == NULL ||
CU_add_test(suite, "channel_destroy_races", channel_destroy_races) == NULL ||
CU_add_test(suite, "thread_exit", thread_exit) == NULL
CU_add_test(suite, "thread_exit", thread_exit) == NULL ||
CU_add_test(suite, "thread_update_stats", thread_update_stats) == NULL
) {
CU_cleanup_registry();
return CU_get_error();