Startup diagnostics

docs/MetadataScaling.md

@@ -0,0 +1,56 @@
+# Metadata scaling and 32-bit indexes
+
+## Local reproduction
+
+Windows x64 Release, MSVC v145, Boost 1.92. The benchmark generates deterministic metadata and passes it through the actual SubscriberInstance metadata parser and configuration builder. Its timer excludes XML generation, compression, network transfer, and post-parse validation.
+
+480,000 analog measurements concentrated on eight devices (60,000 each), 185,450,687 XML bytes:
+
+| Stage | Original implementation | Indexed frame construction |
+|---|---:|---:|
+| Complete metadata processing | 107.081 s | 10.947 s |
+| Configuration frames | 92.934 s | 0.348 s |
+| XML parsing | 0.504 s | 0.369 s |
+
+A final run after widening metadata indexes completed in **9.783 s**, with all output validation passing. These are individual runs and vary with machine load. Three alternating 50,000-point comparisons gave median totals of 5.479 s original and 1.211 s optimized.
+
+This reproduces a substantial client-side delay locally and identifies configuration construction as the dominant cost for this shape. It does not establish the cause of the client's reported 2.5-minute connection delay: their metadata distribution, server work, transfer, and hardware remain unmeasured.
+
+## Fix
+
+ConstructConfigurationFrames previously scanned a device's measurements for every analog/digital index and scanned its phasors for every phasor index. It now builds lookup vectors once per device. Ordering, missing-index placeholders, and first-match handling of duplicate indexes are preserved.
+
+SignalReference.Index, MeasurementMetadata.PhasorSourceIndex, and PhasorMetadata.SourceIndex now use signed int32_t. Parsing, helper signatures, publisher phasor maps, and metadata filtering preserve these values. Frame loops use int64_t counters so neither 65,535 nor INT32_MAX causes counter wraparound. The aggregate phasor count uses size_t.
+
+Runtime signal-cache and compact-measurement indexes were already int32_t; their wire layout is unchanged. Cache comments have been corrected accordingly.
+
+## Validation
+
+The native benchmark regression mode checks:
+
+- Dense and sparse analog, digital, and phasor metadata, including gzip input.
+- Indexes 65,535, 65,536, and 100,000 for each kind; placeholder positions and signal identities.
+- Duplicate indexes retain the original first-match behavior.
+- A complete 70,000-measurement metadata set.
+- A 70,001-entry wire cache and compact-measurement round trips, including INT32_MAX.
+- Publisher metadata round trips for indexes 34,464 and 100,000, which collided when narrowed to 16 bits.
+- TSSC compressed round trips through indexes 65,535, 65,536, and 100,000.
+
+Build and execution instructions: [MetadataBenchmark](../src/samples/MetadataBenchmark/README.md).
+
+Local evidence is under build/startup-diagnostics (ignored build artifacts): baseline-summary.txt, optimized-summary.txt, massive-baseline.out/.log, massive-optimized.out/.log, massive-int32.out/.log, repeat-baseline-*.out/.log, repeat-optimized-*.out/.log, and int32-regressions.out/.log. MetadataBenchmark-baseline.exe preserves the original frame algorithm for local comparisons.
+
+## Limits and integration
+
+- Configuration frames still allocate placeholders through the maximum index. A sparse enormous index can exhaust memory; signed 32-bit fields do not make billions of frame slots practical. INT32_MAX was tested in parsing, cache, and compact records, not by allocating that many configuration slots or TSSC states.
+- Per-phasor angle/magnitude association still scans device measurements and can become costly on a device with many phasors. This optimization addresses configuration-frame construction.
+- The separately observed duplicate connection initialization remains unchanged; see StartupDiagnostics.md.
+- These changes alter the public native metadata ABI. Rebuild all native consumers. Before using this library with net-cppapi, update its three SWIG field declarations, regenerate bindings, and rebuild both managed and native wrapper components together. Existing .NET binaries have not been replaced.
+- Boost compatibility uses explicit version checks; pre-1.66 branches were not compiled in this environment.
+
+## Final native live check
+
+After the performance and int32 changes, the rebuilt StartupTiming.exe connected to openHistorian at 127.0.0.1:7175 with metadata enabled. First measurement arrived 143.550 ms after connection; the five-second run received 19,860 measurements at approximately 4,100/sec and exited successfully. Evidence: build/startup-diagnostics/final-live.out and final-live.log. This checks compatibility with the local publisher, whose small metadata set does not exercise the large-index cases covered by the synthetic regressions.
+
+Production correctness tests are also available in [ConfigurationFramesTest](../src/samples/ConfigurationFramesTest/README.md), independently of this diagnostics branch.
+

docs/StartupDiagnostics.md

@@ -0,0 +1,111 @@
+# Diagnosing connection-to-first-data delays
+
+## Branch scope
+
+This diagnostics branch is based on production commit 5a5edac. Performance and int32 fixes, together with samples/ConfigurationFramesTest, are already in main. This branch adds opt-in tracing, StartupTiming, MetadataBenchmark, and investigation notes. Measurements below were collected during the original investigation unless explicitly marked as branch validation.
+
+
+## Findings from source inspection
+
+The default SubscriberInstance path is sequential:
+
+connection ready -> request metadata -> receive entire response -> callback queue -> decompress -> parse XML -> construct device/measurement/phasor objects -> construct configuration frames -> install maps -> ParsedMetadata callback -> destroy temporary metadata structures -> send Subscribe -> publisher processes subscription -> receive/decode signal index cache -> receive/decode data -> measurement callback.
+
+`SubscriberInstance::HandleMetadata` waits for `ReceivedMetadata` to return before calling `Subscribe`. The subscription filter does not limit the metadata request: that uses the separate `MetadataFilters` setting. A filter excluding STAT therefore still downloads/processes the default metadata set.
+
+### Findings in the original implementation
+
+1. **Configuration-frame construction.** `ConstructConfigurationFrames` calls `TryFindMeasurement` (a linear scan of the device's measurement vector) for every analog/digital index. `GetSignalKindCount` actually returns the maximum signal-reference index, not the number of records. Cost grows roughly with `measurements-per-device * (maximum-analog-index + maximum-digital-index)`. Dense 50,000 analogs on one device can mean roughly 1.25 billion comparisons. Sparse high indexes also generate placeholder records. The phasor configuration loop repeatedly scans the phasor list. This is per-device scaling, not automatically quadratic in the total metadata count across small devices.
+2. **Phasor association.** For each phasor, ReceivedMetadata scans the associated device's measurements to locate angle/magnitude. Approximately `sum(phasors-per-device * measurements-per-device)` in the worst case.
+3. **Metadata materialization and memory pressure.** Every record creates objects/strings and parses UpdatedOn using string processing and locale-based streams. The metadata maps are copied into member maps; temporary maps, XML storage, and the expanded payload are then destroyed before Subscribe. Raw XML parsing is only one part of this work.
+4. **Transfer/decompression and signal cache.** Metadata and cache decompression use CopyStream, which appends bytes one at a time to a vector. Cache Decode performs per-record allocations/hash insertions, with no pre-reservation. These deserve measurement, but do not show the repeated whole-device scans above.
+
+The client Subscribe method builds and sends a small connection string containing the filter; it does not expand the filter to every measurement locally. The publisher performs selection and subscription setup. A long gap after sending Subscribe and before receiving its response/cache points toward publisher work or transfer, rather than this client's filter evaluation. The C++ publisher code does not establish what openHistorian's publisher spends time doing.
+
+**Fixed:** configuration-frame construction now builds per-device index lookups instead of repeatedly scanning each device. Metadata indexes and publisher mappings use int32_t; frame loops use int64_t counters to avoid wraparound. See [MetadataScaling.md](MetadataScaling.md) for the local reproduction, measurements, and boundary tests. Phasor association remains a separate potential hotspot.
+
+## Opt-in instrumentation
+
+Rebuild the native C++ library/client with the modified sources, then launch from PowerShell:
+
+```powershell
+$env:STTP_STARTUP_TRACE = '1'
+# Run your rebuilt native client with its normal IP/port arguments, redirecting stderr:
+# .\YourClient.exe 127.0.0.1 7175 2> startup-trace.log
+```
+
+The metadata field changes alter the native ABI. Update the three corresponding SWIG field declarations to int32_t and regenerate the bindings before rebuilding the wrapper. For the .NET wrapper, rebuild/relink `sttp.net.lib.dll` against these instrumented sources and redeploy it before testing ConnectionTest. Merely republishing the .NET executable does not incorporate these C++ changes. The old prebuilt native DLL will not emit these diagnostics.
+
+Unset STTP_STARTUP_TRACE or set it to 0 to disable tracing. The setting is read once per process. Events go directly to stderr and are flushed; they are independent of StatusMessage overrides and the callback queue. No measurement values or metadata content are logged. Before constructing configuration frames, a diagnostic-only scan reports maximum per-device measurement/phasor counts and maximum analog/digital/phasor reference indexes. Its duration is reported separately.
+
+Log format contains monotonic milliseconds since the first trace event, native DataSubscriber pointer (to separate connections), stage duration, and item/byte count where applicable. Scope labels appear on entry and exit; marks report elapsed time since the previous mark. Logs can interleave across threads, so compare timestamps and subscriber pointers. Diagnostic I/O adds some overhead; redirect to a local file.
+
+| Compare stages | What the interval covers |
+|---|---|
+| metadata request sending -> metadata response received | Request sending, publisher preparation, response transfer |
+| metadata response received -> response queued -> metadata callback scope entry | Payload copying and callback scheduling; queue and callback may overlap |
+| metadata decompress/copy complete | Gzip expansion or uncompressed payload copy |
+| XML parse complete | pugixml load_buffer_inplace |
+| device / measurement objects complete | Record conversion, timestamps, strings and map insertion |
+| phasor objects and measurement matching complete | Phasor record conversion and association scans |
+| configuration frames complete | Indexed lookups and placeholder construction |
+| metadata maps installed | Configuration lock, map copying/replacement |
+| ParsedMetadata callback complete -> metadata processing scope exit | Temporary metadata/XML/buffer destruction |
+| subscribe command built -> subscribe send returned | Local command construction/send; not publisher completion |
+| subscribe send -> acknowledged / signal cache scope entry | Publisher processing and transfer; response ordering may vary |
+| cache decompress/copy -> cache decode complete | Cache expansion and decoding |
+| first nonempty packet received -> first packet decoded | First packet's decode before measurement callback |
+
+The first-packet marker uses the existing per-subscription receive counter. It is a packet diagnostic, not a guarantee of successful measurements if the packet cannot be decoded or its cache is absent.
+
+## Quick comparison test
+
+Use the same endpoint/filter with one counting subscriber, once with default metadata parsing and once with:
+
+```cpp
+subscriber.SetAutoParseMetadata(false); // before Connect/ConnectAsync
+```
+
+This skips both metadata retrieval and metadata construction and immediately subscribes with the configured filter. Signal-index-cache decoding is still required. It is suitable for the counting test; code that depends on parsed device/configuration metadata will lose that metadata. A large improvement isolates the metadata path, but does not distinguish server metadata preparation/transfer from client parsing; use the stage timings for that distinction.
+
+Then compare the same subscriber with a small filter versus the full filter while metadata is disabled to assess publisher subscription/cache scaling. Keep compression, endpoint and build configuration fixed. Use Release builds for representative performance and record metadata size, per-device point counts and maximum analog/digital/phasor indexes.
+
+## Native build and measured results
+
+The Windows x64 Release diagnostic client is now available at `build/startup-diagnostics/StartupTiming.exe`. Build and run instructions are in `src/samples/StartupTiming/README.md`. Its `--no-metadata` option runs the comparison above without changing the filter. The native library and client were successfully compiled using MSVC v145 and Boost 1.92.
+
+Required compatibility changes: use Boost's built-in UUID std::hash from 1.86 onward, use modern Asio resolver/address APIs with explicit Boost version checks, and explicitly include chrono in ANTLR's profiling source. The configuration-frame optimization is described in MetadataScaling.md. The pre-1.66 Boost branches have not been compiled in this environment.
+
+Initial five-second tests against openHistorian at 127.0.0.1:7175:
+
+| Mode | Connection to first measurement | Received | Exit code |
+|---|---:|---:|---:|
+| Metadata enabled | 241.080 ms | 19,584 | 0 |
+| Metadata disabled | 35.175 ms | 20,402 | 0 |
+
+Both streamed approximately 4,100 measurements/sec. These are individual diagnostic runs, not benchmark averages. Raw traces and console output are in `build/startup-diagnostics/metadata.log`, `metadata-output.log`, `no-metadata.log`, and `no-metadata-output.log`.
+
+For the first metadata response (50,802 compressed bytes, 448,356 expanded bytes, 747 measurement records across 5 devices), the timings were approximately:
+
+- Metadata request to complete response: 116 ms.
+- Decompression/copy: 14.2 ms.
+- XML parsing: 0.8 ms.
+- Measurement-object construction: 15.6 ms.
+- Phasor conversion/matching: 3.6 ms.
+- Configuration frames: 0.23 ms.
+- Signal cache decompression/decoding: approximately 1 ms combined.
+
+This small metadata set does not reproduce the large-device configuration scaling hypothesis. Its maximum per-device measurement count was 169, with maximum analog/digital/phasor indexes of 14/2/59. A trace from the slow client is still needed to locate the 2.5-minute delay.
+
+### Additional observed defect: duplicate startup requests
+
+The trace shows two `connection ready` events, two metadata requests, and two metadata responses/subscriptions for one connection. With metadata disabled it shows two immediate Subscribe commands. Source inspection confirms that `SubscriberInstance::Connect()` calls `ConnectionEstablished()` and `HandleConnect()`, and the registered `HandleConnectionEstablished()` callback also calls them. This duplicates startup work and can trigger a resubscription while the first stream is starting.
+
+The diagnostic patch deliberately retains this behavior so it can be measured. This finding is specific to the current C++ checkout; it does not prove that the older prebuilt SWIG DLL has the same behavior. The diagnostic client retains the earliest connection callback timestamp so duplicate notifications do not reset its timer.
+
+
+
+
+## Diagnostics branch validation
+
+Rebuilt on codex/startup-diagnostics, based on production commit 5a5edac. With tracing enabled, the local openHistorian check at 127.0.0.1:7175 received first data in 171.366 ms and 19,856 measurements over the five-second run (roughly 4,100/sec). Output and trace: build/review-stages/04-live.out and 04-live.log. Timings are individual runs, not benchmark averages.

src/lib/transport/DataSubscriber.cpp

@@ -24,6 +24,7 @@
 //******************************************************************************************************
 
 #include "DataSubscriber.h"
+#include "StartupTrace.h"
 #include "Constants.h"
 #include "CompactMeasurement.h"
 #include "../Convert.h"
@@ -386,6 +387,8 @@ void DataSubscriber::HandleSucceeded(const uint8_t commandCode, uint8_t* data, c
         // Do not break on these messages because there is
         // still an associated message to be processed.
         m_subscribed = (commandCode == ServerCommand::Subscribe);
+        if (m_subscribed)
+            diagnostics::StartupEvent(this, "subscribe acknowledged");
         [[fallthrough]];
     case ServerCommand::UpdateProcessingInterval:
     case ServerCommand::RotateCipherKeys:
@@ -435,7 +438,9 @@ void DataSubscriber::HandleFailed(const uint8_t commandCode, uint8_t* data, cons
 // Handles metadata refresh messages from the server.
 void DataSubscriber::HandleMetadataRefresh(const uint8_t* data, const uint32_t offset, const uint32_t length)
 {
+    diagnostics::StartupEvent(this, "metadata response received (bytes)", 0.0, length);
     Dispatch(&MetadataDispatcher, data, offset, length);
+    diagnostics::StartupEvent(this, "metadata response queued");
 }
 
 // Handles data start time reported by the server at the beginning of a subscription.
@@ -456,6 +461,7 @@ void DataSubscriber::HandleUpdateSignalIndexCache(const uint8_t* data, uint32_t
     if (data == nullptr)
         return;
 
+    diagnostics::StartupPhase startup(this, "signal cache processing scope");
     vector<uint8_t> uncompressedBuffer;
     int32_t cacheIndex = 0;
 
@@ -486,8 +492,10 @@ void DataSubscriber::HandleUpdateSignalIndexCache(const uint8_t* data, uint32_t
         WriteBytes(uncompressedBuffer, data, offset, length);
     }
 
+    startup.Mark("signal cache decompress/copy complete (bytes)", uncompressedBuffer.size());
     SignalIndexCachePtr signalIndexCache = NewSharedPtr<SignalIndexCache>();
     signalIndexCache->Decode(uncompressedBuffer, m_subscriberID);
+    startup.Mark("signal cache decode complete");
 
     m_signalIndexCacheMutex.lock();
     m_signalIndexCache[cacheIndex].swap(signalIndexCache);
@@ -548,6 +556,9 @@ void DataSubscriber::HandleDataPacket(uint8_t* data, uint32_t offset, const uint
 
         // Read measurement count and gather statistics
         const uint32_t count = EndianConverter::ToBigEndian<uint32_t>(data, offset);
+        const bool firstPacket = m_totalMeasurementsReceived == 0 && count > 0;
+        if (firstPacket)
+            diagnostics::StartupEvent(this, "first nonempty data packet received", 0.0, count);
         m_totalMeasurementsReceived += count;
         offset += 4; //-V112
 
@@ -569,6 +580,8 @@ void DataSubscriber::HandleDataPacket(uint8_t* data, uint32_t offset, const uint
         else
             ParseCompactMeasurements(signalIndexCache, data, offset, length, includeTime, info.UseMillisecondResolution, frameLevelTimestamp, measurements);
 
+        if (firstPacket)
+            diagnostics::StartupEvent(this, "first packet decoded; invoking measurement callback", 0.0, measurements.size());
         newMeasurementsCallback(this, measurements);
     }
 }
@@ -1414,6 +1427,7 @@ void DataSubscriber::Subscribe(const SubscriptionInfo& info)
 // Subscribe to publisher in order to start receiving data.
 void DataSubscriber::Subscribe()
 {
+    diagnostics::StartupPhase startup(this, "subscribe send scope");
     stringstream connectionStream;
     vector<uint8_t> buffer;
     uint32_t bigEndianConnectionStringSize;
@@ -1488,7 +1502,9 @@ void DataSubscriber::Subscribe()
     for (size_t i = 0; i < connectionStringSize; ++i)
         buffer[5 + i] = connectionStringPtr[i];
 
+    startup.Mark("subscribe command built (bytes)", bufferSize);
     SendServerCommand(ServerCommand::Subscribe, buffer.data(), 0, bufferSize);
+    startup.Mark("subscribe send returned");
 
     // Reset TSSC decompresser on successful (re)subscription
     m_tsscLastOOSReportMutex.lock();