diff --git a/Makefile b/Makefile index 00a5024..fdd3fda 100644 --- a/Makefile +++ b/Makefile @@ -19,7 +19,7 @@ export DSE_SCHEMA_URL ?= $(DSE_SCHEMA_REPO)/releases/download/v$(DSE_SCHEMA_VERS ############### ## DSE C Library. DSE_CLIB_REPO ?= https://github.com/boschglobal/dse.clib -DSE_CLIB_VERSION ?= 1.0.5 +DSE_CLIB_VERSION ?= 1.0.6 export DSE_CLIB_URL ?= $(DSE_CLIB_REPO)/archive/refs/tags/v$(DSE_CLIB_VERSION).zip @@ -178,7 +178,7 @@ do-test_cmocka-run: do-test_pytest-run: @-pip install -r tests/pytest/requirements.txt redis-cli -h $(REDIS_HOST) ping - pytest -rx --asyncio-mode=strict -W ignore::DeprecationWarning tests/pytest + pytest -rx -x --asyncio-mode=strict -W ignore::DeprecationWarning tests/pytest do-clean: @for d in $(SUBDIRS); do ($(MAKE) -C $$d clean ); done diff --git a/dse/modelc/adapter/CMakeLists.txt b/dse/modelc/adapter/CMakeLists.txt index 0f2d500..3b515b4 100644 --- a/dse/modelc/adapter/CMakeLists.txt +++ b/dse/modelc/adapter/CMakeLists.txt @@ -32,6 +32,7 @@ add_library(adapter OBJECT message.c simbus/adapter.c simbus/handler.c + simbus/profile.c simbus/states.c transport/endpoint.c # transport/mq.c diff --git a/dse/modelc/adapter/adapter.c b/dse/modelc/adapter/adapter.c index 66b13db..e27ab08 100644 --- a/dse/modelc/adapter/adapter.c +++ b/dse/modelc/adapter/adapter.c @@ -11,6 +11,7 @@ #include #include #include +#include #include #include #include @@ -23,6 +24,7 @@ typedef struct notify_spec_t { Adapter* adapter; notify(NotifyMessage_table_t) message; flatcc_builder_t* builder; + struct timespec notifyrecv_ts; } notify_spec_t; @@ -559,6 +561,10 @@ static int _adapter_model_ready(AdapterModel* am) notify(NotifyMessage_signals_add(builder, signals)); notify(NotifyMessage_model_uid_add(builder, model_uids)); notify(NotifyMessage_model_time_add(builder, am->model_time)); + notify( + NotifyMessage_bench_model_time_ns_add(builder, am->bench_steptime_ns)); + notify(NotifyMessage_bench_notify_time_ns_add(builder, + get_elapsedtime_ns(am->bench_notifyrecv_ts) - am->bench_steptime_ns)); notify(NotifyMessage_ref_t) message = notify(NotifyMessage_end(builder)); send_notify_message(adapter, message); @@ -1036,6 +1042,7 @@ static int notify_model(void* value, void* data) { AdapterModel* am = value; notify_spec_t* notify_data = data; + am->bench_notifyrecv_ts = notify_data->notifyrecv_ts; notify(NotifyMessage_table_t) message = notify_data->message; log_simbus("Notify/ModelStart <-- [%u]", am->model_uid); am->model_time = notify(NotifyMessage_model_time(message)); @@ -1086,6 +1093,7 @@ static void handle_notify_message( notify_spec_t notify_data = { .adapter = adapter, .message = notify_message, + .notifyrecv_ts = get_timespec_now(), }; hashmap_iterator(&adapter->models, notify_model, true, ¬ify_data); } diff --git a/dse/modelc/adapter/adapter.h b/dse/modelc/adapter/adapter.h index 9a6cbf0..45b74db 100644 --- a/dse/modelc/adapter/adapter.h +++ b/dse/modelc/adapter/adapter.h @@ -8,6 +8,7 @@ #include #include +#include #include #include #include @@ -64,16 +65,19 @@ typedef struct Adapter Adapter; typedef struct AdapterModel { /* Model properties. */ - uint32_t model_uid; - double model_time; - double stop_time; + uint32_t model_uid; + double model_time; + double stop_time; /* Channel properties. */ - HashMap channels; // Collection of Channel, key is name. - char** channels_keys; // Cached result of hashmap_keys, update on - // hashmap_set/remove. - uint32_t channels_length; - - Adapter* adapter; // back reference ?? Model Instance ?? + HashMap channels; // Collection of Channel, key is name. + char** channels_keys; // Cached result of hashmap_keys, update on + // hashmap_set/remove. + uint32_t channels_length; + /* Reference objects. */ + Adapter* adapter; + /* Benchmarking/Profiling. */ + struct timespec bench_notifyrecv_ts; + uint64_t bench_steptime_ns; } AdapterModel; @@ -89,6 +93,10 @@ typedef struct Adapter { /* Endpoint container. */ Endpoint* endpoint; + + /* Benchmarking/Profiling. */ + struct timespec bench_notifysend_ts; + /* Private object supporting the operation of the Adapter.*/ void* private; } Adapter; diff --git a/dse/modelc/adapter/simbus/adapter.c b/dse/modelc/adapter/simbus/adapter.c index 9e47f4c..c62515e 100644 --- a/dse/modelc/adapter/simbus/adapter.c +++ b/dse/modelc/adapter/simbus/adapter.c @@ -46,6 +46,9 @@ Adapter* simbus_adapter_create(void* endpoint, double bus_step_size) adapter->bus_adapter_model->adapter = adapter; adapter->bus_adapter_model->model_uid = adapter->endpoint->uid; + /* Benchmarking/Profiling. */ + simbus_profile_init(bus_step_size); + return adapter; } @@ -112,4 +115,8 @@ void simbus_adapter_run(Adapter* adapter) } log_simbus("exit run loop"); + + /* Benchmarking/Profiling. */ + simbus_profile_print_benchmarks(); + simbus_profile_destroy(); } diff --git a/dse/modelc/adapter/simbus/handler.c b/dse/modelc/adapter/simbus/handler.c index fe1aba9..85cf405 100644 --- a/dse/modelc/adapter/simbus/handler.c +++ b/dse/modelc/adapter/simbus/handler.c @@ -7,6 +7,7 @@ #include #include #include +#include #include @@ -620,6 +621,26 @@ void simbus_handle_notify_message( log_simbus("Notify/ModelReady <--"); log_simbus(" model_time=%f", model_time); + /* Benchmarking/Profiling. */ + if (adapter->bus_time > 0.0) { + struct timespec ref_ts = get_timespec_now(); + uint64_t model_exec_time = + notify(NotifyMessage_bench_model_time_ns(notify_message)); + uint64_t model_proc_time = + notify(NotifyMessage_bench_notify_time_ns(notify_message)); + uint64_t network_time_ns = + get_deltatime_ns(adapter->bench_notifysend_ts, ref_ts) - + (model_proc_time + model_exec_time); + flatbuffers_uint32_vec_t vector = + notify(NotifyMessage_model_uid(notify_message)); + size_t vector_len = flatbuffers_uint32_vec_len(vector); + for (uint32_t _vi = 0; _vi < vector_len; _vi++) { + uint32_t model_uid = flatbuffers_uint32_vec_at(vector, _vi); + simbus_profile_accumulate_model_part(model_uid, model_exec_time, + model_proc_time, network_time_ns, ref_ts); + } + } + /* Handle embedded SignalVector tables. */ notify(SignalVector_vec_t) vector = notify(NotifyMessage_signals(notify_message)); @@ -663,6 +684,17 @@ void simbus_handle_notify_message( double model_time = adapter->bus_time; double stop_time = model_time + adapter->bus_step_size; + /* Benchmarking/Profiling. */ + if (adapter->bus_time > 0.0) { + struct timespec ref_ts = get_timespec_now(); + uint64_t simbus_cycle_total_ns = + get_deltatime_ns(adapter->bench_notifysend_ts, ref_ts); + simbus_profile_accumulate_cycle_total( + simbus_cycle_total_ns, ref_ts); + } + adapter->bench_notifysend_ts = get_timespec_now(); + + /* Notify/ModelStart. */ resolve_and_notify(adapter, model_time, stop_time); simbus_models_to_start(am); } diff --git a/dse/modelc/adapter/simbus/profile.c b/dse/modelc/adapter/simbus/profile.c new file mode 100644 index 0000000..24f5fc9 --- /dev/null +++ b/dse/modelc/adapter/simbus/profile.c @@ -0,0 +1,306 @@ +// Copyright 2024 Robert Bosch GmbH +// +// SPDX-License-Identifier: Apache-2.0 + +#include +#include +#include +#include + + +/* +Profiling and Benchmarks +======================== + +Fields +------ +__ME__ (Model Execute Time) +: Time to complete the model do_step() function. + +__MP__ (Model Processing Time) +: Time to respond to a Notify message (receive ModelStart then respond + ModelReady) minus the Model Execute Time. This value represents the ModelC + processing overhead. + +__NET__ (Network Time) +: The amount of time taken to transmit and receive Notify messages. This value + is calculated at the SimBus: + Time(Notify RX) - Time(Notify TX) - (ME + MP) + +__SW__ (SimBus Wait Time) +: The amount of time the SimBus algorithm waits before processing a particular + models Notify data. The SimBus algorithm waits for _all_ models before it can +processes Notify data. + +__SP__ (SimBus Processing Time) +: The time spent by the SimBus to process the incoming Notify messages. This +is a derived value: +Time(Model Total) = ME + MP + NET +Time(SP) = Total - Model Total - SW + +__Total__ (Total Time) +: The total time. + +*/ + + +#define UNUSED(x) ((void)x) +#define UINT32_STR_MAX_LEN 11 + + +typedef struct ModelBenchmarkProfile { + uint32_t model_uid; + struct timespec wait_ref_ts; + + /* Last sample. */ + uint64_t sam_model_execute_ns; + uint64_t sam_model_proc_ns; + uint64_t sam_network_ns; + uint64_t sam_simbus_wait_ns; + uint64_t sam_total_ns; + + /* Accumulators. */ + uint64_t acc_model_execute_ns; + uint64_t acc_model_proc_ns; + uint64_t acc_network_ns; + uint64_t acc_simbus_wait_ns; + uint64_t acc_total_ns; + + /* Averages. */ + uint32_t ma_sample_count; + double ma_model_execute; + double ma_model_proc; + double ma_network; + double ma_simbus_wait; + double ma_simbus_proc; + double ma_total; +} ModelBenchmarkProfile; + + +static HashMap __model_data; +static uint32_t __accumulate_sample_count; +static uint32_t __accumulate_on_sample; + + +void simbus_profile_init(double bus_step_size) +{ + hashmap_init_alt(&__model_data, 64, NULL); + __accumulate_on_sample = 1.0 / bus_step_size; +} + + +void simbus_profile_destroy(void) +{ + hashmap_destroy_ext(&__model_data, NULL, NULL); +} + + +static ModelBenchmarkProfile* _get_mbp(uint32_t model_uid) +{ + static char key[UINT32_STR_MAX_LEN]; + + snprintf(key, UINT32_STR_MAX_LEN, "%u", model_uid); + ModelBenchmarkProfile* mbp = hashmap_get(&__model_data, key); + if (mbp == NULL) { + mbp = calloc(1, sizeof(ModelBenchmarkProfile)); + mbp->model_uid = model_uid; + hashmap_set(&__model_data, key, mbp); + } + return mbp; +} + + +static inline double _ns_to_us_to_sec(uint64_t t_ns) +{ + uint32_t t_us = t_ns / 1000; + return t_us / 1000000.0; +} + +static inline double _ma(double val, double mean, uint32_t n) +{ + double delta = val - mean; + mean += delta / (double)n; + return mean; +} + +static void simbus_profile_update_averages(ModelBenchmarkProfile* mbp) +{ + if (__accumulate_sample_count == 0) return; + + /* Collect this accumulation cycle. */ + double model_execute = _ns_to_us_to_sec(mbp->acc_model_execute_ns); + double model_proc = _ns_to_us_to_sec(mbp->acc_model_proc_ns); + double network = _ns_to_us_to_sec(mbp->acc_network_ns); + double simbus_wait = _ns_to_us_to_sec(mbp->acc_simbus_wait_ns); + double total = _ns_to_us_to_sec(mbp->acc_total_ns); + double model_total = model_execute + model_proc + network; + double simbus_proc = mbp->ma_total - model_total - mbp->ma_simbus_wait; + if (__accumulate_sample_count < __accumulate_on_sample) { + /* Normalise the accumulator samples to full 1.0 second. */ + double factor = __accumulate_on_sample / __accumulate_sample_count; + model_execute *= factor; + model_proc *= factor; + network *= factor; + simbus_wait *= factor; + total *= factor; + model_total *= factor; + simbus_proc *= factor; + } + + /* Moving average according to Welford's algorithm. */ + mbp->ma_sample_count++; + if (mbp->ma_sample_count == 1) { + mbp->ma_model_execute = model_execute; + mbp->ma_model_proc = model_proc; + mbp->ma_network = network; + mbp->ma_simbus_wait = simbus_wait; + mbp->ma_total = total; + model_total = + mbp->ma_model_execute + mbp->ma_model_proc + mbp->ma_network; + mbp->ma_simbus_proc = mbp->ma_total - model_total - mbp->ma_simbus_wait; + } else { + uint32_t n = mbp->ma_sample_count; + mbp->ma_model_execute = _ma(model_execute, mbp->ma_model_execute, n); + mbp->ma_model_proc = _ma(model_proc, mbp->ma_model_proc, n); + mbp->ma_network = _ma(network, mbp->ma_network, n); + mbp->ma_simbus_wait = _ma(simbus_wait, mbp->ma_simbus_wait, n); + mbp->ma_total = _ma(total, mbp->ma_total, n); + model_total = + mbp->ma_model_execute + mbp->ma_model_proc + mbp->ma_network; + mbp->ma_simbus_proc = mbp->ma_total - model_total - mbp->ma_simbus_wait; + } +} + + +void simbus_profile_accumulate_model_part(uint32_t model_uid, uint64_t me, + uint64_t mp, uint64_t net, struct timespec ref_ts) +{ + ModelBenchmarkProfile* mbp = _get_mbp(model_uid); + + /* Sample. */ + mbp->sam_model_execute_ns = me; + mbp->sam_model_proc_ns = mp; + mbp->sam_network_ns = net; + + /* Accumulate. */ + mbp->acc_model_execute_ns += me; + mbp->acc_model_proc_ns += mp; + mbp->acc_network_ns += net; + + /* Set reference time for simbus part. */ + mbp->wait_ref_ts = ref_ts; +} + + +typedef struct SimbusCycleData { + uint64_t cycle_total_ns; + struct timespec ref_ts; +} SimbusCycleData; + +static int _acc_simbus_part(void* map_item, void* additional_data) +{ + ModelBenchmarkProfile* mbp = map_item; + SimbusCycleData* data = additional_data; + uint64_t simbus_wait_ns = get_deltatime_ns(mbp->wait_ref_ts, data->ref_ts); + + /* Accumulate. */ + mbp->sam_simbus_wait_ns = simbus_wait_ns; + mbp->sam_total_ns = data->cycle_total_ns; + + /* Accumulate. */ + mbp->acc_simbus_wait_ns += simbus_wait_ns; + mbp->acc_total_ns += data->cycle_total_ns; + __accumulate_sample_count++; + + /* Averages. */ + if (__accumulate_sample_count >= __accumulate_on_sample) { + simbus_profile_update_averages(mbp); + /* Reset accumulators. */ + mbp->acc_model_execute_ns = 0; + mbp->acc_model_proc_ns = 0; + mbp->acc_network_ns = 0; + mbp->acc_simbus_wait_ns = 0; + mbp->acc_total_ns = 0; + __accumulate_sample_count = 0; + } + + return 0; +} + +void simbus_profile_accumulate_cycle_total( + uint64_t simbus_cycle_total_ns, struct timespec ref_ts) +{ + SimbusCycleData data = { + .cycle_total_ns = simbus_cycle_total_ns, + .ref_ts = ref_ts, + }; + hashmap_iterator(&__model_data, _acc_simbus_part, false, &data); +} + + +static int _print_benchmark(void* map_item, void* additional_data) +{ + UNUSED(additional_data); + ModelBenchmarkProfile* mbp = map_item; + simbus_profile_update_averages(mbp); + log_notice(" %-9u %-11.6f %-11.6f %-11.6f %-11.6f %-8.3f %-8.3f", + mbp->model_uid, mbp->ma_model_execute, mbp->ma_model_proc, + mbp->ma_network, mbp->ma_simbus_wait, mbp->ma_simbus_proc, + mbp->ma_total); + return 0; +} + +static int _print_benchmark_acc(void* map_item, void* additional_data) +{ + UNUSED(additional_data); + ModelBenchmarkProfile* mbp = map_item; + + double model_execute = _ns_to_us_to_sec(mbp->acc_model_execute_ns); + double model_proc = _ns_to_us_to_sec(mbp->acc_model_proc_ns); + double network = _ns_to_us_to_sec(mbp->acc_network_ns); + double simbus_wait = _ns_to_us_to_sec(mbp->acc_simbus_wait_ns); + double total = _ns_to_us_to_sec(mbp->acc_total_ns); + double model_total = model_execute + model_proc + network; + double simbus_proc = total - model_total - simbus_wait; + + log_notice(" %-9u %-11.6f %-11.6f %-11.6f %-11.6f %-8.3f %-8.3f", + mbp->model_uid, model_execute, model_proc, network, simbus_wait, + simbus_proc, total); + return 0; +} + +static int _print_benchmark_sam(void* map_item, void* additional_data) +{ + UNUSED(additional_data); + ModelBenchmarkProfile* mbp = map_item; + + double model_execute = _ns_to_us_to_sec(mbp->sam_model_execute_ns); + double model_proc = _ns_to_us_to_sec(mbp->sam_model_proc_ns); + double network = _ns_to_us_to_sec(mbp->sam_network_ns); + double simbus_wait = _ns_to_us_to_sec(mbp->sam_simbus_wait_ns); + double total = _ns_to_us_to_sec(mbp->sam_total_ns); + double model_total = model_execute + model_proc + network; + double simbus_proc = total - model_total - simbus_wait; + + log_notice(" %-9u %-11.6f %-11.6f %-11.6f %-11.6f %-8.3f %-8.3f", + mbp->model_uid, model_execute, model_proc, network, simbus_wait, + simbus_proc, total); + return 0; +} + +void simbus_profile_print_benchmarks(void) +{ + log_notice("Profile/Benchmark Data:"); + log_notice(" Normalised: (relative to 1.0 second simulation time)"); + log_notice(" model_uid ME MP NET SW " + "SP Total"); + hashmap_iterator(&__model_data, _print_benchmark, false, NULL); + log_notice(" Accumulators: (raw accumulated sample data)"); + log_notice(" model_uid ME MP NET SW " + "SP Total"); + hashmap_iterator(&__model_data, _print_benchmark_acc, false, NULL); + log_notice(" Samples: (last sample data)"); + log_notice(" model_uid ME MP NET SW " + "SP Total"); + hashmap_iterator(&__model_data, _print_benchmark_sam, false, NULL); +} diff --git a/dse/modelc/adapter/simbus/simbus_private.h b/dse/modelc/adapter/simbus/simbus_private.h index e1e12a4..c637b87 100644 --- a/dse/modelc/adapter/simbus/simbus_private.h +++ b/dse/modelc/adapter/simbus/simbus_private.h @@ -8,6 +8,7 @@ #include #include +#include #include #include #include @@ -35,6 +36,16 @@ DLL_PRIVATE void simbus_handle_notify_message( Adapter* adapter, notify(NotifyMessage_table_t) notify_message); +/* profile.c */ +DLL_PRIVATE void simbus_profile_init(double bus_step_size); +DLL_PRIVATE void simbus_profile_accumulate_model_part(uint32_t model_uid, + uint64_t me, uint64_t mp, uint64_t net, struct timespec ref_ts); +DLL_PRIVATE void simbus_profile_accumulate_cycle_total( + uint64_t simbus_cycle_total_ns, struct timespec ref_ts); +DLL_PRIVATE void simbus_profile_print_benchmarks(void); +DLL_PRIVATE void simbus_profile_destroy(void); + + /* states.c */ DLL_PRIVATE bool simbus_network_ready(AdapterModel* am); DLL_PRIVATE bool simbus_models_ready(AdapterModel* am); diff --git a/dse/modelc/adapter/timer.h b/dse/modelc/adapter/timer.h new file mode 100644 index 0000000..5cedaa8 --- /dev/null +++ b/dse/modelc/adapter/timer.h @@ -0,0 +1,54 @@ +// Copyright 2024 Robert Bosch GmbH +// +// SPDX-License-Identifier: Apache-2.0 + +#ifndef DSE_MODELC_ADAPTER_TIMER_H_ +#define DSE_MODELC_ADAPTER_TIMER_H_ + + +#include +#include + + +inline struct timespec get_timespec_now(void) +{ + struct timespec ts = {}; + clock_gettime(CLOCK_MONOTONIC_RAW, &ts); + return ts; +} + + +inline uint64_t get_elapsedtime_us(struct timespec ref) +{ + struct timespec now = get_timespec_now(); + uint64_t u_sec = (now.tv_sec * 1000000 + now.tv_sec / 1000) - + (ref.tv_sec * 1000000 + ref.tv_sec / 1000); + return u_sec; +} + + +inline uint64_t get_elapsedtime_ns(struct timespec ref) +{ + struct timespec now = get_timespec_now(); + if (ref.tv_sec == now.tv_sec) { + return now.tv_nsec - ref.tv_nsec; + } else { + return ((now.tv_sec - ref.tv_sec) * 1000000000) + + (now.tv_nsec - ref.tv_nsec); + } +} + + +inline uint64_t get_deltatime_ns( + struct timespec from_ref, struct timespec to_ref) +{ + if (from_ref.tv_sec == to_ref.tv_sec) { + return to_ref.tv_nsec - from_ref.tv_nsec; + } else { + return ((to_ref.tv_sec - from_ref.tv_sec) * 1000000000) + + (to_ref.tv_nsec - from_ref.tv_nsec); + } +} + + +#endif // DSE_MODELC_ADAPTER_TIMER_H_ diff --git a/dse/modelc/controller/step.c b/dse/modelc/controller/step.c index a4e102c..5669fcb 100644 --- a/dse/modelc/controller/step.c +++ b/dse/modelc/controller/step.c @@ -8,6 +8,7 @@ #include #include #include +#include #include #include @@ -43,9 +44,12 @@ int step_model(ModelInstanceSpec* mi, double* model_time) AdapterModel* am = mip->adapter_model; /* Step the Model (i.e. call registered Model Functions). */ - mf_step_data step_data = { mi, am->model_time, am->stop_time }; - HashMap* mf_map = &cm->model_functions; + mf_step_data step_data = { mi, am->model_time, am->stop_time }; + HashMap* mf_map = &cm->model_functions; + struct timespec stepcall_ts = get_timespec_now(); int rc = hashmap_iterator(mf_map, _do_step_func, false, &step_data); + am->bench_steptime_ns = get_elapsedtime_ns(stepcall_ts); + /* Update the Model times. */ am->model_time = am->stop_time; *model_time = am->model_time;