public void Logger_Stats_MessageSizeLimit()
{
const string testName = "Logger_Stats_MessageSizeLimit";
TestLogConsumer logConsumer = new TestLogConsumer();
TraceLogger.LogConsumers.Add(logConsumer);
TraceLogger logger1 = TraceLogger.GetLogger(testName);
const string StatsCounterBaseName = "LoggerTest.Stats.Size";
for (int i = 1; i <= 1000; i++)
{
StatisticName counterName = new StatisticName(StatsCounterBaseName + "." + i);
CounterStatistic ctr = CounterStatistic.FindOrCreate(counterName);
ctr.IncrementBy(i);
}
LogStatistics statsLogger = new LogStatistics(TimeSpan.Zero, true);
statsLogger.DumpCounters().Wait();
int count = logConsumer.GetEntryCount((int)ErrorCode.PerfCounterDumpAll);
Console.WriteLine(count + " stats log message entries written");
Assert.IsTrue(count > 1, "Should be some stats log message entries - saw " + count);
Assert.AreEqual(0, logConsumer.GetEntryCount((int)ErrorCode.Logger_LogMessageTruncated), "Should not see any 'Message truncated' message");
}
public void Counter_SetValue()
{
StatisticName name = new StatisticName(CounterName);
int val = random.Next(1000000);
CounterStatistic ctr = CounterStatistic.FindOrCreate(name);
ctr.IncrementBy(val);
Assert.Equal(val, ctr.GetCurrentValue());
}
private async Task AsyncTimerCallback(object state)
{
try
{
var myQueueId = (QueueId)(state);
if (timer == null)
{
return; // timer was already removed, last tick
}
IQueueAdapterReceiver rcvr = receiver;
// loop through the queue until it is empty.
while (true)
{
// Retrive one multiBatch from the queue. Every multiBatch has an IEnumerable of IBatchContainers, each IBatchContainer may have multiple events.
IEnumerable <IBatchContainer> msgsEnumerable = await rcvr.GetQueueMessagesAsync();
List <IBatchContainer> multiBatch = null;
if (msgsEnumerable != null)
{
multiBatch = msgsEnumerable.ToList();
}
if (multiBatch == null || multiBatch.Count == 0)
{
return; // queue is empty. Exit the loop. Will attempt again in the next timer callback.
}
rcvr.AddToCache(multiBatch);
numMessages += multiBatch.Count;
numReadMessagesCounter.IncrementBy(multiBatch.Count);
if (logger.IsVerbose2)
{
logger.Verbose2((int)ErrorCode.PersistentStreamPullingAgent_11, "Got {0} messages from queue {1}. So far {2} msgs from this queue.",
multiBatch.Count, myQueueId.ToStringWithHashCode(), numMessages);
}
foreach (var group in multiBatch.Where(m => m != null)
.GroupBy(container => new Tuple <Guid, string>(container.StreamGuid, container.StreamNamespace)))
{
var streamId = StreamId.GetStreamId(group.Key.Item1, queueAdapter.Name, group.Key.Item2);
StreamConsumerCollection streamData;
if (pubSubCache.TryGetValue(streamId, out streamData))
{
StartInactiveCursors(streamId, streamData); // if this is an existing stream, start any inactive cursors
}
else
{
RegisterStream(streamId, group.First().SequenceToken); // if this is a new stream register as producer of stream in pub sub system
}
}
}
}
catch (Exception exc)
{
logger.Error((int)ErrorCode.PersistentStreamPullingAgent_12,
String.Format("Exception while PersistentStreamPullingAgentGrain.AsyncTimerCallback"), exc);
}
}
public void Counter_DecrementBy()
{
StatisticName name = new StatisticName(CounterName);
int startValue = 10;
int newValue = startValue - 1;
CounterStatistic ctr = CounterStatistic.FindOrCreate(name);
ctr.IncrementBy(startValue);
Assert.Equal(startValue, ctr.GetCurrentValue());
ctr.DecrementBy(1);
Assert.Equal(newValue, ctr.GetCurrentValue());
}
public void Counter_IncrementFromMinInt()
{
StatisticName name = new StatisticName(CounterName);
int val = int.MinValue;
CounterStatistic ctr = CounterStatistic.FindOrCreate(name);
ctr.IncrementBy(val);
Assert.Equal(val, ctr.GetCurrentValue());
ctr.Increment();
Assert.Equal(val + 1, ctr.GetCurrentValue());
ctr.Increment();
Assert.Equal(val + 2, ctr.GetCurrentValue());
}
public void Counter_IncrementFromMaxInt()
{
StatisticName name = new StatisticName("Counter6");
int val = int.MaxValue;
long longVal = int.MaxValue;
Assert.AreEqual(longVal, val);
CounterStatistic ctr = CounterStatistic.FindOrCreate(name);
ctr.IncrementBy(val);
Assert.AreEqual(val, ctr.GetCurrentValue());
ctr.Increment();
Assert.AreEqual(longVal + 1, ctr.GetCurrentValue());
ctr.Increment();
Assert.AreEqual(longVal + 2, ctr.GetCurrentValue());
}
public void Logger_Stats_MessageSizeLimit()
{
const string testName = "Logger_Stats_MessageSizeLimit";
TestLogConsumer logConsumer = new TestLogConsumer(output);
LogManager.LogConsumers.Add(logConsumer);
Logger logger1 = LogManager.GetLogger(testName);
const string StatsCounterBaseName = "LoggerTest.Stats.Size";
var createdCounters = new List <string>();
try
{
for (int i = 1; i <= 1000; i++)
{
string name = StatsCounterBaseName + "." + i;
StatisticName counterName = new StatisticName(name);
CounterStatistic ctr = CounterStatistic.FindOrCreate(counterName);
ctr.IncrementBy(i);
createdCounters.Add(name);
}
LogStatistics statsLogger = new LogStatistics(TimeSpan.Zero, true);
statsLogger.DumpCounters().Wait();
int count = logConsumer.GetEntryCount((int)ErrorCode.PerfCounterDumpAll);
output.WriteLine(count + " stats log message entries written");
Assert.True(count > 1, "Should be some stats log message entries - saw " + count);
Assert.Equal(0, logConsumer.GetEntryCount((int)ErrorCode.Logger_LogMessageTruncated)); // "Should not see any 'Message truncated' message"
}
finally
{
createdCounters.ForEach(name => CounterStatistic.Delete(name));
}
}
/// <summary>
/// Read from queue.
/// Returns true, if data was read, false if it was not
/// </summary>
/// <param name="myQueueId"></param>
/// <param name="rcvr"></param>
/// <param name="maxCacheAddCount"></param>
/// <returns></returns>
private async Task <bool> ReadFromQueue(QueueId myQueueId, IQueueAdapterReceiver rcvr, int maxCacheAddCount)
{
if (rcvr == null)
{
return(false);
}
var now = DateTime.UtcNow;
// Try to cleanup the pubsub cache at the cadence of 10 times in the configurable StreamInactivityPeriod.
if ((now - lastTimeCleanedPubSubCache) >= config.StreamInactivityPeriod.Divide(StreamInactivityCheckFrequency))
{
lastTimeCleanedPubSubCache = now;
CleanupPubSubCache(now);
}
if (queueCache != null)
{
IList <IBatchContainer> purgedItems;
if (queueCache.TryPurgeFromCache(out purgedItems))
{
try
{
await rcvr.MessagesDeliveredAsync(purgedItems);
}
catch (Exception exc)
{
logger.Warn(ErrorCode.PersistentStreamPullingAgent_27,
$"Exception calling MessagesDeliveredAsync on queue {myQueueId}. Ignoring.", exc);
}
}
}
if (queueCache != null && queueCache.IsUnderPressure())
{
// Under back pressure. Exit the loop. Will attempt again in the next timer callback.
logger.Info((int)ErrorCode.PersistentStreamPullingAgent_24, "Stream cache is under pressure. Backing off.");
return(false);
}
// Retrieve one multiBatch from the queue. Every multiBatch has an IEnumerable of IBatchContainers, each IBatchContainer may have multiple events.
IList <IBatchContainer> multiBatch = await rcvr.GetQueueMessagesAsync(maxCacheAddCount);
if (multiBatch == null || multiBatch.Count == 0)
{
return(false); // queue is empty. Exit the loop. Will attempt again in the next timer callback.
}
queueCache?.AddToCache(multiBatch);
numMessages += multiBatch.Count;
numReadMessagesCounter.IncrementBy(multiBatch.Count);
if (logger.IsVerbose2)
{
logger.Verbose2(ErrorCode.PersistentStreamPullingAgent_11, "Got {0} messages from queue {1}. So far {2} msgs from this queue.",
multiBatch.Count, myQueueId.ToStringWithHashCode(), numMessages);
}
foreach (var group in
multiBatch
.Where(m => m != null)
.GroupBy(container => new Tuple <Guid, string>(container.StreamGuid, container.StreamNamespace)))
{
var streamId = StreamId.GetStreamId(group.Key.Item1, queueAdapter.Name, group.Key.Item2);
StreamSequenceToken startToken = group.First().SequenceToken;
StreamConsumerCollection streamData;
if (pubSubCache.TryGetValue(streamId, out streamData))
{
streamData.RefreshActivity(now);
StartInactiveCursors(streamData, startToken); // if this is an existing stream, start any inactive cursors
}
else
{
RegisterStream(streamId, startToken, now).Ignore(); // if this is a new stream register as producer of stream in pub sub system
}
}
return(true);
}
private async Task AsyncTimerCallback(object state)
{
try
{
var myQueueId = (QueueId)(state);
if (IsShutdown) return; // timer was already removed, last tick
IQueueAdapterReceiver rcvr = receiver;
int maxCacheAddCount = queueCache != null ? queueCache.MaxAddCount : QueueAdapterConstants.UNLIMITED_GET_QUEUE_MSG;
// loop through the queue until it is empty.
while (!IsShutdown) // timer will be set to null when we are asked to shudown.
{
var now = DateTime.UtcNow;
// Try to cleanup the pubsub cache at the cadence of 10 times in the configurable StreamInactivityPeriod.
if ((now - lastTimeCleanedPubSubCache) >= config.StreamInactivityPeriod.Divide(StreamInactivityCheckFrequency))
{
lastTimeCleanedPubSubCache = now;
CleanupPubSubCache(now);
}
if (queueCache != null)
{
IList<IBatchContainer> purgedItems;
if (queueCache.TryPurgeFromCache(out purgedItems))
{
try
{
await rcvr.MessagesDeliveredAsync(purgedItems);
}
catch (Exception exc)
{
logger.Warn((int)ErrorCode.PersistentStreamPullingAgent_27,
String.Format("Exception calling MessagesDeliveredAsync on queue {0}. Ignoring.", myQueueId), exc);
}
}
}
if (queueCache != null && queueCache.IsUnderPressure())
{
// Under back pressure. Exit the loop. Will attempt again in the next timer callback.
logger.Info((int)ErrorCode.PersistentStreamPullingAgent_24, "Stream cache is under pressure. Backing off.");
return;
}
// Retrive one multiBatch from the queue. Every multiBatch has an IEnumerable of IBatchContainers, each IBatchContainer may have multiple events.
IList<IBatchContainer> multiBatch = await rcvr.GetQueueMessagesAsync(maxCacheAddCount);
if (multiBatch == null || multiBatch.Count == 0) return; // queue is empty. Exit the loop. Will attempt again in the next timer callback.
if (queueCache != null)
{
queueCache.AddToCache(multiBatch);
}
numMessages += multiBatch.Count;
numReadMessagesCounter.IncrementBy(multiBatch.Count);
if (logger.IsVerbose2) logger.Verbose2((int)ErrorCode.PersistentStreamPullingAgent_11, "Got {0} messages from queue {1}. So far {2} msgs from this queue.",
multiBatch.Count, myQueueId.ToStringWithHashCode(), numMessages);
foreach (var group in
multiBatch
.Where(m => m != null)
.GroupBy(container => new Tuple<Guid, string>(container.StreamGuid, container.StreamNamespace)))
{
var streamId = StreamId.GetStreamId(group.Key.Item1, queueAdapter.Name, group.Key.Item2);
StreamConsumerCollection streamData;
if (pubSubCache.TryGetValue(streamId, out streamData))
{
streamData.RefreshActivity(now);
StartInactiveCursors(streamData); // if this is an existing stream, start any inactive cursors
}
else
{
RegisterStream(streamId, group.First().SequenceToken, now).Ignore(); // if this is a new stream register as producer of stream in pub sub system
}
}
}
}
catch (Exception exc)
{
logger.Error((int)ErrorCode.PersistentStreamPullingAgent_12, "Exception while PersistentStreamPullingAgentGrain.AsyncTimerCallback", exc);
}
}
/// <summary>
/// Read from queue.
/// Returns true, if data was read, false if it was not
/// </summary>
/// <param name="myQueueId"></param>
/// <param name="rcvr"></param>
/// <param name="maxCacheAddCount"></param>
/// <returns></returns>
private async Task <bool> ReadFromQueue(QueueId myQueueId, IQueueAdapterReceiver rcvr, int maxCacheAddCount)
{
if (rcvr == null)
{
return(false);
}
var now = DateTime.UtcNow;
// Try to cleanup the pubsub cache at the cadence of 10 times in the configurable StreamInactivityPeriod.
if ((now - lastTimeCleanedPubSubCache) >= this.options.StreamInactivityPeriod.Divide(StreamInactivityCheckFrequency))
{
lastTimeCleanedPubSubCache = now;
CleanupPubSubCache(now);
}
if (queueCache != null)
{
IList <IBatchContainer> purgedItems;
if (queueCache.TryPurgeFromCache(out purgedItems))
{
try
{
await rcvr.MessagesDeliveredAsync(purgedItems);
}
catch (Exception exc)
{
logger.LogWarning(
(int)ErrorCode.PersistentStreamPullingAgent_27,
exc,
"Exception calling MessagesDeliveredAsync on queue {MyQueueId}. Ignoring.",
myQueueId);
}
}
}
if (queueCache != null && queueCache.IsUnderPressure())
{
// Under back pressure. Exit the loop. Will attempt again in the next timer callback.
logger.LogInformation((int)ErrorCode.PersistentStreamPullingAgent_24, "Stream cache is under pressure. Backing off.");
return(false);
}
// Retrieve one multiBatch from the queue. Every multiBatch has an IEnumerable of IBatchContainers, each IBatchContainer may have multiple events.
IList <IBatchContainer> multiBatch = await rcvr.GetQueueMessagesAsync(maxCacheAddCount);
if (multiBatch == null || multiBatch.Count == 0)
{
return(false); // queue is empty. Exit the loop. Will attempt again in the next timer callback.
}
queueCache?.AddToCache(multiBatch);
numMessages += multiBatch.Count;
numReadMessagesCounter.IncrementBy(multiBatch.Count);
if (logger.IsEnabled(LogLevel.Trace))
{
logger.LogTrace(
(int)ErrorCode.PersistentStreamPullingAgent_11,
"Got {ReceivedCount} messages from queue {Queue}. So far {MessageCount} messages from this queue.",
multiBatch.Count,
myQueueId.ToStringWithHashCode(),
numMessages);
}
foreach (var group in
multiBatch
.Where(m => m != null)
.GroupBy(container => container.StreamId))
{
var streamId = new InternalStreamId(queueAdapter.Name, group.Key);
StreamSequenceToken startToken = group.First().SequenceToken;
StreamConsumerCollection streamData;
if (pubSubCache.TryGetValue(streamId, out streamData))
{
streamData.RefreshActivity(now);
if (streamData.StreamRegistered)
{
StartInactiveCursors(streamData,
startToken); // if this is an existing stream, start any inactive cursors
}
else
{
if (this.logger.IsEnabled(LogLevel.Debug))
{
this.logger.LogDebug(
$"Pulled new messages in stream {streamId} from the queue, but pulling agent haven't succeeded in" +
$"RegisterStream yet, will start deliver on this stream after RegisterStream succeeded");
}
}
}
else
{
RegisterStream(streamId, startToken, now).Ignore(); // if this is a new stream register as producer of stream in pub sub system
}
}
return(true);
}
