diff --git a/README.md b/README.md index b85bdd3..6107596 100644 --- a/README.md +++ b/README.md @@ -10,51 +10,41 @@ It builds on a baseline that simulates the sort of device you might be adding th measures itself: see [docs/baseline.md](docs/baseline.md) for what the baseline is, how the figures are made, and how to run it. -## This stage — Sequence numbers +## This stage — Buffered -Add the first structured-data element, `SolidSyslogMetaSd`, carrying a sequence number. Elements -are supplied to the logger as an array and read on every record, so they must outlive the call that -creates the logger. +A `SolidSyslogCircularBuffer` between `SolidSyslog_Log` and the sender, drained by a service task +calling `SolidSyslog_Service`. `SolidSyslog_Log` formats, enqueues and returns; the service task +does the I/O. ```c -static struct SolidSyslogStructuredData* sd[1]; - -struct SolidSyslogMetaSdConfig metaConfig = { - .Counter = SolidSyslogStdAtomicCounter_Create(), -}; -sd[0] = SolidSyslogMetaSd_Create(&metaConfig); - -struct SolidSyslogConfig config = { - /* ... */ - .Sd = sd, - .SdCount = 1U, -}; -``` +static uint8_t s_ring[SOLIDSYSLOG_CIRCULAR_BUFFER_RING_BYTES(SYSLOG_BUFFER_RECORDS)]; -```text -... BOOT [meta sequenceId="1"] device started +.Buffer = SolidSyslogCircularBuffer_Create(SolidSyslogFreeRtosMutex_Create(), s_ring, sizeof(s_ring)), ``` -The sequence number is incremented once per record *formatted*, not once per record delivered. A -record that never arrives therefore leaves a gap in the sequence rather than no trace at all, which -is why it is worth adding before any buffering or storage that could drop one. Instrument first, -then introduce the failure mode. +This separates logging an event from sending it. `SolidSyslog_Log` becomes safe to call from any +number of tasks, and cheap enough to call from the place the event actually happens rather than +from somewhere convenient later. Nothing that logs waits on the network. -Unlike a header field, an SD PARAM has no nil value: one that is unset is omitted entirely rather -than written as `-`. +**A whole record now passes through both seams,** and the depth follows it. The log task formats +one; the service task drains one and sends it. Sized at the RTOS floor, the service task did not +merely trip its overflow hook — it locked the CPU up, because a frame that large clears the guard +band entirely rather than growing into it. Both seams now hold a record and their onward call, and +both are tightened against measured high-water marks at the end. -The counter comes from `SolidSyslogStdAtomicCounter`. If your toolchain has no atomics, supply your -own to the contract `SolidSyslogAtomicCounter_Increment` states — and note that logging from more -than one task is what makes the atomic part of it necessary. +The mutex is what makes the enqueue and drain sides safe on different tasks, and it comes from the +RTOS — which is what brings the `FreeRtos` platform into the build. A single-task device injects +`SolidSyslogNullMutex_Get()` instead and pays nothing. -`StdAtomic` joins the platform list, and here that is all it is: naming it compiles its two sources -exactly as naming `LwipRaw` compiles its eleven. +`SolidSyslog_Service` returns a status a device wanting more sophisticated scheduling can drive +from. A loop with a delay is the simplest model that works. -**When you need it.** If anyone needs to know that records have gone missing. +**When you need it.** Once logging and sending are decoupled, the buffer has to absorb however many +events can be logged before it is next serviced. It also makes logging from multiple tasks safe. -**Cost above baseline: Flash +6,052 B, RAM +1,972 B.** +**Cost above baseline: Flash +6,804 B, RAM +7,484 B.** @@ -74,6 +64,7 @@ committed as [`run-report.md`](run-report.md), and rewritten by every stage. | First record | a valid RFC 5424 record on the wire, over UDP | +4,724 | +1,908 | | Header fields | a timestamped record naming the device, instead of nil values | +5,108 | +1,908 | | Sequence numbers | every record numbered, so a gap in the sequence is visible | +6,052 | +1,972 | +| Buffered | logging that returns immediately, with the send moved off the logging task | +6,804 | +7,484 | *Deltas are bytes above the baseline, which is itself Flash 350,124 B, RAM 111,192 B.* diff --git a/app/AppConfig.h b/app/AppConfig.h index 5087b59..9b44086 100644 --- a/app/AppConfig.h +++ b/app/AppConfig.h @@ -10,13 +10,12 @@ /* CMSDK UART0 on the mps2-an385, surfaced by QEMU over -serial stdio. */ #define DEVICE_UART0_BASE ((uintptr_t) 0x40004000U) -/* The log seam formats the record on its own stack, so it holds - * SOLIDSYSLOG_MAX_MESSAGE_SIZE and the send beneath it and no longer fits the - * FreeRTOS floor. The service seam is still idle and keeps it. Both are sized - * generously here and tightened against measured high-water marks once the - * pipeline is complete. */ +/* Both seams handle a whole record — the log seam formats one, the service seam + * drains one — so each holds SOLIDSYSLOG_MAX_MESSAGE_SIZE and its onward call + * beneath, and neither fits the FreeRTOS floor. Sized generously here and + * tightened against measured high-water marks once the pipeline is complete. */ #define LOG_TASK_STACK_WORDS (configMINIMAL_STACK_SIZE * 4U) -#define SERVICE_TASK_STACK_WORDS (configMINIMAL_STACK_SIZE) +#define SERVICE_TASK_STACK_WORDS (configMINIMAL_STACK_SIZE * 4U) #define LOG_TASK_PRIORITY (tskIDLE_PRIORITY + 1U) #define SERVICE_TASK_PRIORITY (tskIDLE_PRIORITY + 1U) diff --git a/app/main.c b/app/main.c index 25fa459..e42240a 100644 --- a/app/main.c +++ b/app/main.c @@ -66,10 +66,11 @@ static void HarnessTask(void* parameters) bool logIdle = LogTask_WaitIdle(2000U); bool serviceIdle = ServiceTask_WaitIdle(2000U); - /* Emitted before the figures are taken: the record goes out inline on the - * log task's stack, so its stack figure only means anything afterwards. */ + /* Log enqueues and returns; the service task sends it, so give that a moment + * before the figures are taken. What arrived is the collector's word. */ bool logged = LogTask_EmitOnce(5000U); (void) printf("[device] first record logged: %s\n", logged ? "yes" : "FAILED"); + vTaskDelay(pdMS_TO_TICKS(500U)); (void) Measure_Report(); diff --git a/app/syslog/Syslog.c b/app/syslog/Syslog.c index 36b431d..9753b82 100644 --- a/app/syslog/Syslog.c +++ b/app/syslog/Syslog.c @@ -1,24 +1,25 @@ /* See Syslog.h. * - * The smallest wiring that delivers: a UDP sender over lwIP, with a passthrough - * buffer in front of it. Passthrough means Log sends inline on the calling task - * — no queue, no background drain, nothing to service. + * A UDP sender over lwIP behind a circular buffer: Log enqueues and returns, and + * the service task drains and sends. The mutex is what makes those two sides + * safe on different tasks. * * Unlike a header field, an SD PARAM has no NILVALUE: an unset one is omitted * entirely rather than written as "-". */ #include "Syslog.h" +#include "SolidSyslogCircularBuffer.h" #include "SolidSyslogConfig.h" #include "SolidSyslogEndpoint.h" #include "SolidSyslogEndpointHost.h" +#include "SolidSyslogFreeRtosMutex.h" #include "SolidSyslogLwipRawAddress.h" #include "SolidSyslogLwipRawDatagram.h" #include "SolidSyslogLwipRawMarshal.h" #include "SolidSyslogLwipRawResolver.h" #include "SolidSyslogMetaSd.h" #include "SolidSyslogNullStore.h" -#include "SolidSyslogPassthroughBuffer.h" #include "SolidSyslogStdAtomicCounter.h" #include "SolidSyslogUdpSender.h" #include "SyslogFields.h" @@ -35,7 +36,12 @@ #define SYSLOG_COLLECTOR_HOST "10.0.2.2" #define SYSLOG_COLLECTOR_PORT ((uint16_t) 5514U) +/* Depth enough to absorb a burst while the sender is busy, without sizing for a + * backlog the store is there to hold. */ +#define SYSLOG_BUFFER_RECORDS 8U + static struct SolidSyslog* s_logger = NULL; +static uint8_t s_ring[SOLIDSYSLOG_CIRCULAR_BUFFER_RING_BYTES(SYSLOG_BUFFER_RECORDS)]; /* The logger reads these on every record, so they outlive Syslog_Start. */ static struct SolidSyslogStructuredData* s_sd[1]; @@ -84,7 +90,7 @@ void Syslog_Start(void) s_sd[0] = SolidSyslogMetaSd_Create(&metaConfig); struct SolidSyslogConfig config = { - .Buffer = SolidSyslogPassthroughBuffer_Create(sender), + .Buffer = SolidSyslogCircularBuffer_Create(SolidSyslogFreeRtosMutex_Create(), s_ring, sizeof(s_ring)), .Sender = sender, /* No store-and-forward here. The Null object rather than NULL is how * that is said out loud — NULL is reported as a fault. */ diff --git a/app/tasks/LogTask.h b/app/tasks/LogTask.h index a63f514..dd3dc6e 100644 --- a/app/tasks/LogTask.h +++ b/app/tasks/LogTask.h @@ -12,9 +12,9 @@ extern "C" { #endif - /* The log source seam: the one place this device logs from. Its stack figure - * only means anything if logging happens here and not on the harness that - * asks for it. */ + /* The log source seam. With a buffer in front of the sender any task could + * call Log for the same cost; this stays one task so the stack figure has a + * single owner. */ bool LogTask_Create(void); TaskHandle_t LogTask_Handle(void); diff --git a/app/tasks/ServiceTask.c b/app/tasks/ServiceTask.c index 6cbbb80..735ae05 100644 --- a/app/tasks/ServiceTask.c +++ b/app/tasks/ServiceTask.c @@ -3,9 +3,14 @@ #include "ServiceTask.h" #include "AppConfig.h" +#include "Syslog.h" + +#include "SolidSyslog.h" #include "semphr.h" +#define SERVICE_POLL_MS 20U + static TaskHandle_t s_handle = NULL; static StaticTask_t s_taskBuffer; static StackType_t s_stack[SERVICE_TASK_STACK_WORDS]; @@ -20,7 +25,11 @@ static void ServiceTask_Entry(void* parameters) for (;;) { - vTaskDelay(portMAX_DELAY); + /* Service returns a status, which a device wanting more sophisticated + * scheduling can drive from. A loop with a delay is the simplest model + * that works. */ + (void) SolidSyslog_Service(Syslog_Handle()); + vTaskDelay(pdMS_TO_TICKS(SERVICE_POLL_MS)); } } diff --git a/make/solidsyslog.mk b/make/solidsyslog.mk index 5110f89..f0e1ac9 100644 --- a/make/solidsyslog.mk +++ b/make/solidsyslog.mk @@ -3,7 +3,7 @@ # upstream option it needs. # https://docs.cososo.co.uk/solid-syslog/getting-started/#path-b--non-cmake-integrator-the-manifest -SOLIDSYSLOG_PLATFORMS := LwipRaw StdAtomic +SOLIDSYSLOG_PLATFORMS := LwipRaw StdAtomic FreeRtos include $(THIRD_PARTY)/solid-syslog/solidsyslog.mk SOLIDSYSLOG_LIB := $(BUILD)/libSolidSyslog.a diff --git a/measurements/buffered.csv b/measurements/buffered.csv new file mode 100644 index 0000000..23152c8 --- /dev/null +++ b/measurements/buffered.csv @@ -0,0 +1,13 @@ +# buffered figures (bytes) — captured by scripts/run.sh (CAPTURE=1). +# The device reads measurements/Baseline.csv as its frozen baseline and reports current-minus-Baseline. +flash_text,356440 +flash_data,488 +static_bss,118188 +heap_used,4440 +mbedtls_peak,21332 +mbedtls_free,11436 +lwip_mem_free,7576 +lwip_pbufs_free,13 +stack_log,792 +stack_service,1004 +stack_harness,2848 diff --git a/measurements/stages.tsv b/measurements/stages.tsv index d955b6b..8639976 100644 --- a/measurements/stages.tsv +++ b/measurements/stages.tsv @@ -16,3 +16,4 @@ logger Logger created the logger object, reporting exactly what is still missing udp First record a valid RFC 5424 record on the wire, over UDP header-fields Header fields a timestamped record naming the device, instead of nil values sequence-id Sequence numbers every record numbered, so a gap in the sequence is visible +buffered Buffered logging that returns immediately, with the send moved off the logging task diff --git a/run-report.md b/run-report.md index 1a75381..b8b2108 100644 --- a/run-report.md +++ b/run-report.md @@ -1,4 +1,4 @@ -# solid-syslog-example — run (sequence-id) +# solid-syslog-example — run (buffered) ## Device (self-measured) @@ -10,16 +10,16 @@ [device] first record logged: yes [report] --- SolidSyslog cost above baseline (simulated existing application) --- [report] key,current,baseline,used_above_baseline -[report] flash_text,355704,349808,5896 -[report] flash_data,472,316,156 -[report] static_bss,112692,110876,1816 +[report] flash_text,356440,349808,6632 +[report] flash_data,488,316,172 +[report] static_bss,118188,110876,7312 [report] heap_used,4440,4440,0 -[report] mbedtls_peak,21352,21328,24 -[report] mbedtls_free,11416,11440,-24 +[report] mbedtls_peak,21236,21328,-92 +[report] mbedtls_free,11532,11440,92 [report] lwip_mem_free,7576,7576,0 -[report] lwip_pbufs_free,14,13,1 -[report] stack_log,1024,120,904 -[report] stack_service,52,52,0 +[report] lwip_pbufs_free,13,13,0 +[report] stack_log,792,120,672 +[report] stack_service,1004,52,952 [report] stack_harness,2848,2840,8 [report] --- end --- [device] ready @@ -29,7 +29,7 @@ ```text text data bss dec hex filename - 355696 480 112692 468868 72784 /w/build/baseline.elf + 356432 496 118188 475116 73fec /w/build/baseline.elf ``` ## Listeners (proved before the device ran) @@ -47,23 +47,23 @@ ## Collector (syslog-ng) received ```text -wire <134>1 2026-08-16T19:22:20.850000Z 10.0.2.15 solid-syslog-example - BOOT [meta sequenceId="1"] device started -parsed PRIORITY=134 TIMESTAMP=2026-08-16T19:22:20+00:00 HOSTNAME=10.0.2.15 APP_NAME=solid-syslog-example PROCID= MSGID=BOOT STRUCTURED_DATA=[meta sequenceId="1"] MSG=device started +wire <134>1 2026-08-16T19:29:06.310000Z 10.0.2.15 solid-syslog-example - BOOT [meta sequenceId="1"] device started +parsed PRIORITY=134 TIMESTAMP=2026-08-16T19:29:06+00:00 HOSTNAME=10.0.2.15 APP_NAME=solid-syslog-example PROCID= MSGID=BOOT STRUCTURED_DATA=[meta sequenceId="1"] MSG=device started ``` -## Self-check (vs measurements/sequence-id.csv) +## Self-check (vs measurements/buffered.csv) ```text - OK flash_text: 355704 (expected 355704, Δ0) - OK flash_data: 472 (expected 472, Δ0) - OK static_bss: 112692 (expected 112692, Δ0) + OK flash_text: 356440 (expected 356440, Δ0) + OK flash_data: 488 (expected 488, Δ0) + OK static_bss: 118188 (expected 118188, Δ0) OK heap_used: 4440 (expected 4440, Δ0) - OK mbedtls_peak: 21352 (expected 21320, Δ32) - OK mbedtls_free: 11416 (expected 11448, Δ32) + OK mbedtls_peak: 21236 (expected 21332, Δ96) + OK mbedtls_free: 11532 (expected 11436, Δ96) OK lwip_mem_free: 7576 (expected 7576, Δ0) - OK lwip_pbufs_free: 14 (expected 14, Δ0) - OK stack_log: 1024 (expected 1024, Δ0) - OK stack_service: 52 (expected 52, Δ0) + OK lwip_pbufs_free: 13 (expected 13, Δ0) + OK stack_log: 792 (expected 792, Δ0) + OK stack_service: 1004 (expected 1004, Δ0) OK stack_harness: 2848 (expected 2848, Δ0) ```