patrick/zephyr
1
0
Fork 0
Code Issues Pull requests Actions 8 Packages Projects Releases Wiki Activity

samples: subsys: logging: logger: Fix performance showcase

Browse source 
Sample tries to estimate maximum number of messages that can be
logged. It was using two system cycles and counting number of
messages logged in that window. It did not take into account the
fact that clock frequency may vary and logging speed also varies
(especially if LOG_IMMEDIATE is enabled). Presented results may
be faulty and misleading.

Fix is attempting to adjust window size to increase precision of
the measurement.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
Krzysztof Chruscinski 2020-01-13 13:29:32 +01:00 committed by Carles Cufí
parent 086a6b7c64
commit a7725aef0e
1 changed files with 53 additions and 24 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

77
samples/subsys/logging/logger/src/main.c
View file

@ -191,6 +191,13 @@ static void log_strdup_showcase(void)
transient_str[0] = '\0';
}
static void wait_on_log_flushed(void)
{
while (log_buffered_cnt()) {
k_sleep(K_MSEC(5));
}
}
/**
* @brief Function demonstrates how fast data can be logged.
*
@ -200,32 +207,61 @@ static void log_strdup_showcase(void)
*/
static void performance_showcase(void)
{
/* Arbitrary limit when LOG_IMMEDIATE is enabled. */
#define LOG_IMMEDIATE_TEST_MESSAGES_LIMIT 50
volatile uint32_t current_timestamp;
volatile uint32_t start_timestamp;
uint32_t limit = COND_CODE_1(CONFIG_LOG_IMMEDIATE,
(LOG_IMMEDIATE_TEST_MESSAGES_LIMIT),
(CONFIG_LOG_BUFFER_SIZE / sizeof(struct log_msg)));
uint32_t per_sec;
uint32_t cnt = 0U;
uint32_t window = 2U;
printk("Logging performance showcase.\n");
start_timestamp = timestamp_get();
while (start_timestamp == timestamp_get()) {
#if (CONFIG_ARCH_POSIX)
k_busy_wait(100);
#endif
}
start_timestamp = timestamp_get();
wait_on_log_flushed();
do {
LOG_INF("performance test - log message %d", cnt);
cnt++;
current_timestamp = timestamp_get();
#if (CONFIG_ARCH_POSIX)
k_busy_wait(100);
#endif
} while (current_timestamp < (start_timestamp + window));
cnt = 0;
start_timestamp = timestamp_get();
while (start_timestamp == timestamp_get()) {
#if (CONFIG_ARCH_POSIX)
k_busy_wait(100);
#endif
}
start_timestamp = timestamp_get();
do {
LOG_INF("performance test - log message %d", cnt);
cnt++;
current_timestamp = timestamp_get();
#if (CONFIG_ARCH_POSIX)
k_busy_wait(100);
#endif
} while (current_timestamp < (start_timestamp + window));
wait_on_log_flushed();
/* If limit exceeded then some messages might be dropped which
* degraded performance. Decrease window size.
* If less than half of limit is reached then it means that
* window can be increased to improve precision.
*/
if (cnt >= limit) {
if (window >= 2) {
window /= 2;
} else {
break;
}
} else if (cnt < (limit / 2)) {
window *= 2;
} else {
break;
}
} while (1);
per_sec = (cnt * timestamp_freq()) / window;
printk("Estimated logging capabilities: %d messages/second\n", per_sec);
@ -240,13 +276,6 @@ static void external_log_system_showcase(void)
ext_log_system_foo();
}
static void wait_on_log_flushed(void)
{
while (log_buffered_cnt()) {
k_sleep(K_MSEC(5));
}
}
static void log_demo_thread(void *p1, void *p2, void *p3)
{
bool usermode = _is_user_context();