First published: Last updated:
Metrics, Logs, and Traces
Originally published in Japanese at https://zenn.dev/ymotongpoo/books/tinygo-otel-esp32/viewer/45-three-signals.
The previous chapters built the path that sends OTLP metrics from the device. This chapter decides what to put on that path. OpenTelemetry calls each kind of telemetry that it handles a signal. This book’s implementation sends three signals: metrics, logs, and traces. It sends metrics every 10 seconds, and it sends logs and traces right after each successful metrics export.
Without an SDK, you decide for yourself what to measure and how much to keep on the device. I used one rule throughout. The device records only what you cannot learn from outside the device, and it sets an upper limit on how much it buffers.
Choosing the metrics
The metrics are 12 time series (one series for each combination of a name and attributes). They cover the uptime, the Wi-Fi signal strength, memory, export results, and the counts of dropped logs and spans. I skip the metrics whose names explain their content. This section looks at three metrics that I chose for a specific reason.
Two kinds of memory
For memory, the device sends the pair device.memory.usage and device.memory.limit twice, with a different value of the device.memory.pool attribute each time. One pair is the Go heap, which the device reads with runtime.ReadMemStats. The other pair is the arena of the Wi-Fi driver (a fixed-size region that the driver allocates at startup and manages itself).
runtime.ReadMemStats(&ms)
heapInuse.Set(float64(ms.HeapInuse))
heapTotal.Set(float64(ms.HeapSys))
used, capacity := espradio.ArenaStats()
arenaUsed.Set(float64(used))
arenaCap.Set(float64(capacity))
As Chapter 9 showed, the Go GC cannot see the arena. If the device sent only runtime.MemStats, you could not tell whether a memory shortage came from the Go heap or from espradio (the driver that lets TinyGo use the Wi-Fi of the ESP32). On the real device, the arena usage stayed at 31,312 bytes out of a capacity of 49,144 bytes. The code declares ms outside the loop and reuses it. This way, the code that reads memory does not grow the heap that it reads.
RSSI of the connected AP
RSSI (Received Signal Strength Indicator) is the strength of the received radio signal, in dBm. The device sends it so that, when exports keep failing, you can tell whether the signal is weak or the Collector is down.
espradio v0.3.0 has no Go function that returns the RSSI of the connected access point (AP). espradio.Scan() lists nearby APs, and its results cannot replace the value for the current link. The Wi-Fi binary library that Espressif provides (the blob from here on) has esp_wifi_sta_get_rssi, and espradio links this blob. The symbol is already in the binary. So if you declare the prototype in a cgo preamble, the call works.
/*
int esp_wifi_sta_get_rssi(int *rssi);
*/
import "C"
func stationRSSI() (int, error) {
var v C.int
if code := C.esp_wifi_sta_get_rssi(&v); code != 0 {
return 0, errRSSI
}
return int(v), nil
}
I did not change espradio itself. Even when a driver has no wrapper, this method lets you get a value from a C function that is already linked. The prototype declaration has the same form as the one in the blob’s header (esp_wifi.h) that espradio bundles.
Three outcomes for an export
device.export.attempts is a counter, and its outcome attribute has three values: success, failure, and partial_rejection. partial_rejection is the case where HTTP returns 200, but the Collector reports in the partialSuccess field of the response that it rejected some data points (see Chapter 7). If you count this case as a success, the success rate stays at 100% even when data is missing. If you count it as a failure, the same as a lost connection, a retry gets rejected again for the same reason. So the device counts it as a separate value.
The counter and device.export.payload show the result of the previous export. The encoder reads them during encoding, before the current export changes their values.
Recording logs, with a limit
The device sends events that happen on it as OTLP log records to /v1/logs. It records four kinds of events: startup, the start of failed exports, recovery from failure, and a partial rejection by the Collector. When failures continue, the device records only the first one, and the recovery log carries the number of failures as an attribute. If the device recorded every failure, records with the same content would fill the buffer during a long outage.
Logs are always JSON, whatever encoding the metrics use. OTLP/HTTP lets you choose the Content-Type for each request. A hand-written protobuf encoder only for logs would not change what the Collector receives. Logs reuse the TCP connection from the metrics export, so adding logs does not add connections.
Events keep happening while the device cannot reach the Collector. If the buffer had no limit, a network outage would lead directly to a reset caused by running out of memory. So the device keeps logs in a fixed-size ring buffer of 16 records. When the buffer is full, the device overwrites the oldest record and counts the overwritten records.
} else {
// Full: overwrite the oldest.
i = b.head
b.head = (b.head + 1) % len(b.records)
b.Dropped++
}
The device sends this count as the device.logs.dropped metric. Logs cannot report their own loss, because the lost records are no longer on the device. With the count in the metrics, you can check on the dashboard whether any logs are missing.
The timestamp of a record is the time of the event, not the time of the export. On the real device, I stopped the Collector for 25 seconds. export failed arrived in Loki with the time 07:04:54, while the Collector was down. export recovered (failed_attempts=2) arrived with the time 07:05:17, after the Collector came back. So logs that the device records during an outage still line up in the correct order when they arrive.
Tracing the export cycle
The unit of a trace is one export cycle, which runs every 10 seconds. The root span (a record with the start time and end time of one operation) represents the whole cycle. Under it, the device places three child spans: reading values (collect), encoding (encode), and the POST /v1/metrics to the Collector. Only the HTTP span has the kind CLIENT, and its status becomes ERROR when the export fails.
On a server, the SDK and instrumentation libraries would create these spans. Here, code that only records start and end times and assigns IDs is enough.
cycle := spans.start(trace, otlpjson.SpanID{}, "export cycle", otlpjson.SpanKindInternal)
collect := spans.start(trace, cycle.s.SpanID, "collect", otlpjson.SpanKindInternal)
The device creates trace IDs and span IDs with crypto/rand. On the ESP32-S3, TinyGo implements crypto/rand with the hardware random number generator built into the chip (machine.GetRNG). So you do not need to manage a pseudorandom seed for the IDs.1 As Chapter 6 mentioned, OTLP/JSON writes IDs as hex strings.
Like logs, the device always sends spans as JSON and keeps them in a fixed-size buffer of 16 records. Metrics go first. The HTTP span cannot close until the export finishes, so the device can send traces only after the metrics export is done. Spans from a cycle whose export failed stay in the buffer, and they arrive together with the first successful export after recovery. Each cycle creates four spans, so the 16-record buffer holds four cycles. Spans beyond that push out the oldest spans, and the count of pushed-out spans goes into device.spans.dropped.
In one cycle that I recorded on the real device, the whole cycle took 14.5 ms, collect took 0.47 ms, encode took 2.31 ms, and POST /v1/metrics took 11.34 ms. In this example, the HTTP request to the Collector took nearly 80% of the cycle, and encoding took less than 20%. You can read from the trace where the time goes, without guessing on the device. Tempo creates duration metrics from the spans, so the dashboard also shows how the values change from cycle to cycle (see the next chapter).
The cost of three signals
With logs and traces, each export cycle has three POSTs. Each cycle also converts the IDs of four spans to hex and assembles strings. As a result, the short-lived heap allocations per cycle grew from 800 bytes with metrics only to 2,992 bytes.
What grew was the amount of allocation, not the memory that the program holds. In a 30-minute continuous test, all 180 exports succeeded, and GC ran 7 times (about every 5 minutes). The heap after GC stayed at about 204 KB all 7 times. When I restarted the Collector partway through, exports resumed after 9.1 seconds. The next chapter describes the test procedure and the comparison with the metrics-only version.
A comment in the code notes that this random number generator uses radio noise as its source, so the device creates IDs after it connects to Wi-Fi. The specification of the ESP32-S3 random number generator is in the Technical Reference Manual. ↩︎