public void Start()
{
Log.Info("Entry queue start: started=" + started);
if (started)
{
return;
}
started = true; // this must be set before thread.Start
Log.Info("Entry queue create " + nconsumers + " consumer threads");
for (int i = 0; i < nconsumers; i++)
{
ethreads[i] = new EventQueueThread(Consume, i);
}
if (abort != null)
{
abort.Enabled = true;
}
}
private void Consume(object data)
{
if (data == null)
{
Log.Error("Log event consumption: got null data?!");
return;
}
EventQueueThread ethread = (EventQueueThread)data;
Log.Info("Log event consumption (thread " + ethread.Number + "): start");
EventEntry evtlog;
string procName;
string logpfx;
long tnevts = 0;
long errcnt = 0;
long errtime = DateTime.Now.Ticks;
string firstProcName = null;
F2BSection config = F2B.Config.Instance;
if (config.Processors.Count > 0)
{
firstProcName = config.Processors[0].Name;
}
while (started)
{
evtlog = null;
procName = null;
tnevts++;
logpfx = string.Format("Consuming({0}/{1}): ", ethread.Number, tnevts);
try
{
Tuple <EventEntry, string> entry;
#if DEBUG
if (Log.Level == EventLogEntryType.Information)
{
Log.Info(logpfx + "queue High(" + queueHigh.Count + ")/Medium(" + queueMedium.Count + ")/Low(" + queueLow.Count + ")");
}
int queueIndex =
#endif
BlockingCollection <Tuple <EventEntry, string> > .TakeFromAny(queue, out entry, cancel.Token);
#if DEBUG
if (Log.Level == EventLogEntryType.Information)
{
Log.Info(logpfx + "queue High(" + queueHigh.Count + ")/Medium(" + queueMedium.Count + ")/Low(" + queueLow.Count + "): queueIndex = " + queueIndex);
}
#endif
evtlog = entry.Item1;
procName = entry.Item2;
}
catch (OperationCanceledException)
{
Log.Info(logpfx + "Log event consumption canceled (started=" + started + ")");
continue;
}
#if DEBUG
// evtlog can become null only if F2BLogAnalyzer runs in interactive
// mode and user requested dump of its current state by pressing "d" key
bool debug = evtlog == null;
string debugFile = procName;
if (!debug && (evtlog.LogData.GetType() == typeof(EventRecordWrittenEventArgs) || evtlog.LogData.GetType().IsSubclassOf(typeof(EventRecordWrittenEventArgs))))
{
EventRecordWrittenEventArgs evtarg = evtlog.LogData as EventRecordWrittenEventArgs;
EventRecord evtrec = evtarg.EventRecord;
if (evtrec.ProviderName == "F2BDump")
{
// special windows EventLog event that can be used to request state dump
// (to be able to receive this event you must add selector for F2BDump events)
debug = true;
debugFile = @"c:\F2B\dump.txt";
// process event XML data
string xmlString = evtrec.ToXml();
var doc = XDocument.Parse(xmlString);
var namespaces = new XmlNamespaceManager(new NameTable());
var ns = doc.Root.GetDefaultNamespace();
namespaces.AddNamespace("ns", ns.NamespaceName);
foreach (var element in doc.XPathSelectElements("/ns:Event/ns:EventData/ns:Data", namespaces))
{
debugFile = element.Value;
}
}
}
if (debug)
{
Log.Warn(logpfx + "Dump processors debug info");
Utils.DumpProcessInfo(EventLogEntryType.Warning);
StreamWriter output = null;
lock (thisInst)
{
try
{
DateTime curr = DateTime.Now;
long utc = curr.ToUniversalTime().Ticks;
output = new StreamWriter(new FileStream(debugFile, FileMode.Append));
output.WriteLine("======================================================================");
output.WriteLine("======================================================================");
output.WriteLine("Timestamp: " + curr + " (UTC " + utc + ")");
foreach (BaseProcessor p in processors.Values)
{
output.WriteLine("========== " + p.GetType() + "[" + p.Name + "] processor ==========");
try
{
p.Debug(output);
}
catch (Exception ex)
{
Log.Error(logpfx + "Unable to dump " + p.GetType() + "[" + p.Name + "] debug info: " + ex.Message);
}
}
output.WriteLine("========== process environment ==========");
output.WriteLine("Environment.Is64BitProcess: {0}", Environment.Is64BitProcess);
output.WriteLine("Environment.Is64BitOperatingSystem: {0}", Environment.Is64BitOperatingSystem);
output.WriteLine("========== processors performance summary ==========");
IDictionary <string, ProcPerformance> summary = PerfSum();
foreach (string perfProcName in processors.Keys)
{
ProcPerformance p = summary[perfProcName];
output.WriteLine("Performance[{6}][{0}]: avg({1:0.00}/{2}={3:0.00}ms), min({4:0.00}ms), max({5:0.00}ms)", perfProcName, p.sum, p.count, p.sum / p.count, p.min, p.max, utc);
}
output.WriteLine("========== memory usage summary ==========");
Process currentProcess = Process.GetCurrentProcess();
string linePrefix = string.Format("Process[{0}][{1}]", utc, currentProcess.Id);
output.WriteLine("{0}: NonpagedSystemMemorySize64 = {1}", linePrefix, currentProcess.NonpagedSystemMemorySize64);
output.WriteLine("{0}: PagedMemorySize64 = {1}", linePrefix, currentProcess.PagedMemorySize64);
output.WriteLine("{0}: PagedSystemMemorySize64 = {1}", linePrefix, currentProcess.PagedSystemMemorySize64);
output.WriteLine("{0}: PeakPagedMemorySize64 = {1}", linePrefix, currentProcess.PeakPagedMemorySize64);
output.WriteLine("{0}: PeakVirtualMemorySize64 = {1}", linePrefix, currentProcess.PeakVirtualMemorySize64);
output.WriteLine("{0}: PeadWorkingSet64 = {1}", linePrefix, currentProcess.PeakWorkingSet64);
output.WriteLine("{0}: PrivateMemorySize64 = {1}", linePrefix, currentProcess.PrivateMemorySize64);
output.WriteLine("{0}: VirtualMemorySize64 = {1}", linePrefix, currentProcess.VirtualMemorySize64);
output.WriteLine("{0}: WorkingSet64 = {1}", linePrefix, currentProcess.WorkingSet64);
output.WriteLine("{0}: PrivilegedProcessorTime = {1}", linePrefix, currentProcess.PrivilegedProcessorTime);
output.WriteLine("{0}: StartTime = {1}", linePrefix, currentProcess.StartTime);
//output.WriteLine("{0}: ExitTime = {1}", linePrefix, currentProcess.ExitTime);
output.WriteLine("{0}: TotalProcessorTime = {1}", linePrefix, currentProcess.TotalProcessorTime);
output.WriteLine("{0}: UserProcessorTime = {1}", linePrefix, currentProcess.UserProcessorTime);
}
catch (Exception ex)
{
Log.Error(logpfx + "Unable to dump debug info (" + debugFile + "): " + ex.ToString());
}
finally
{
if (output != null)
{
output.Close();
}
}
}
continue;
}
#endif
if (evtlog == null)
{
// special event used for debugging
continue;
}
logpfx = string.Format("Consuming({0}/{1}) event[{2}@{3}]: ",
ethread.Number, tnevts, evtlog.Id, evtlog.Input.Name);
BaseProcessor proc = null;
if (string.IsNullOrEmpty(procName))
{
procName = firstProcName;
}
//ethread.Reset();
while (true)
{
ethread.Process(procName);
if (procName == null)
{
Log.Info(logpfx + "NULL processor terminated event processing");
break;
}
if (!processors.ContainsKey(procName))
{
Log.Info(logpfx + "processor \"" + procName + "\" not found");
break;
}
Log.Info(logpfx + "processor \"" + procName + "\" executed");
proc = processors[procName];
evtlog.AddProcName(procName);
try
{
ethread.AbortAllowed = true;
if (nconsumers == 1 || typeof(IThreadSafeProcessor).IsAssignableFrom(proc.GetType()))
{
procName = proc.Execute(evtlog);
}
else
{
lock (proc)
{
procName = proc.Execute(evtlog);
}
}
}
catch (ThreadAbortException ex)
{
ethread.Reset();
Thread.ResetAbort();
Log.Warn(logpfx + "abort(" + proc.Name + ", "
+ errtime + ", " + errcnt + "): " + ex.Message);
break;
}
catch (Exception ex)
{
// use processor error configuration
procName = proc.goto_error;
errcnt++;
if (errcnt >= max_errs)
{
// reset exception counter (to log another group of exceptions)
long currtime = DateTime.Now.Ticks;
if (errtime + 60 * TimeSpan.TicksPerSecond < currtime)
{
errcnt = 0;
errtime = currtime;
}
}
// log only limited number of execptions
if (errcnt < max_errs)
{
Log.Error(logpfx + "exception(" + proc.Name + ", "
+ errtime + ", " + errcnt + "): " + ex.ToString());
}
}
finally
{
ethread.AbortAllowed = false;
}
#if DEBUG
Log.Info(logpfx + "processor \"" + ethread.Name + "\" execution time: " + string.Format("{0:0.00}ms", ethread.ProcTime / 1000));
#endif
}
#if DEBUG
Log.Info(logpfx + "processor chain execution time: " + string.Format("{0:0.00}s", ethread.ChainTime / 1000));
#endif
ethread.Reset();
}
Log.Info("Log event consumption (thread " + ethread.Number + "): finished");
}
