Analyze an App's Runtime Behavior — Logs, Metrics, Traces, Catalog

Overview

When you need to understand what an app actually does at runtime — why a page is slow, which microflow dominates cost, what hits the database, whether an error is network or logic — the signals live in four places. This skill is the procedure for collecting them and, crucially, joining them, because the useful questions cross sources that no single tool answers alone.

Signal	Where	How you get it
Logs (server stack traces + your LOG output)	<projectDir>/.mxcli/runtime.log	mxcli run --local tees it automatically
Metrics (throughput, DB counts, sessions, queues)	/prometheus on the admin port	mxcli run --local --metrics
Traces (per-microflow / per-activity spans + timings)	console→runtime.log, or an OTLP collector	mxcli run --local --trace / --trace-otlp
Model shape (activities, complexity, refs, XPath)	.mxcli/catalog.db (SQLite)	mxcli … "refresh catalog full" then SELECT … FROM CATALOG.*

When to Use This Skill

• A page/microflow is slow and you need to find where the time goes.
• You want to know which entities/queries the app actually hits, and how often.
• A server-side error shows only a generic dialog in the browser.
• You're profiling and need a flame chart, or want cost correlated with model shape.

Prerequisite: run the app with the fast local loop — see run-local. Everything below assumes mxcli run --local (add the flags noted per signal).

1. Logs — the first stop for errors

run --local writes the runtime log to <projectDir>/.mxcli/runtime.log (override --runtime-log, - disables). It carries JVM stdout/stderr and the application log — server stack traces, your microflow/nanoflow LOG output, and the DB synchronization counts at startup.

mxcli run --local -p app.mpr
tail -f .mxcli/runtime.log

Gotchas:

• Nanoflow LOG lands under the Client_Nanoflow node, not the node name you declared — a filter built around microflow node names silently drops it. LOG DEBUG from a nanoflow is dropped server-side (browser console only). See write-nanoflows.
• A spike in "Executing N database synchronization command(s)" on an unchanged model is a red flag (see the create or modify data-loss class of bug).

Turning up one subsystem: mxcli log

Everything logs at INFO by default, so the detail you need usually is not in the file at all — and raising the whole runtime to TRACE is unusable. Logging is publish/subscribe: code publishes to a named LogNode, and each node has its own level.

mxcli log list                          # every node and its level (57 on a blank 11.12 app)
mxcli log list --filter connectionbus   # narrow it — nobody remembers the exact names
mxcli log set ConnectionBus_Queries TRACE
mxcli log set ConnectionBus_Queries=TRACE Connector=DEBUG   # one admin call
mxcli log set ConnectionBus_Queries INFO                    # put it back

Levels: NONE CRITICAL ERROR WARNING INFO DEBUG TRACE.

This needs a running app (it goes through the M2EE admin API), and the change lasts as long as the process — it is a debugging knob, not project configuration.

Nodes worth knowing:

Question	Node
What SQL is being run	ConnectionBus_Queries (and _Retrieve, _Update)
Database sync at startup	ConnectionBus_Synchronize
Consumed OData / REST calls	ODataConsume, REST Consume
Published OData requests (the incoming URI)	OData Publish — note the space; only exists if the project publishes a service
Microflow execution	MicroflowEngine, ActionManager
Scheduled events / queues	SystemTask, TaskQueue
Java/JS action wiring	Connector

--force creates the node, permanently. Without it an unknown node is refused, which is what you want — a typo should be an error. With it the name is registered for the life of the process, so a typo becomes a real (empty) node that shows up in log list from then on. Use it only to pre-register a node that has not published yet.

Nodes appear only once something registers them, so the list is a property of this app, not of Mendix. A blank 11.12 app reports 57; adding one published OData service makes it 58. This is why log list is the first step rather than a remembered name — and why --force exists for a node that has not registered yet.

Seeing what a published OData resource is asked

OData Publish — note the space — is the node, and it exists only when the project publishes a service. At TRACE it logs the full incoming URI, which is the question $filter/$top/key-lookup bugs turn on:

mxcli log set "OData Publish" TRACE
# GET /odata/f1/Rows?$top=5&$filter=rowKey eq 'abc'

TRACE - OData Publish: Incoming request from 127.0.0.1: GET .../Rows?$top=5&$filter=rowKey eq 'abc'
DEBUG - OData Publish: Responding to client with status code 400.

ODataConsume is the client side — a different node for a different direction.

That same probe showed Mendix rejecting $filter on a property not declared Filterable, with a 400 "Property 'rowKey' is non-filterable", before the read microflow ran. So the platform does enforce the filterability you declare in expose (…); what it does not do is apply $top/$skip/$orderby for a read-microflow resource (see odata-data-sharing).

2. Metrics — throughput and database pressure

--metrics registers a Prometheus registry, served at http://127.0.0.1:<admin-port>/prometheus (loopback).

mxcli run --local -p app.mpr --metrics
curl -s http://127.0.0.1:8090/prometheus | grep -E 'connectionbus_|handler_requests|sessions_|taskqueue_'

Useful families: connectionbus_{selects,inserts,updates,deletes,transactions}_total (database pressure), handler_requests_total (throughput), sessions_*, taskqueue_* (background work). Merge any extra registry (otlp/influx/statsd) with --runtime-setting 'Metrics.Registries=[…]'.

3. Traces — where the time goes

--trace attaches the bundled OpenTelemetry agent. Default span filters ship with it (OpenTelemetry._RuntimeSpanFilters) because unfiltered per-activity tracing is ~10× slower and produces ~110k spans for one busy transaction — that's a flow-shape debugging mode, not a timing mode.

# console exporter → runtime.log (span names/attrs only)
mxcli run --local -p app.mpr --trace
# flame charts: export to a collector (console can't reconstruct call trees/durations)
mxcli run --local -p app.mpr --trace-otlp http://127.0.0.1:4318

• The console exporter omits start/end timestamps and parent span IDs — you get span names + attributes but no call tree and no durations. For real timing/flame charts use --trace-otlp <endpoint> (implies --trace), which sets the OTLP exporter for you; user-set OTEL_* env still wins.
• --trace-service NAME sets OTEL_SERVICE_NAME (default the .mpr name); use distinct names per app for multi-app correlation. Trace context (W3C traceparent) crosses app boundaries automatically over rest call.
• To examine flow shape on a small flow, temporarily disable the filters with --runtime-setting 'OpenTelemetry._RuntimeSpanFilters=[]'.

4. Model shape — the catalog

The catalog is a SQLite database at .mxcli/catalog.db describing the model. Run refresh catalog full — plain refresh catalog (fast mode) leaves the analytic tables (CATALOG.ACTIVITIES, CATALOG.REFS, CATALOG.XPATH_EXPRESSIONS, CATALOG.WIDGETS) empty (a fast-mode query warns "requires refresh catalog full").

mxcli -p app.mpr -c "refresh catalog full"
mxcli -p app.mpr -c "SELECT MicroflowQualifiedName, COUNT(*) activities
                     FROM CATALOG.ACTIVITIES GROUP BY 1 ORDER BY 2 DESC LIMIT 10"

CATALOG.ACTIVITIES.Id is the model GUID the debugger breaks on (see debug-microflows), with the action name and its sequence — a named, ordered activity list per microflow. See catalog-search / graph-analysis for the richer queries.

5. The app warehouse — join the signals (external DuckDB)

Each signal alone answers little; the useful questions cross them. Because the catalog is a plain database and the app's dev data is Postgres, one engine can join model shape + live data + telemetry with no ETL. mxcli does not embed DuckDB — this is a dev-container recipe (dev data, dev telemetry, everything read-only):

-- in duckdb, from the project dir, after `refresh catalog full` + a --trace-otlp run
ATTACH '.mxcli/catalog.db' AS cat (TYPE sqlite, READ_ONLY);
ATTACH 'dbname=app host=127.0.0.1 user=mendix' AS app (TYPE postgres, READ_ONLY);
CREATE VIEW spans AS SELECT * FROM read_json_auto('spans.jsonl');

Two joins that are impossible in any single source:

• Runtime cost × model shape — span durations per microflow joined to cat.activities_data (count) and complexity. Complexity does not predict cost: a 2-activity flow that delegates can cost more than a 14-activity one. A lint rule can't see that; this join can.
• Query time × entity × live rows — span DB timings joined to cat (which entity) and app (row counts). This is how you find that the task-queue poller (system$queuedtask, owned by no microflow) is the app's largest DB consumer — invisible from any per-microflow view.

Caveats: keep every attachment read-only (never a production DB; even locally make it explicit), and filter/sample traces first — unfiltered span volume is large.

Known gap: logs ↔ traces

Runtime log lines carry no trace id, so joining logs to traces is a fuzzy timestamp join (worst exactly under concurrency). The OTel agent populates the trace id in the MDC, but Mendix's log pattern doesn't print it — closing the file-log side needs an upstream %X{trace_id} change, not mxcli. For collector-side correlation, export traces (and logs) via OTLP with --trace-otlp so the backend joins them.

Decision guide

Question	Reach for
"Why did this error?" (server-side)	Logs (runtime.log)
"How much DB / throughput / queue work?"	Metrics (--metrics)
"Where does the time go in this flow?"	Traces (--trace-otlp for a flame chart)
"What's the flow's shape / activity list?"	Catalog (refresh catalog full) or the debugger
"Which cost belongs to which entity/model construct?"	Warehouse (catalog × spans × app DB)

See Also

• run-local — the local loop these flags hang off (--metrics / --trace / --trace-otlp / --runtime-setting reference).
• debug-microflows — interactive breakpoints/stepping when a trace isn't enough.
• catalog-search, graph-analysis — catalog query patterns and dependency analysis.
• verify-with-oql — query the running app's data directly.