Logging

A logging facility in MMF is provided by the ApplicationLogging project. SimpleML utilizes this to provide detailed logging of the activity of modules.

Logging from Modules

All SimpleML modules emit logging information via the 'logger' member of the MMF ModuleBase class. An example from the MatrixTrainTestSplitter appears below...

logger.Log(this, LogLevel.Information, "Split matrix into train and test portions of " + trainNumRows + " and " + testNumRows + " rows respectively.");

Capturing Logging

In order to capture the logging information, an instance of the ApplicationLogging IApplicationLogger interface is passed to the ModuleGraphProcessor constructor. This is demonstrated in the Program class using a FileApplicationLogger instance...

using (FileApplicationLogger logger = new FileApplicationLogger(LogLevel.Information, '|', " ", Path.Combine(logFilePath, "SimpleMLSampleLog.txt"))) using (SizeLimitedBufferProcessor bufferProcessor = new SizeLimitedBufferProcessor(10)) using (FileMetricLogger metricLogger = new FileMetricLogger('|', Path.Combine(logFilePath, "SimpleMLSampleMetrics.txt"), bufferProcessor, true)) using (ModuleGraphProcessor processor = new ModuleGraphProcessor(logger, metricLogger)) { bufferProcessor.Start(); try { processor.Process(moduleGraph, false); } finally { bufferProcessor.Stop(); } }

Note that the level of detail of the logging information can be adjusted by changing the 'minimumLogLevel' parameter on the FileApplicationLogger classes' constructor (e.g. to LogLevel.Debug),

In the above case, the FileApplicationLogger class will output log information to a text file, with content similar to the following...

2016-09-20 12:09:18.420 | Source = ModuleGraphProcessor | Starting module graph processing. 2016-09-20 12:09:18.452 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.MatrixCsvReader'. 2016-09-20 12:09:18.483 | Source = MatrixCsvReader | Read CSV data from file at path "..\..\Resources\MarketData.csv" into a matrix. 2016-09-20 12:09:18.483 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.MatrixOrderRandomizer'. 2016-09-20 12:09:18.483 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.AutomaticFeatureScaler'. 2016-09-20 12:09:18.483 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.MatrixTrainTestSplitter'. 2016-09-20 12:09:18.483 | Source = MatrixTrainTestSplitter | Split matrix into train and test portions of 430 and 286 rows respectively. 2016-09-20 12:09:18.483 | Source = ModuleGraphProcessor | WARNING | Output slot 'TestData' on module 'SimpleML.Samples.Modules.MatrixTrainTestSplitter' is not referenced by a slot link. 2016-09-20 12:09:18.483 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.MatrixColumnSplitter'. 2016-09-20 12:09:18.483 | Source = MatrixColumnSplitter | Split 3 column matrix into matrices of 2 and 1 columns. 2016-09-20 12:09:18.483 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.LinearRegressionGradientDescentOptimizer'. 2016-09-20 12:09:18.561 | Source = GradientDescentOptimizer | Running gradient descent optimization for 3 theta parameters, 430 training data points, 1500 iterations. 2016-09-20 12:09:21.155 | Source = GradientDescentOptimizer | Completed running gradient descent optimization. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.LinearRegressionCostSeriesCalculator'. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | WARNING | Output slot 'Cost' on module 'SimpleML.Samples.Modules.LinearRegressionCostSeriesCalculator' is not referenced by a slot link. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.FeatureScalingParameterListSplitter'. 2016-09-20 12:09:21.155 | Source = FeatureScalingParameterListSplitter | Split List of FeatureScalingParameters of size 3 into Lists of 2 and 1 items. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.FeatureScaler'. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.LinearRegressionHypothesisCalculator'. 2016-09-20 12:09:21.155 | Source = LinearRegressionHypothesisCalculator | Applied multi-variate linear regression hypothesis to matrix data series of 3 items. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | Processing module 'SimpleML.Samples.Modules.FeatureRescaler'. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | WARNING | Output slot 'RescaledMatrix' on module 'SimpleML.Samples.Modules.FeatureRescaler' is not referenced by a slot link. 2016-09-20 12:09:21.155 | Source = ModuleGraphProcessor | Module graph processing completed.

Metrics / Instrumentation

Instrumentation in MMF is performed via the Application Metrics project, and SimpleML uses this framework to log its own instrumentation and metrics.

Logging Metric Events from Modules

In the case of basic modules, metric events are logged by directly calling member 'metricLogger' of the MMF ModuleBase class. For example the MatrixCsvReader module uses the 'metricLogger' member to capture the time taken to read a CSV file, and also increment a counter to indicate a CSV file was read...

metricLogger.Begin(new CsvFileReadTime()); Matrix result = null; try { result = matrixCsvReader.Read(csvFilePath, startColumn, numberOfColumns); } catch (Exception e) { metricLogger.CancelBegin(new CsvFileReadTime()); logger.Log(this, LogLevel.Critical, "Error occurred whilst attempting to read matrix from CSV file at path \"" + csvFilePath + "\".", e); throw; } metricLogger.End(new CsvFileReadTime()); metricLogger.Increment(new CsvFileRead());

For more complex modules which compose classes with greater functionality, the 'metricLogger' member is passed to the composed classes. The LinearRegressionGradientDescentOptimizer module follows this pattern, by passing the 'metricLogger' member to the constructor of the composed GradientDescentOptimizer class...

GradientDescentOptimizer gradientDescentOptimizer = new GradientDescentOptimizer(logger, metricLogger);

Capturing Metric Events

In order to capture the metric events, an instance of the ApplicationMetrics IMetricLogger interface is passed to the ModuleGraphProcessor constructor. This is demonstrated in the Program class using a FileMetricLogger instance...

using (FileApplicationLogger logger = new FileApplicationLogger(LogLevel.Information, '|', " ", Path.Combine(logFilePath, "SimpleMLSampleLog.txt"))) using (SizeLimitedBufferProcessor bufferProcessor = new SizeLimitedBufferProcessor(10)) using (FileMetricLogger metricLogger = new FileMetricLogger('|', Path.Combine(logFilePath, "SimpleMLSampleMetrics.txt"), bufferProcessor, true)) using (ModuleGraphProcessor processor = new ModuleGraphProcessor(logger, metricLogger)) { bufferProcessor.Start(); try { processor.Process(moduleGraph, false); } finally { bufferProcessor.Stop(); } }

In the above case, the FileMetricLogger class will output metric events to a text file, with content similar to the following...

2016-09-20 12:09:18.483 | CsvFileRead 2016-09-20 12:09:18.483 | ModuleProcessed 2016-09-20 12:09:18.483 | MatrixRowOrderRandomized 2016-09-20 12:09:18.483 | ModuleProcessed 2016-09-20 12:09:18.483 | MatrixFeaturesScaled 2016-09-20 12:09:18.483 | ModuleProcessed 2016-09-20 12:09:18.483 | ModuleProcessed 2016-09-20 12:09:18.483 | ModuleProcessed 2016-09-20 12:09:18.467 | CsvFileRead | 16 2016-09-20 12:09:18.452 | ModuleProcessingTime | 31 2016-09-20 12:09:18.483 | ModuleProcessingTime | 0 2016-09-20 12:09:18.483 | ModuleProcessingTime | 0 2016-09-20 12:09:18.483 | ModuleProcessingTime | 0 2016-09-20 12:09:18.483 | ModuleProcessingTime | 0 2016-09-20 12:09:21.155 | GradientDescentOptimizationCompleted 2016-09-20 12:09:21.155 | ModuleProcessed 2016-09-20 12:09:21.155 | ModuleProcessed 2016-09-20 12:09:21.155 | ModuleProcessed 2016-09-20 12:09:21.155 | MatrixFeaturesScaled 2016-09-20 12:09:21.155 | GradientDescentIterations | 1500 2016-09-20 12:09:18.561 | GradientDescentOptimizationTime | 2594 2016-09-20 12:09:18.483 | ModuleProcessingTime | 2672 2016-09-20 12:09:21.155 | ModuleProcessingTime | 0 2016-09-20 12:09:21.155 | ModuleProcessingTime | 0 2016-09-20 12:09:21.155 | ModuleProcessed 2016-09-20 12:09:21.155 | ModuleProcessed 2016-09-20 12:09:21.155 | MatrixFeaturesRescaled 2016-09-20 12:09:21.155 | ModuleProcessed 2016-09-20 12:09:21.155 | ModuleGraphProcessed 2016-09-20 12:09:21.155 | ModuleProcessingTime | 0 2016-09-20 12:09:21.155 | ModuleProcessingTime | 0 2016-09-20 12:09:21.155 | ModuleProcessingTime | 0 2016-09-20 12:09:18.452 | ModuleGraphProcessingTime | 2703