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"); }