From 995f0821283aa9adf7cf56f754a3b2efc8582f4b Mon Sep 17 00:00:00 2001 From: Jean-Roland Gosse Date: Thu, 26 Oct 2023 14:25:38 +0200 Subject: [PATCH] Measure wall time in ping tests (#269) --- examples/unix/c11/z_ping.c | 36 ++++++++++++++++++------------- examples/unix/c99/z_ping.c | 36 ++++++++++++++++++------------- examples/windows/z_ping.c | 36 ++++++++++++++++++------------- src/system/arduino/esp32/system.c | 8 +++---- src/system/espidf/system.c | 8 +++---- src/system/unix/system.c | 8 +++---- src/system/zephyr/system.c | 8 +++---- 7 files changed, 79 insertions(+), 61 deletions(-) diff --git a/examples/unix/c11/z_ping.c b/examples/unix/c11/z_ping.c index d3853d475..af13efb2a 100644 --- a/examples/unix/c11/z_ping.c +++ b/examples/unix/c11/z_ping.c @@ -22,6 +22,11 @@ #include "zenoh-pico/system/platform.h" #if Z_FEATURE_SUBSCRIPTION == 1 && Z_FEATURE_PUBLICATION == 1 + +#define DEFAULT_PKT_SIZE 8 +#define DEFAULT_PING_NB 100 +#define DEFAULT_WARMUP_MS 1000 + // WARNING: for the sake of this example we are using "internal" structs and functions (starting with "_"). // Synchronisation primitives are planned to be added to the API in the future. _z_condvar_t cond; @@ -50,11 +55,12 @@ int main(int argc, char** argv) { if (args.help_requested) { printf( "\ - -n (optional, int, default=4): the number of pings to be attempted\n\ - -s (optional, int, default=8): the size of the payload embedded in the ping and repeated by the pong\n\ - -w (optional, int, default=0): the warmup time in ms during which pings will be emitted but not measured\n\ + -n (optional, int, default=%d): the number of pings to be attempted\n\ + -s (optional, int, default=%d): the size of the payload embedded in the ping and repeated by the pong\n\ + -w (optional, int, default=%d): the warmup time in ms during which pings will be emitted but not measured\n\ -c (optional, string): the path to a configuration file for the session. If this option isn't passed, the default configuration will be used.\n\ - "); + ", + DEFAULT_PKT_SIZE, DEFAULT_PING_NB, DEFAULT_WARMUP_MS); return 1; } _z_mutex_init(&mutex); @@ -94,23 +100,23 @@ int main(int argc, char** argv) { _z_mutex_lock(&mutex); if (args.warmup_ms) { printf("Warming up for %dms...\n", args.warmup_ms); - clock_t warmup_end = clock() + CLOCKS_PER_SEC * args.warmup_ms / 1000; - for (clock_t now = clock(); now < warmup_end; now = clock()) { + z_clock_t warmup_start = z_clock_now(); + unsigned long elapsed_us = 0; + while (elapsed_us < args.warmup_ms * 1000) { z_publisher_put(z_loan(pub), data, args.size, NULL); _z_condvar_wait(&cond, &mutex); + elapsed_us = z_clock_elapsed_us(&warmup_start); } } - clock_t* results = z_malloc(sizeof(clock_t) * args.number_of_pings); + unsigned long* results = z_malloc(sizeof(unsigned long) * args.number_of_pings); for (unsigned int i = 0; i < args.number_of_pings; i++) { - clock_t start = clock(); + z_clock_t measure_start = z_clock_now(); z_publisher_put(z_loan(pub), data, args.size, NULL); _z_condvar_wait(&cond, &mutex); - clock_t end = clock(); - results[i] = end - start; + results[i] = z_clock_elapsed_us(&measure_start); } for (unsigned int i = 0; i < args.number_of_pings; i++) { - clock_t rtt = results[i] * 1000000 / CLOCKS_PER_SEC; - printf("%d bytes: seq=%d rtt=%ldµs lat=%ldµs\n", args.size, i, rtt, rtt / 2); + printf("%d bytes: seq=%d rtt=%luµs, lat=%luµs\n", args.size, i, results[i], results[i] / 2); } _z_mutex_unlock(&mutex); z_free(results); @@ -145,17 +151,17 @@ struct args_t parse_args(int argc, char** argv) { } } char* arg = getopt(argc, argv, 's'); - unsigned int size = 8; + unsigned int size = DEFAULT_PKT_SIZE; if (arg) { size = atoi(arg); } arg = getopt(argc, argv, 'n'); - unsigned int number_of_pings = 4; + unsigned int number_of_pings = DEFAULT_PING_NB; if (arg) { number_of_pings = atoi(arg); } arg = getopt(argc, argv, 'w'); - unsigned int warmup_ms = 0; + unsigned int warmup_ms = DEFAULT_WARMUP_MS; if (arg) { warmup_ms = atoi(arg); } diff --git a/examples/unix/c99/z_ping.c b/examples/unix/c99/z_ping.c index 451a8fc30..94fe42424 100644 --- a/examples/unix/c99/z_ping.c +++ b/examples/unix/c99/z_ping.c @@ -23,6 +23,11 @@ #include "zenoh-pico/system/platform.h" #if Z_FEATURE_SUBSCRIPTION == 1 && Z_FEATURE_PUBLICATION == 1 + +#define DEFAULT_PKT_SIZE 8 +#define DEFAULT_PING_NB 100 +#define DEFAULT_WARMUP_MS 1000 + _z_condvar_t cond; _z_mutex_t mutex; @@ -49,11 +54,12 @@ int main(int argc, char** argv) { if (args.help_requested) { printf( "\ - -n (optional, int, default=4): the number of pings to be attempted\n\ - -s (optional, int, default=8): the size of the payload embedded in the ping and repeated by the pong\n\ - -w (optional, int, default=0): the warmup time in ms during which pings will be emitted but not measured\n\ + -n (optional, int, default=%d): the number of pings to be attempted\n\ + -s (optional, int, default=%d): the size of the payload embedded in the ping and repeated by the pong\n\ + -w (optional, int, default=%d): the warmup time in ms during which pings will be emitted but not measured\n\ -c (optional, string): the path to a configuration file for the session. If this option isn't passed, the default configuration will be used.\n\ - "); + ", + DEFAULT_PKT_SIZE, DEFAULT_PING_NB, DEFAULT_WARMUP_MS); return 1; } _z_mutex_init(&mutex); @@ -94,23 +100,23 @@ int main(int argc, char** argv) { _z_mutex_lock(&mutex); if (args.warmup_ms) { printf("Warming up for %dms...\n", args.warmup_ms); - clock_t warmup_end = clock() + CLOCKS_PER_SEC * args.warmup_ms / 1000; - for (clock_t now = clock(); now < warmup_end; now = clock()) { + z_clock_t warmup_start = z_clock_now(); + unsigned long elapsed_us = 0; + while (elapsed_us < args.warmup_ms * 1000) { z_publisher_put(z_publisher_loan(&pub), data, args.size, NULL); _z_condvar_wait(&cond, &mutex); + elapsed_us = z_clock_elapsed_us(&warmup_start); } } - clock_t* results = z_malloc(sizeof(clock_t) * args.number_of_pings); + unsigned long* results = z_malloc(sizeof(unsigned long) * args.number_of_pings); for (unsigned int i = 0; i < args.number_of_pings; i++) { - clock_t start = clock(); + z_clock_t measure_start = z_clock_now(); z_publisher_put(z_publisher_loan(&pub), data, args.size, NULL); _z_condvar_wait(&cond, &mutex); - clock_t end = clock(); - results[i] = end - start; + results[i] = z_clock_elapsed_us(&measure_start); } for (unsigned int i = 0; i < args.number_of_pings; i++) { - clock_t rtt = results[i] * 1000000 / CLOCKS_PER_SEC; - printf("%d bytes: seq=%d rtt=%ldµs lat=%ldµs\n", args.size, i, rtt, rtt / 2); + printf("%d bytes: seq=%d rtt=%luµs, lat=%luµs\n", args.size, i, results[i], results[i] / 2); } _z_mutex_unlock(&mutex); z_free(results); @@ -145,17 +151,17 @@ struct args_t parse_args(int argc, char** argv) { } } char* arg = getopt(argc, argv, 's'); - unsigned int size = 8; + unsigned int size = DEFAULT_PKT_SIZE; if (arg) { size = atoi(arg); } arg = getopt(argc, argv, 'n'); - unsigned int number_of_pings = 4; + unsigned int number_of_pings = DEFAULT_PING_NB; if (arg) { number_of_pings = atoi(arg); } arg = getopt(argc, argv, 'w'); - unsigned int warmup_ms = 0; + unsigned int warmup_ms = DEFAULT_WARMUP_MS; if (arg) { warmup_ms = atoi(arg); } diff --git a/examples/windows/z_ping.c b/examples/windows/z_ping.c index da6cb75db..f1a218386 100644 --- a/examples/windows/z_ping.c +++ b/examples/windows/z_ping.c @@ -22,6 +22,11 @@ #include "zenoh-pico/system/platform.h" #if Z_FEATURE_SUBSCRIPTION == 1 && Z_FEATURE_PUBLICATION == 1 + +#define DEFAULT_PKT_SIZE 8 +#define DEFAULT_PING_NB 100 +#define DEFAULT_WARMUP_MS 1000 + _z_condvar_t cond; _z_mutex_t mutex; @@ -48,11 +53,12 @@ int main(int argc, char** argv) { if (args.help_requested) { printf( "\ - -n (optional, int, default=4): the number of pings to be attempted\n\ - -s (optional, int, default=8): the size of the payload embedded in the ping and repeated by the pong\n\ - -w (optional, int, default=0): the warmup time in ms during which pings will be emitted but not measured\n\ + -n (optional, int, default=%d): the number of pings to be attempted\n\ + -s (optional, int, default=%d): the size of the payload embedded in the ping and repeated by the pong\n\ + -w (optional, int, default=%d): the warmup time in ms during which pings will be emitted but not measured\n\ -c (optional, string): the path to a configuration file for the session. If this option isn't passed, the default configuration will be used.\n\ - "); + ", + DEFAULT_PKT_SIZE, DEFAULT_PING_NB, DEFAULT_WARMUP_MS); return 1; } _z_mutex_init(&mutex); @@ -91,23 +97,23 @@ int main(int argc, char** argv) { _z_mutex_lock(&mutex); if (args.warmup_ms) { printf("Warming up for %dms...\n", args.warmup_ms); - clock_t warmup_end = clock() + CLOCKS_PER_SEC * args.warmup_ms / 1000; - for (clock_t now = clock(); now < warmup_end; now = clock()) { + z_clock_t warmup_start = z_clock_now(); + unsigned long elapsed_us = 0; + while (elapsed_us < args.warmup_ms * 1000) { z_publisher_put(z_loan(pub), data, args.size, NULL); _z_condvar_wait(&cond, &mutex); + elapsed_us = z_clock_elapsed_us(&warmup_start); } } - clock_t* results = z_malloc(sizeof(clock_t) * args.number_of_pings); + unsigned long* results = z_malloc(sizeof(unsigned long) * args.number_of_pings); for (unsigned int i = 0; i < args.number_of_pings; i++) { - clock_t start = clock(); + z_clock_t measure_start = z_clock_now(); z_publisher_put(z_loan(pub), data, args.size, NULL); _z_condvar_wait(&cond, &mutex); - clock_t end = clock(); - results[i] = end - start; + results[i] = z_clock_elapsed_us(&measure_start); } for (unsigned int i = 0; i < args.number_of_pings; i++) { - clock_t rtt = results[i] * 1000000 / CLOCKS_PER_SEC; - printf("%d bytes: seq=%d rtt=%ldµs lat=%ldµs\n", args.size, i, rtt, rtt / 2); + printf("%d bytes: seq=%d rtt=%luµs, lat=%luµs\n", args.size, i, results[i], results[i] / 2); } _z_mutex_unlock(&mutex); z_free(results); @@ -142,17 +148,17 @@ struct args_t parse_args(int argc, char** argv) { } } char* arg = getopt(argc, argv, 's'); - unsigned int size = 8; + unsigned int size = DEFAULT_PKT_SIZE; if (arg) { size = atoi(arg); } arg = getopt(argc, argv, 'n'); - unsigned int number_of_pings = 4; + unsigned int number_of_pings = DEFAULT_PING_NB; if (arg) { number_of_pings = atoi(arg); } arg = getopt(argc, argv, 'w'); - unsigned int warmup_ms = 0; + unsigned int warmup_ms = DEFAULT_WARMUP_MS; if (arg) { warmup_ms = atoi(arg); } diff --git a/src/system/arduino/esp32/system.c b/src/system/arduino/esp32/system.c index a9eab813c..8f0773751 100644 --- a/src/system/arduino/esp32/system.c +++ b/src/system/arduino/esp32/system.c @@ -135,13 +135,13 @@ int z_sleep_s(size_t time) { return sleep(time); } /*------------------ Instant ------------------*/ z_clock_t z_clock_now(void) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); return now; } unsigned long z_clock_elapsed_us(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000); return elapsed; @@ -149,7 +149,7 @@ unsigned long z_clock_elapsed_us(z_clock_t *instant) { unsigned long z_clock_elapsed_ms(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000000); return elapsed; @@ -157,7 +157,7 @@ unsigned long z_clock_elapsed_ms(z_clock_t *instant) { unsigned long z_clock_elapsed_s(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = now.tv_sec - instant->tv_sec; return elapsed; diff --git a/src/system/espidf/system.c b/src/system/espidf/system.c index 8a655cf0d..a93c5b0e5 100644 --- a/src/system/espidf/system.c +++ b/src/system/espidf/system.c @@ -136,13 +136,13 @@ int z_sleep_s(size_t time) { return sleep(time); } /*------------------ Instant ------------------*/ z_clock_t z_clock_now(void) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); return now; } unsigned long z_clock_elapsed_us(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000); return elapsed; @@ -150,7 +150,7 @@ unsigned long z_clock_elapsed_us(z_clock_t *instant) { unsigned long z_clock_elapsed_ms(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000000); return elapsed; @@ -158,7 +158,7 @@ unsigned long z_clock_elapsed_ms(z_clock_t *instant) { unsigned long z_clock_elapsed_s(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = now.tv_sec - instant->tv_sec; return elapsed; diff --git a/src/system/unix/system.c b/src/system/unix/system.c index 875bc5f2b..990619dac 100644 --- a/src/system/unix/system.c +++ b/src/system/unix/system.c @@ -156,13 +156,13 @@ int z_sleep_s(size_t time) { return sleep(time); } /*------------------ Instant ------------------*/ z_clock_t z_clock_now(void) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); return now; } unsigned long z_clock_elapsed_us(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000); return elapsed; @@ -170,7 +170,7 @@ unsigned long z_clock_elapsed_us(z_clock_t *instant) { unsigned long z_clock_elapsed_ms(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000000); return elapsed; @@ -178,7 +178,7 @@ unsigned long z_clock_elapsed_ms(z_clock_t *instant) { unsigned long z_clock_elapsed_s(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = now.tv_sec - instant->tv_sec; return elapsed; diff --git a/src/system/zephyr/system.c b/src/system/zephyr/system.c index 28ce1d303..20e54d146 100644 --- a/src/system/zephyr/system.c +++ b/src/system/zephyr/system.c @@ -150,13 +150,13 @@ int z_sleep_s(size_t time) { /*------------------ Instant ------------------*/ z_clock_t z_clock_now(void) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); return now; } unsigned long z_clock_elapsed_us(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000); return elapsed; @@ -164,7 +164,7 @@ unsigned long z_clock_elapsed_us(z_clock_t *instant) { unsigned long z_clock_elapsed_ms(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = (1000 * (now.tv_sec - instant->tv_sec) + (now.tv_nsec - instant->tv_nsec) / 1000000); return elapsed; @@ -172,7 +172,7 @@ unsigned long z_clock_elapsed_ms(z_clock_t *instant) { unsigned long z_clock_elapsed_s(z_clock_t *instant) { z_clock_t now; - clock_gettime(CLOCK_REALTIME, &now); + clock_gettime(CLOCK_MONOTONIC, &now); unsigned long elapsed = now.tv_sec - instant->tv_sec; return elapsed;