From b60ecc8a2dc0c196baeb094e88ff3cd10a6e7bfb Mon Sep 17 00:00:00 2001 From: Benjamin Vedder Date: Sun, 6 Aug 2023 14:47:04 +0200 Subject: [PATCH] Squashed 'lispBM/lispBM/' changes from a20fb514..a33d675a a33d675a Profiler interface changed. Profiler now also reports system overhead in a category by itself. System overhead will be large if all you have are threads that do not use up their quota. git-subtree-dir: lispBM/lispBM git-subtree-split: a33d675ad1befd1f8046a8a3010f3afaa89db907 --- doc/lbmref.md | 20 +++---- include/lbm_prof.h | 9 ++-- repl/repl.c | 33 +++++++----- src/eval_cps.c | 3 ++ src/lbm_prof.c | 131 ++++++++++++++++++++------------------------- 5 files changed, 95 insertions(+), 101 deletions(-) diff --git a/doc/lbmref.md b/doc/lbmref.md index 08e6f764..9efba0c8 100644 --- a/doc/lbmref.md +++ b/doc/lbmref.md @@ -473,13 +473,13 @@ Example that evaluates to 3. Evaluate a list of data where each element represents an expression. Example that results in the value 15: -``` +```clj (define prg '( (+ 1 2) (+ 3 4) (+ 10 5))) (eval-program prg) ``` Example that prints the strings "apa", "bepa" and "cepa": -``` +```clj (define prg '( (print "apa") (print "bepa") (print "cepa"))) (eval-program prg) ``` @@ -1262,7 +1262,7 @@ The `assoc` function looks up the first value in an alist matching a given a key The form of an `assoc` expression is `(assoc alist-expr key-expr)` Example that looks up the value of key `2` in an alist. -``` +```clj # (assoc (list '(1 . horse) '(2 . donkey) '(3 . shark)) 2) > donkey ``` @@ -1276,7 +1276,7 @@ The `cossa` function looks up the first key in an alist that matches a given val The form of an `cossa` expression is `(cossa alist-expr value-expr)` Example that looks up the key for the value `donkey` in an alist. -``` +```clj # (cossa (list '(1 . horse) '(2 . donkey) '(3 . shark)) 'donkey) > 2 ``` @@ -1635,7 +1635,7 @@ Like [recv](./lbmref.md#recv), `recv-to` is used to receive messages but `recv-to` takes an extra timeout argument. The form of an `recv-to` expression is -``` +```clj (recv-to timeout-secs (pattern1 exp1) ... @@ -1647,7 +1647,7 @@ delivered to the waiting process. This `timeout` message can be handled in one of the receive patterns. Example -``` +```clj (recv-to 0.5 ( timeout (handle-timeout)) ( _ (do-something-else))) @@ -1683,13 +1683,13 @@ successful. A flatten expression has the form `(flatten expr)`. Note that `expr` before the flattening. Example: -``` +```clj # (define a (flatten (+ 1 2))) > "" ``` The example above creates a byte-array representating the the value `3`. -``` +```clj # (define a (flatten '(+ 1 2))) > "+" ``` @@ -1704,7 +1704,7 @@ Now the byte-array contains a representation of the list `(+ 1 2)` `unflatten` expression is `(unflatten flat-value)` Example: -``` +```clj # (define a (flatten (+ 1 2))) > "" # (unflatten a) @@ -1713,7 +1713,7 @@ Example: and: -``` +```clj # (define a (flatten '(+ 1 2))) > "+" # (unflatten a) diff --git a/include/lbm_prof.h b/include/lbm_prof.h index fc16c6b2..dbdcb6c0 100644 --- a/include/lbm_prof.h +++ b/include/lbm_prof.h @@ -31,13 +31,12 @@ typedef struct { lbm_uint gc_count; } lbm_prof_t; -bool lbm_prof_init(void (*usleep_fptr)(uint32_t), - lbm_uint sample_interval, - lbm_prof_t *prof_data_buf, +bool lbm_prof_init(lbm_prof_t *prof_data_buf, lbm_uint prof_data_buf_num); lbm_uint lbm_prof_get_num_samples(void); +lbm_uint lbm_prof_get_num_system_samples(void); lbm_uint lbm_prof_get_num_sleep_samples(void); lbm_uint lbm_prof_stop(void); -bool lbm_prof_is_running(void); -void lbm_prof_run(void); +void lbm_prof_sample(void); + #endif diff --git a/repl/repl.c b/repl/repl.c index da0f1914..247160be 100644 --- a/repl/repl.c +++ b/repl/repl.c @@ -177,11 +177,6 @@ void *eval_thd_wrapper(void *v) { return NULL; } -void *prof_thd_wrapper(void *v) { - lbm_prof_run(); - return NULL; -} - void done_callback(eval_context_t *ctx) { erase(); @@ -221,6 +216,15 @@ void sleep_callback(uint32_t us) { nanosleep(&s, &r); } +static bool prof_running = false; + +void *prof_thd(void *v) { + while (prof_running) { + lbm_prof_sample(); + sleep_callback(200); + } + return NULL; +} bool dyn_load(const char *str, const char **code) { bool res = false; @@ -647,12 +651,11 @@ int main(int argc, char **argv) { printf("Symbol names size FLASH: %"PRI_UINT" Bytes\n", lbm_get_symbol_table_size_names_flash()); free(str); } else if (strncmp(str, ":prof start", 11) == 0) { - lbm_prof_init(sleep_callback, - 200, - prof_data, + lbm_prof_init(prof_data, PROF_DATA_NUM); - pthread_t prof_thd; // just forget this id. - if (pthread_create(&prof_thd, NULL, prof_thd_wrapper, NULL)) { + pthread_t thd; // just forget this id. + prof_running = true; + if (pthread_create(&thd, NULL, prof_thd, NULL)) { printf("Error creating profiler thread\n"); free(str); continue; @@ -660,11 +663,12 @@ int main(int argc, char **argv) { printf("Profiler started\n"); free(str); } else if (strncmp(str, ":prof stop", 10) == 0) { + prof_running = false; printf("Profiler stopped. Issue command ':prof report' for statistics\n."); - lbm_prof_stop(); free(str); } else if (strncmp(str, ":prof report", 12) == 0) { lbm_uint num_sleep = lbm_prof_get_num_sleep_samples(); + lbm_uint num_system = lbm_prof_get_num_system_samples(); lbm_uint tot_samples = lbm_prof_get_num_samples(); lbm_uint tot_gc = 0; printf("CID\tName\tSamples\t%%Load\t%%GC\n"); @@ -679,9 +683,10 @@ int main(int argc, char **argv) { 100.0 * ((float)prof_data[i].gc_count) / (float)prof_data[i].count); } printf("\n"); - printf("GC:\t%u\t%f%%\n", tot_gc, 100.0 * (float)tot_gc/(float)tot_samples); - printf("sleep:\t%u\t%f%%\n", num_sleep, 100.0 * (float)num_sleep/(float)tot_samples); - printf("total:\t%u samples\n", tot_samples); + printf("GC:\t%u\t%f%%\n", tot_gc, 100.0 * ((float)tot_gc / (float)tot_samples)); + printf("System:\t%u\t%f%%\n", num_system, 100.0 * ((float)num_system / (float)tot_samples)); + printf("Sleep:\t%u\t%f%%\n", num_sleep, 100.0 * ((float)num_sleep / (float)tot_samples)); + printf("Total:\t%u samples\n", tot_samples); free(str); } else if (strncmp(str, ":env", 4) == 0) { lbm_value curr = *lbm_get_env_ptr(); diff --git a/src/eval_cps.c b/src/eval_cps.c index 99e1de11..fe692a2b 100644 --- a/src/eval_cps.c +++ b/src/eval_cps.c @@ -155,6 +155,7 @@ static bool mailbox_add_mail(eval_context_t *ctx, lbm_value mail); // The currently executing context. eval_context_t *ctx_running = NULL; +volatile bool lbm_system_sleeping = false; static volatile bool gc_requested = false; void lbm_request_gc(void) { @@ -4321,8 +4322,10 @@ void lbm_run_eval(void){ ctx_running = dequeue_ctx_nm(&queue); mutex_unlock(&qmutex); if (!ctx_running) { + lbm_system_sleeping = true; //Fixed sleep interval to poll events regularly. usleep_callback(EVAL_CPS_MIN_SLEEP); + lbm_system_sleeping = false; } } } diff --git a/src/lbm_prof.c b/src/lbm_prof.c index bc8849a1..28546b73 100644 --- a/src/lbm_prof.c +++ b/src/lbm_prof.c @@ -18,28 +18,24 @@ #include "lbm_prof.h" #include "platform_mutex.h" -static lbm_uint sample_interval_us = 200; -static bool lbm_prof_running = false; static lbm_uint num_samples = 0; +static lbm_uint num_system_samples = 0; static lbm_uint num_sleep_samples = 0; -static void (*usleep_callback)(uint32_t) = NULL; extern eval_context_t *ctx_running; extern mutex_t qmutex; extern bool qmutex_initialized; +extern volatile bool lbm_system_sleeping; static lbm_prof_t *prof_data; static lbm_uint prof_data_num; #define TRUNC_SIZE(N) (((N) > LBM_PROF_MAX_NAME_SIZE -1) ? LBM_PROF_MAX_NAME_SIZE-1 : N) -bool lbm_prof_init(void (*usleep_fptr)(uint32_t), - lbm_uint sample_interval, - lbm_prof_t *prof_data_buf, +bool lbm_prof_init(lbm_prof_t *prof_data_buf, lbm_uint prof_data_buf_num) { if (qmutex_initialized && prof_data_buf && prof_data_buf_num > 0) { - usleep_callback = usleep_fptr; - sample_interval_us = sample_interval; num_samples = 0; + num_system_samples = 0; num_sleep_samples = 0; prof_data_num = prof_data_buf_num; prof_data = prof_data_buf; @@ -49,10 +45,6 @@ bool lbm_prof_init(void (*usleep_fptr)(uint32_t), memset(&prof_data_buf[i].name, 0, LBM_PROF_MAX_NAME_SIZE); prof_data_buf[i].count = 0; } - if (usleep_callback != NULL) { - lbm_prof_running = true; - return true; - } } return false; } @@ -61,71 +53,66 @@ lbm_uint lbm_prof_get_num_samples(void) { return num_samples; } +lbm_uint lbm_prof_get_num_system_samples(void) { + return num_system_samples; +} + lbm_uint lbm_prof_get_num_sleep_samples(void) { return num_sleep_samples; } -lbm_uint lbm_prof_stop(void) { - lbm_prof_running = false; - return num_samples; -} +void lbm_prof_sample(void) { + num_samples ++; -bool lbm_prof_is_running(void) { - return lbm_prof_running; -} - -// start in an OS thread. -void lbm_prof_run(void) { - while (lbm_prof_running) { - num_samples ++; - - // Lock mutex so context cannot be destroyed until - // we are done storing a sample. - mutex_lock(&qmutex); - eval_context_t *curr = ctx_running; - if (curr != NULL) { - lbm_cid id = curr->id; - char *name = curr->name; - lbm_uint name_len = 0; - bool doing_gc = false; - if (curr->state & LBM_THREAD_STATE_GC_BIT) { - doing_gc = true; - } - if (name) name_len = strlen(name) + 1; - for (lbm_uint i = 0; i < prof_data_num; i ++) { - if (prof_data[i].cid == -1) { - // add new sample: - prof_data[i].cid = id; - prof_data[i].count = 1; - prof_data[i].gc_count = doing_gc ? 1 : 0; - if (name) { - memcpy(&prof_data[i].name, name, TRUNC_SIZE(name_len)); - prof_data[i].name[LBM_PROF_MAX_NAME_SIZE - 1] = 0; - prof_data[i].has_name = true; - } - break; - } - if (prof_data[i].cid == id && - prof_data[i].has_name && - name != NULL && - strncmp(prof_data[i].name, name, TRUNC_SIZE(name_len)) == 0) { - // found a named existing measurement. - prof_data[i].count ++; - prof_data[i].gc_count += doing_gc ? 1 : 0; - break; - } - if (prof_data[i].cid == id && - !prof_data[i].has_name && - name == NULL) { - prof_data[i].count ++; - prof_data[i].gc_count += doing_gc ? 1 : 0; - break; - } - } - } else { - num_sleep_samples ++; + // Lock mutex so context cannot be destroyed until + // we are done storing a sample. + mutex_lock(&qmutex); + eval_context_t *curr = ctx_running; + if (curr != NULL) { + lbm_cid id = curr->id; + char *name = curr->name; + lbm_uint name_len = 0; + bool doing_gc = false; + if (curr->state & LBM_THREAD_STATE_GC_BIT) { + doing_gc = true; + } + if (name) name_len = strlen(name) + 1; + for (lbm_uint i = 0; i < prof_data_num; i ++) { + if (prof_data[i].cid == -1) { + // add new sample: + prof_data[i].cid = id; + prof_data[i].count = 1; + prof_data[i].gc_count = doing_gc ? 1 : 0; + if (name) { + memcpy(&prof_data[i].name, name, TRUNC_SIZE(name_len)); + prof_data[i].name[LBM_PROF_MAX_NAME_SIZE - 1] = 0; + prof_data[i].has_name = true; + } + break; + } + if (prof_data[i].cid == id && + prof_data[i].has_name && + name != NULL && + strncmp(prof_data[i].name, name, TRUNC_SIZE(name_len)) == 0) { + // found a named existing measurement. + prof_data[i].count ++; + prof_data[i].gc_count += doing_gc ? 1 : 0; + break; + } + if (prof_data[i].cid == id && + !prof_data[i].has_name && + name == NULL) { + prof_data[i].count ++; + prof_data[i].gc_count += doing_gc ? 1 : 0; + break; + } + } + } else { + if (lbm_system_sleeping) { + num_sleep_samples ++; + } else { + num_system_samples ++; } - mutex_unlock(&qmutex); - usleep_callback(sample_interval_us); } + mutex_unlock(&qmutex); }