|
| 1 | +// Copyright (c) .NET Foundation. All rights reserved. |
| 2 | +// Licensed under the MIT License. See License.txt in the project root for license information. |
| 3 | + |
| 4 | +using System; |
| 5 | +using System.Collections.Generic; |
| 6 | +using System.Linq; |
| 7 | +using System.Threading; |
| 8 | +using System.Threading.Tasks; |
| 9 | +using Azure.Messaging.EventHubs; |
| 10 | +using Azure.Messaging.EventHubs.Primitives; |
| 11 | +using Microsoft.Azure.WebJobs.EventHubs.Listeners; |
| 12 | +using Microsoft.Extensions.Logging; |
| 13 | + |
| 14 | +namespace Microsoft.Azure.WebJobs.Extensions.EventHubs.Listeners |
| 15 | +{ |
| 16 | + internal class EventHubMetricsProvider |
| 17 | + { |
| 18 | + private const int PartitionLogIntervalInMinutes = 5; |
| 19 | + |
| 20 | + private readonly string _functionId; |
| 21 | + private readonly IEventHubConsumerClient _client; |
| 22 | + private readonly ILogger _logger; |
| 23 | + private readonly BlobCheckpointStoreInternal _checkpointStore; |
| 24 | + |
| 25 | + private DateTime _nextPartitionLogTime; |
| 26 | + private DateTime _nextPartitionWarningTime; |
| 27 | + |
| 28 | + // Used for mocking. |
| 29 | + public EventHubMetricsProvider() { } |
| 30 | + |
| 31 | + public EventHubMetricsProvider(string functionId, IEventHubConsumerClient client, BlobCheckpointStoreInternal checkpointStore, ILogger logger) |
| 32 | + { |
| 33 | + _functionId = functionId; |
| 34 | + _logger = logger; |
| 35 | + _checkpointStore = checkpointStore; |
| 36 | + _nextPartitionLogTime = DateTime.UtcNow; |
| 37 | + _nextPartitionWarningTime = DateTime.UtcNow; |
| 38 | + _client = client; |
| 39 | + } |
| 40 | + |
| 41 | + public async Task<EventHubsTriggerMetrics> GetMetricsAsync() |
| 42 | + { |
| 43 | + EventHubsTriggerMetrics metrics = new EventHubsTriggerMetrics(); |
| 44 | + string[] partitions = null; |
| 45 | + |
| 46 | + try |
| 47 | + { |
| 48 | + partitions = await _client.GetPartitionsAsync().ConfigureAwait(false); |
| 49 | + metrics.PartitionCount = partitions.Length; |
| 50 | + } |
| 51 | + catch (Exception e) |
| 52 | + { |
| 53 | + _logger.LogWarning($"Encountered an exception while checking EventHub '{_client.EventHubName}'. Error: {e.Message}"); |
| 54 | + return metrics; |
| 55 | + } |
| 56 | + |
| 57 | + // Get the PartitionRuntimeInformation for all partitions |
| 58 | + _logger.LogInformation($"Querying partition information for {partitions.Length} partitions."); |
| 59 | + var partitionPropertiesTasks = new Task<PartitionProperties>[partitions.Length]; |
| 60 | + var checkpointTasks = new Task<EventProcessorCheckpoint>[partitionPropertiesTasks.Length]; |
| 61 | + |
| 62 | + for (int i = 0; i < partitions.Length; i++) |
| 63 | + { |
| 64 | + partitionPropertiesTasks[i] = _client.GetPartitionPropertiesAsync(partitions[i]); |
| 65 | + |
| 66 | + checkpointTasks[i] = _checkpointStore.GetCheckpointAsync( |
| 67 | + _client.FullyQualifiedNamespace, |
| 68 | + _client.EventHubName, |
| 69 | + _client.ConsumerGroup, |
| 70 | + partitions[i], |
| 71 | + CancellationToken.None); |
| 72 | + } |
| 73 | + |
| 74 | + await Task.WhenAll(partitionPropertiesTasks).ConfigureAwait(false); |
| 75 | + EventProcessorCheckpoint[] checkpoints; |
| 76 | + |
| 77 | + try |
| 78 | + { |
| 79 | + checkpoints = await Task.WhenAll(checkpointTasks).ConfigureAwait(false); |
| 80 | + } |
| 81 | + catch |
| 82 | + { |
| 83 | + // GetCheckpointsAsync would log |
| 84 | + return metrics; |
| 85 | + } |
| 86 | + |
| 87 | + return CreateTriggerMetrics(partitionPropertiesTasks.Select(t => t.Result).ToList(), checkpoints); |
| 88 | + } |
| 89 | + |
| 90 | + private EventHubsTriggerMetrics CreateTriggerMetrics(List<PartitionProperties> partitionRuntimeInfo, EventProcessorCheckpoint[] checkpoints, bool alwaysLog = false) |
| 91 | + { |
| 92 | + long totalUnprocessedEventCount = 0; |
| 93 | + |
| 94 | + DateTime utcNow = DateTime.UtcNow; |
| 95 | + bool logPartitionInfo = alwaysLog ? true : utcNow >= _nextPartitionLogTime; |
| 96 | + bool logPartitionWarning = alwaysLog ? true : utcNow >= _nextPartitionWarningTime; |
| 97 | + |
| 98 | + // For each partition, get the last enqueued sequence number. |
| 99 | + // If the last enqueued sequence number does not equal the SequenceNumber from the lease info in storage, |
| 100 | + // accumulate new event counts across partitions to derive total new event counts. |
| 101 | + List<string> partitionErrors = new List<string>(); |
| 102 | + for (int i = 0; i < partitionRuntimeInfo.Count; i++) |
| 103 | + { |
| 104 | + var partitionProperties = partitionRuntimeInfo[i]; |
| 105 | + |
| 106 | + var checkpoint = (BlobCheckpointStoreInternal.BlobStorageCheckpoint)checkpoints.SingleOrDefault(c => c?.PartitionId == partitionProperties.Id); |
| 107 | + |
| 108 | + // Check for the unprocessed messages when there are messages on the Event Hub partition |
| 109 | + // In that case, LastEnqueuedSequenceNumber will be >= 0 |
| 110 | + |
| 111 | + if ((partitionProperties.LastEnqueuedSequenceNumber != -1 && partitionProperties.LastEnqueuedSequenceNumber != (checkpoint?.SequenceNumber ?? -1)) |
| 112 | + || (checkpoint == null && partitionProperties.LastEnqueuedSequenceNumber >= 0)) |
| 113 | + { |
| 114 | + long partitionUnprocessedEventCount = GetUnprocessedEventCount(partitionProperties, checkpoint); |
| 115 | + totalUnprocessedEventCount += partitionUnprocessedEventCount; |
| 116 | + } |
| 117 | + } |
| 118 | + |
| 119 | + // Only log if not all partitions are failing or it's time to log |
| 120 | + if (partitionErrors.Count > 0 && (partitionErrors.Count != partitionRuntimeInfo.Count || logPartitionWarning)) |
| 121 | + { |
| 122 | + _logger.LogWarning($"Function '{_functionId}': Unable to deserialize partition or checkpoint info with the " + |
| 123 | + $"following errors: {string.Join(" ", partitionErrors)}"); |
| 124 | + _nextPartitionWarningTime = DateTime.UtcNow.AddMinutes(PartitionLogIntervalInMinutes); |
| 125 | + } |
| 126 | + |
| 127 | + if (totalUnprocessedEventCount > 0 && logPartitionInfo) |
| 128 | + { |
| 129 | + _logger.LogInformation($"Function '{_functionId}', Total new events: {totalUnprocessedEventCount}"); |
| 130 | + _nextPartitionLogTime = DateTime.UtcNow.AddMinutes(PartitionLogIntervalInMinutes); |
| 131 | + } |
| 132 | + |
| 133 | + return new EventHubsTriggerMetrics |
| 134 | + { |
| 135 | + Timestamp = DateTime.UtcNow, |
| 136 | + PartitionCount = partitionRuntimeInfo.Count, |
| 137 | + EventCount = totalUnprocessedEventCount |
| 138 | + }; |
| 139 | + } |
| 140 | + |
| 141 | + // Get the number of unprocessed events by deriving the delta between the server side info and the partition lease info, |
| 142 | + private static long GetUnprocessedEventCount(PartitionProperties partitionInfo, BlobCheckpointStoreInternal.BlobStorageCheckpoint checkpoint) |
| 143 | + { |
| 144 | + // If the partition is empty, there are no events to process. |
| 145 | + |
| 146 | + if (partitionInfo.IsEmpty) |
| 147 | + { |
| 148 | + return 0; |
| 149 | + } |
| 150 | + |
| 151 | + // If there is no checkpoint and the beginning and last sequence numbers for the partition are the same |
| 152 | + // this partition received its first event. |
| 153 | + |
| 154 | + if (checkpoint == null |
| 155 | + && partitionInfo.LastEnqueuedSequenceNumber == partitionInfo.BeginningSequenceNumber) |
| 156 | + { |
| 157 | + return 1; |
| 158 | + } |
| 159 | + |
| 160 | + var startingSequenceNumber = checkpoint?.SequenceNumber switch |
| 161 | + { |
| 162 | + // There was no checkpoint, use the beginning sequence number - 1, since |
| 163 | + // that event hasn't been processed yet. |
| 164 | + |
| 165 | + null => partitionInfo.BeginningSequenceNumber - 1, |
| 166 | + |
| 167 | + // Use the checkpoint. |
| 168 | + |
| 169 | + long seq => seq |
| 170 | + }; |
| 171 | + |
| 172 | + // For normal scenarios, the last sequence number will be greater than the starting number and |
| 173 | + // simple subtraction can be used. |
| 174 | + |
| 175 | + if (partitionInfo.LastEnqueuedSequenceNumber > startingSequenceNumber) |
| 176 | + { |
| 177 | + return (partitionInfo.LastEnqueuedSequenceNumber - startingSequenceNumber); |
| 178 | + } |
| 179 | + |
| 180 | + // Partition is a circular buffer, so it is possible that |
| 181 | + // LastEnqueuedSequenceNumber < startingSequenceNumber |
| 182 | + |
| 183 | + long count = 0; |
| 184 | + unchecked |
| 185 | + { |
| 186 | + count = (long.MaxValue - partitionInfo.LastEnqueuedSequenceNumber) + startingSequenceNumber; |
| 187 | + } |
| 188 | + |
| 189 | + // It's possible for the starting sequence number to be ahead of the last sequence number, |
| 190 | + // especially if checkpointing is happening often and load is very low. If count is negative, |
| 191 | + // we need to know that this read is invalid, so return 0. |
| 192 | + // e.g., (9223372036854775807 - 10) + 11 = -9223372036854775808 |
| 193 | + |
| 194 | + return (count < 0) ? 0 : count; |
| 195 | + } |
| 196 | + } |
| 197 | +} |
0 commit comments