diff --git a/docs/Debugging.md b/docs/Debugging.md index 4b464836..6a159851 100644 --- a/docs/Debugging.md +++ b/docs/Debugging.md @@ -6,12 +6,12 @@ An instance of [Application Insights](https://docs.microsoft.com/en-us/azure/azu ### Telemetry Collected All telemetry below can be viewed in [Application Insights](https://docs.microsoft.com/en-us/azure/azure-monitor/app/app-insights-overview). Select the [metrics](https://docs.microsoft.com/en-us/azure/azure-monitor/platform/metrics-charts) section. The telemetry documented will fall under the **custom** category. -* **MeasurementIngestionLatency**: The difference between the ingestion time on the event hub end point and received by the FHIR conversion function. Measured in seconds. +* **MeasurementIngestionLatency**: The difference between the ingestion time on the event hub end point and received by the FHIR conversion function. Measured in milliseconds. * **MeasurementGroup**: The number of unique groupings of measurements across type, device, patient, and configured time period generated by the FHIR conversion function. Should directly correlate to the number of observations being created or updated. * **Measurement**: The number of raw value readings received by the FHIR conversion function. * **DeviceEvent**: The number of raw events received by the connector prior to any normalization. * **NormalizedEvent**: The number of mapped normalized values outputted from the normalization step. -* **DeviceEventProcessingLatency**: The time between an event's ingestion and being processed for normalization. A large value here indicates a backlog of events being processed for normalization. Measured in seconds. +* **DeviceEventProcessingLatency**: The time between an event's ingestion and being processed for normalization. A large value here indicates a backlog of events being processed for normalization. Measured in milliseconds. * **Handled Exceptions**: The number of handled exceptions for a given category. In order to not stall the pipeline certain non recoverable errors are categorized and then recorded as telemetry. The current exceptions handled are: |Exception|Description diff --git a/src/func/Microsoft.Health.Fhir.Ingest.Host/IomtConnectorFunctions.cs b/src/func/Microsoft.Health.Fhir.Ingest.Host/IomtConnectorFunctions.cs index fc4e5d70..4548fc74 100644 --- a/src/func/Microsoft.Health.Fhir.Ingest.Host/IomtConnectorFunctions.cs +++ b/src/func/Microsoft.Health.Fhir.Ingest.Host/IomtConnectorFunctions.cs @@ -46,7 +46,7 @@ public async Task MeasurementCollectionToFhir( catch (Exception ex) { _logger.LogMetric( - IomtMetrics.UnhandledException(ex.GetType().Name, ConnectorStage.FHIRConversion), + IomtMetrics.UnhandledException(ex.GetType().Name, ConnectorOperation.FHIRConversion), 1); throw; } @@ -77,7 +77,7 @@ public async Task NormalizeDeviceData( catch (Exception ex) { _logger.LogMetric( - IomtMetrics.UnhandledException(ex.GetType().Name, ConnectorStage.Normalization), + IomtMetrics.UnhandledException(ex.GetType().Name, ConnectorOperation.Normalization), 1); throw; } diff --git a/src/lib/Microsoft.Health.Common/Telemetry/Metric.cs b/src/lib/Microsoft.Health.Common/Telemetry/Metric.cs index 9bd0fe60..63e505da 100644 --- a/src/lib/Microsoft.Health.Common/Telemetry/Metric.cs +++ b/src/lib/Microsoft.Health.Common/Telemetry/Metric.cs @@ -15,8 +15,16 @@ public Metric(string name, IDictionary dimensions) Dimensions = dimensions; } - public string Name { get; } + public string Name { get; set; } public IDictionary Dimensions { get; } + + public void AddPrefixToName(string prefix) + { + if (!Name.StartsWith(prefix, System.StringComparison.CurrentCulture)) + { + Name = $"{prefix}{Name}"; + } + } } } diff --git a/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/ConnectorStage.cs b/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/ConnectorOperation.cs similarity index 67% rename from src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/ConnectorStage.cs rename to src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/ConnectorOperation.cs index 8b19d4ea..1446214a 100644 --- a/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/ConnectorStage.cs +++ b/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/ConnectorOperation.cs @@ -5,31 +5,31 @@ namespace Microsoft.Health.Common.Telemetry { - public static class ConnectorStage + public static class ConnectorOperation { /// /// The setup stage of the IoMT Connector /// - public static string Setup => nameof(ConnectorStage.Setup); + public static string Setup => nameof(ConnectorOperation.Setup); /// /// The normalization stage of the IoMT Connector /// - public static string Normalization => nameof(ConnectorStage.Normalization); + public static string Normalization => nameof(ConnectorOperation.Normalization); /// /// The grouping stage of the IoMT Connector /// - public static string Grouping => nameof(ConnectorStage.Grouping); + public static string Grouping => nameof(ConnectorOperation.Grouping); /// /// The FHIR conversion stage of the IoMT Connector /// - public static string FHIRConversion => nameof(ConnectorStage.FHIRConversion); + public static string FHIRConversion => nameof(ConnectorOperation.FHIRConversion); /// /// If a stage is not determined. /// - public static string Unknown => nameof(ConnectorStage.Unknown); + public static string Unknown => nameof(ConnectorOperation.Unknown); } } diff --git a/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/DimensionNames.cs b/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/DimensionNames.cs index 5b811c86..d76f52a3 100644 --- a/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/DimensionNames.cs +++ b/src/lib/Microsoft.Health.Common/Telemetry/Metrics/Dimensions/DimensionNames.cs @@ -20,7 +20,7 @@ public static class DimensionNames /// /// A metric dimension that represents each ingestion stage of the IoMT Connector. /// - public static string Stage => nameof(DimensionNames.Stage); + public static string Operation => nameof(DimensionNames.Operation); /// /// A metric dimension for a error type. diff --git a/src/lib/Microsoft.Health.Extensions.Fhir/MultipleResourceFoundException.cs b/src/lib/Microsoft.Health.Extensions.Fhir/MultipleResourceFoundException.cs index c1e8da84..df44f23b 100644 --- a/src/lib/Microsoft.Health.Extensions.Fhir/MultipleResourceFoundException.cs +++ b/src/lib/Microsoft.Health.Extensions.Fhir/MultipleResourceFoundException.cs @@ -42,7 +42,7 @@ public MultipleResourceFoundException(string message, Exception innerException) { DimensionNames.Category, Category.Errors }, { DimensionNames.ErrorType, ErrorType.FHIRResourceError }, { DimensionNames.ErrorSeverity, ErrorSeverity.Warning }, - { DimensionNames.Stage, ConnectorStage.FHIRConversion }, + { DimensionNames.Operation, ConnectorOperation.FHIRConversion }, }); } } diff --git a/src/lib/Microsoft.Health.Fhir.Ingest.Template/TemplateNotFoundException.cs b/src/lib/Microsoft.Health.Fhir.Ingest.Template/TemplateNotFoundException.cs index b9bfda71..9bf921a1 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest.Template/TemplateNotFoundException.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest.Template/TemplateNotFoundException.cs @@ -21,7 +21,7 @@ public class TemplateNotFoundException : { DimensionNames.Category, Category.Errors }, { DimensionNames.ErrorType, ErrorType.GeneralError }, { DimensionNames.ErrorSeverity, ErrorSeverity.Critical }, - { DimensionNames.Stage, ConnectorStage.Unknown }, + { DimensionNames.Operation, ConnectorOperation.Unknown }, }); public TemplateNotFoundException(string message) diff --git a/src/lib/Microsoft.Health.Fhir.Ingest/Data/CorrelationIdNotDefinedException.cs b/src/lib/Microsoft.Health.Fhir.Ingest/Data/CorrelationIdNotDefinedException.cs index 5b315e7b..6daecc4f 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest/Data/CorrelationIdNotDefinedException.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest/Data/CorrelationIdNotDefinedException.cs @@ -35,7 +35,7 @@ public CorrelationIdNotDefinedException() { DimensionNames.Category, Category.Errors }, { DimensionNames.ErrorType, ErrorType.DeviceMessageError }, { DimensionNames.ErrorSeverity, ErrorSeverity.Critical }, - { DimensionNames.Stage, ConnectorStage.Grouping }, + { DimensionNames.Operation, ConnectorOperation.Grouping }, }); } } diff --git a/src/lib/Microsoft.Health.Fhir.Ingest/FhirResourceNotFoundException.cs b/src/lib/Microsoft.Health.Fhir.Ingest/FhirResourceNotFoundException.cs index ead298f4..932c5400 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest/FhirResourceNotFoundException.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest/FhirResourceNotFoundException.cs @@ -46,7 +46,7 @@ public FhirResourceNotFoundException(string message, Exception innerException) { DimensionNames.Category, Category.Errors }, { DimensionNames.ErrorType, ErrorType.FHIRResourceError }, { DimensionNames.ErrorSeverity, ErrorSeverity.Warning }, - { DimensionNames.Stage, ConnectorStage.FHIRConversion }, + { DimensionNames.Operation, ConnectorOperation.FHIRConversion }, }); } } diff --git a/src/lib/Microsoft.Health.Fhir.Ingest/ResourceIdentityNotDefinedException.cs b/src/lib/Microsoft.Health.Fhir.Ingest/ResourceIdentityNotDefinedException.cs index 54cea253..c462de66 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest/ResourceIdentityNotDefinedException.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest/ResourceIdentityNotDefinedException.cs @@ -46,7 +46,7 @@ public ResourceIdentityNotDefinedException(string message, Exception innerExcept { DimensionNames.Category, Category.Errors }, { DimensionNames.ErrorType, ErrorType.FHIRResourceError }, { DimensionNames.ErrorSeverity, ErrorSeverity.Warning }, - { DimensionNames.Stage, ConnectorStage.FHIRConversion }, + { DimensionNames.Operation, ConnectorOperation.FHIRConversion }, }); } } diff --git a/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementEventNormalizationService.cs b/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementEventNormalizationService.cs index 23df8b00..0471f206 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementEventNormalizationService.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementEventNormalizationService.cs @@ -82,6 +82,10 @@ private async Task StartConsumer(ISourceBlock producer, IAsyncCollect IomtMetrics.DeviceEventProcessingLatency(), (DateTime.UtcNow - evt.SystemProperties.EnqueuedTimeUtc).TotalSeconds); + _log.LogMetric( + IomtMetrics.DeviceEventProcessingLatencyMs(), + (DateTime.UtcNow - evt.SystemProperties.EnqueuedTimeUtc).TotalMilliseconds); + var token = _converter.Convert(evt); foreach (var measurement in _contentTemplate.GetMeasurements(token)) { diff --git a/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementFhirImportService.cs b/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementFhirImportService.cs index 8c367cf1..6a38f369 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementFhirImportService.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest/Service/MeasurementFhirImportService.cs @@ -53,7 +53,7 @@ public async Task ProcessStreamAsync(Stream data, string templateDefinition, ITe } catch (Exception ex) { - if (!Options.ExceptionService.HandleException(ex, log, ConnectorStage.FHIRConversion)) + if (!Options.ExceptionService.HandleException(ex, log, ConnectorOperation.FHIRConversion)) { log.LogError(ex); throw; @@ -109,11 +109,13 @@ await Task.Run(() => continue; } - var latency = (nowRef - m.IngestionTimeUtc.Value).TotalSeconds; - log.LogMetric( IomtMetrics.MeasurementIngestionLatency(), - latency); + (nowRef - m.IngestionTimeUtc.Value).TotalSeconds); + + log.LogMetric( + IomtMetrics.MeasurementIngestionLatencyMs(), + (nowRef - m.IngestionTimeUtc.Value).TotalMilliseconds); } }).ConfigureAwait(false); } diff --git a/src/lib/Microsoft.Health.Fhir.Ingest/Service/PatientDeviceMismatchException.cs b/src/lib/Microsoft.Health.Fhir.Ingest/Service/PatientDeviceMismatchException.cs index b3dcf30d..df2852e1 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest/Service/PatientDeviceMismatchException.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest/Service/PatientDeviceMismatchException.cs @@ -35,7 +35,7 @@ public PatientDeviceMismatchException() { DimensionNames.Category, Category.Errors }, { DimensionNames.ErrorType, ErrorType.FHIRResourceError }, { DimensionNames.ErrorSeverity, ErrorSeverity.Warning }, - { DimensionNames.Stage, ConnectorStage.FHIRConversion }, + { DimensionNames.Operation, ConnectorOperation.FHIRConversion }, }); } } diff --git a/src/lib/Microsoft.Health.Fhir.Ingest/Telemetry/Metrics/IomtMetrics.cs b/src/lib/Microsoft.Health.Fhir.Ingest/Telemetry/Metrics/IomtMetrics.cs index ddc5417a..2d1ecfbb 100644 --- a/src/lib/Microsoft.Health.Fhir.Ingest/Telemetry/Metrics/IomtMetrics.cs +++ b/src/lib/Microsoft.Health.Fhir.Ingest/Telemetry/Metrics/IomtMetrics.cs @@ -18,7 +18,7 @@ public static class IomtMetrics private static string _categoryDimension = DimensionNames.Category; private static string _errorTypeDimension = DimensionNames.ErrorType; private static string _errorSeverityDimension = DimensionNames.ErrorSeverity; - private static string _stageDimension = DimensionNames.Stage; + private static string _operationDimension = DimensionNames.Operation; private static Metric _measurementIngestionLatency = new Metric( "MeasurementIngestionLatency", @@ -26,7 +26,16 @@ public static class IomtMetrics { { _nameDimension, "MeasurementIngestionLatency" }, { _categoryDimension, Category.Latency }, - { _stageDimension, ConnectorStage.FHIRConversion }, + { _operationDimension, ConnectorOperation.FHIRConversion }, + }); + + private static Metric _measurementIngestionLatencyMs = new Metric( + "MeasurementIngestionLatencyMs", + new Dictionary + { + { _nameDimension, "MeasurementIngestionLatencyMs" }, + { _categoryDimension, Category.Latency }, + { _operationDimension, ConnectorOperation.FHIRConversion }, }); private static Metric _measurementGroup = new Metric( @@ -35,7 +44,7 @@ public static class IomtMetrics { { _nameDimension, "MeasurementGroup" }, { _categoryDimension, Category.Traffic }, - { _stageDimension, ConnectorStage.FHIRConversion }, + { _operationDimension, ConnectorOperation.FHIRConversion }, }); private static Metric _measurement = new Metric( @@ -44,7 +53,7 @@ public static class IomtMetrics { { _nameDimension, "Measurement" }, { _categoryDimension, Category.Traffic }, - { _stageDimension, ConnectorStage.FHIRConversion }, + { _operationDimension, ConnectorOperation.FHIRConversion }, }); private static Metric _deviceEvent = new Metric( @@ -53,7 +62,7 @@ public static class IomtMetrics { { _nameDimension, "DeviceEvent" }, { _categoryDimension, Category.Traffic }, - { _stageDimension, ConnectorStage.Normalization }, + { _operationDimension, ConnectorOperation.Normalization }, }); private static Metric _normalizedEvent = new Metric( @@ -62,7 +71,7 @@ public static class IomtMetrics { { _nameDimension, "NormalizedEvent" }, { _categoryDimension, Category.Traffic }, - { _stageDimension, ConnectorStage.Normalization }, + { _operationDimension, ConnectorOperation.Normalization }, }); private static Metric _deviceEventProcessingLatency = new Metric( @@ -71,7 +80,16 @@ public static class IomtMetrics { { _nameDimension, "DeviceEventProcessingLatency" }, { _categoryDimension, Category.Latency }, - { _stageDimension, ConnectorStage.Normalization }, + { _operationDimension, ConnectorOperation.Normalization }, + }); + + private static Metric _deviceEventProcessingLatencyMs = new Metric( + "DeviceEventProcessingLatencyMs", + new Dictionary + { + { _nameDimension, "DeviceEventProcessingLatencyMs" }, + { _categoryDimension, Category.Latency }, + { _operationDimension, ConnectorOperation.Normalization }, }); private static Metric _notSupported = new Metric( @@ -82,7 +100,7 @@ public static class IomtMetrics { _categoryDimension, Category.Errors }, { _errorTypeDimension, ErrorType.FHIRResourceError }, { _errorSeverityDimension, ErrorSeverity.Warning }, - { _stageDimension, ConnectorStage.FHIRConversion }, + { _operationDimension, ConnectorOperation.FHIRConversion }, }); /// @@ -93,6 +111,14 @@ public static Metric MeasurementIngestionLatency() return _measurementIngestionLatency; } + /// + /// The latency between event ingestion and output to FHIR processor, in milliseconds. + /// + public static Metric MeasurementIngestionLatencyMs() + { + return _measurementIngestionLatencyMs; + } + /// /// The number of measurement groups generated by the FHIR processor based on provided input. /// @@ -133,6 +159,14 @@ public static Metric DeviceEventProcessingLatency() return _deviceEventProcessingLatency; } + /// + /// The latency between the event ingestion time and normalization processing, in milliseconds. An increase here indicates a backlog of messages to process. + /// + public static Metric DeviceEventProcessingLatencyMs() + { + return _deviceEventProcessingLatencyMs; + } + /// /// A metric for when FHIR resource does not support the provided type as a value. /// @@ -145,14 +179,14 @@ public static Metric UnhandledException(string exceptionName, string connectorSt { EnsureArg.IsNotNull(exceptionName); return new Metric( - exceptionName, + "UnhandledException", new Dictionary { { _nameDimension, exceptionName }, { _categoryDimension, Category.Errors }, { _errorTypeDimension, ErrorType.GeneralError }, { _errorSeverityDimension, ErrorSeverity.Critical }, - { _stageDimension, connectorStage }, + { _operationDimension, connectorStage }, }); } @@ -165,7 +199,8 @@ public static Metric HandledException(string exceptionName, string connectorStag { _nameDimension, exceptionName }, { _categoryDimension, Category.Errors }, { _errorTypeDimension, ErrorType.GeneralError }, - { _stageDimension, connectorStage }, + { _errorSeverityDimension, ErrorSeverity.Critical }, + { _operationDimension, connectorStage }, }); } } diff --git a/test/Microsoft.Health.Fhir.Ingest.UnitTests/Service/MeasurementFhirImportServiceTests.cs b/test/Microsoft.Health.Fhir.Ingest.UnitTests/Service/MeasurementFhirImportServiceTests.cs index 5ab0efd3..740e0578 100644 --- a/test/Microsoft.Health.Fhir.Ingest.UnitTests/Service/MeasurementFhirImportServiceTests.cs +++ b/test/Microsoft.Health.Fhir.Ingest.UnitTests/Service/MeasurementFhirImportServiceTests.cs @@ -107,7 +107,7 @@ public async void GivenExceptionDuringParseStreamAsync_WhenParseStreamAsyncAndEx options.TemplateFactory.Received(1).Create(string.Empty); await fhirService.ReceivedWithAnyArgs(2).ProcessAsync(default, default); - options.ExceptionService.Received(2).HandleException(exception, log, ConnectorStage.FHIRConversion); + options.ExceptionService.Received(2).HandleException(exception, log, ConnectorOperation.FHIRConversion); } [Fact] @@ -182,7 +182,7 @@ public async void GivenMultipleMeasurementsInMeasurementGroup_WhenParseStreamAsy // Telemetry logging is async/non-blocking. Ensure enough time has pass so section is hit. await Task.Delay(1000); - log.ReceivedWithAnyArgs(4).LogMetric(null, 0d); + log.ReceivedWithAnyArgs(6).LogMetric(null, 0d); } private static Stream ToStream(object obj) diff --git a/test/Microsoft.Health.Fhir.Ingest.UnitTests/Telemetry/ExceptionTelemetryProcessorTests.cs b/test/Microsoft.Health.Fhir.Ingest.UnitTests/Telemetry/ExceptionTelemetryProcessorTests.cs index 8bc06d51..fc98b96d 100644 --- a/test/Microsoft.Health.Fhir.Ingest.UnitTests/Telemetry/ExceptionTelemetryProcessorTests.cs +++ b/test/Microsoft.Health.Fhir.Ingest.UnitTests/Telemetry/ExceptionTelemetryProcessorTests.cs @@ -28,7 +28,7 @@ public void GivenHandledExceptionTypes_WhenHandleExpection_ThenMetricLoggedAndTr var ex = Activator.CreateInstance(exType) as Exception; var exProcessor = new ExceptionTelemetryProcessor(); - var handled = exProcessor.HandleException(ex, log, ConnectorStage.FHIRConversion); + var handled = exProcessor.HandleException(ex, log, ConnectorOperation.FHIRConversion); Assert.True(handled); log.ReceivedWithAnyArgs(1).LogMetric(null, default(double)); @@ -42,7 +42,7 @@ public void GivenUnhandledExceptionTypes_WhenHandleExpection_ThenNoMetricLoggedA var ex = Activator.CreateInstance(exType) as Exception; var exProcessor = new ExceptionTelemetryProcessor(); - var handled = exProcessor.HandleException(ex, log, ConnectorStage.FHIRConversion); + var handled = exProcessor.HandleException(ex, log, ConnectorOperation.FHIRConversion); Assert.False(handled); log.DidNotReceiveWithAnyArgs().LogMetric(null, default(double));