{"action":"created","issue":{"url":"https://api.github.com/repos/NLog/NLog/issues/1283","repository_url":"https://api.github.com/repos/NLog/NLog","labels_url":"https://api.github.com/repos/NLog/NLog/issues/1283/labels{/name}","comments_url":"https://api.github.com/repos/NLog/NLog/issues/1283/comments","events_url":"https://api.github.com/repos/NLog/NLog/issues/1283/events","html_url":"https://github.com/NLog/NLog/issues/1283","id":138268482,"number":1283,"title":"Crippling Performance ","user":{"login":"Psyphon","id":5082321,"avatar_url":"https://avatars.githubusercontent.com/u/5082321?v=3","gravatar_id":"","url":"https://api.github.com/users/Psyphon","html_url":"https://github.com/Psyphon","followers_url":"https://api.github.com/users/Psyphon/followers","following_url":"https://api.github.com/users/Psyphon/following{/other_user}","gists_url":"https://api.github.com/users/Psyphon/gists{/gist_id}","starred_url":"https://api.github.com/users/Psyphon/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Psyphon/subscriptions","organizations_url":"https://api.github.com/users/Psyphon/orgs","repos_url":"https://api.github.com/users/Psyphon/repos","events_url":"https://api.github.com/users/Psyphon/events{/privacy}","received_events_url":"https://api.github.com/users/Psyphon/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/NLog/NLog/labels/file-target","name":"file-target","color":"ffffff"},{"url":"https://api.github.com/repos/NLog/NLog/labels/performance","name":"performance","color":"5319e7"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":11,"created_at":"2016-03-03T19:04:06Z","updated_at":"2016-03-03T21:42:29Z","closed_at":null,"body":"[OverflowAction: block, ConcurrentWrites=true, KeepFileOpen=false, AutoFlush=false] \r\n\r\n[OverflowAction: block, ConcurrentWrites=true, KeepFileOpen=true, AutoFlush=true]\r\n\r\nHi! Thanks for reporting this feature/bug/question! Please keep / fill in the relevant info from this template so that we can help you as best as possible.\r\n\r\n\r\n**Type** (choose one):\r\n\r\n- Bug\r\n\r\n\r\n**NLog version**: \r\n1.0.0.505\r\n2.0.0.2000\r\n3.1.0\r\n 4.2.3\r\n\r\n**Platform**: \r\n\r\n.Net 4.5\r\n\r\n**Current NLog config** (xml or C#, if relevant)\r\n\r\n```xml \r\nNonLossyArchiveConcurrentWrites\r\n<nlog xmlns=\"http://www.nlog-project.org/schemas/NLog.xsd\" xmlns:xsi=\"http://www.w3.org/2001/XMLSchema-instance\">\r\n<targets>\r\n            <target name=\"AsyncFileWebHostApplicationLog\" \r\n                  type=\"AsyncWrapper\"                       \r\n                  overflowAction=\"Block\"                    \r\n                  queueLimit=\"10000\"                     \r\n                  batchSize=\"100\"                          \r\n                  timeToSleepBetweenBatches=\"50\">\r\n                <target name=\"webHostApplicationLog\"\r\n                    xsi:type=\"File\"\r\n                    layout=\"${message}\"\r\n                    fileName=\"C:\\logs\\application\\NonLossyArchiveConcurrentWrites.txt\"\r\n                    archiveFileName=\"c:\\logs\\application\\archive\\NonLossyArchiveConcurrentWrites.{########}.txt\"\r\n                    encoding=\"iso-8859-2\"\r\n                    archiveNumbering=\"Rolling\"    \r\n                    maxArchiveFiles=\"5\" \r\n                    archiveAboveSize=\"1073741824\"   \r\n                    archiveEvery=\"Day\"\r\n                    concurrentWrites=\"true\"       \r\n                    keepFileOpen=\"false\"           \r\n                    autoflush=\"false\"             \r\n                    bufferSize=\"1048576\"/>\r\n            </target>\r\n    </targets>\r\n    <rules>\r\n            <logger name=\"*\" minlevel=\"Debug\" writeTo=\"AsyncFileWebHostApplicationLog\" />\r\n    </rules>\r\n</nlog>\r\n\r\n```xml NonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush\r\n<nlog xmlns=\"http://www.nlog-project.org/schemas/NLog.xsd\" xmlns:xsi=\"http://www.w3.org/2001/XMLSchema-instance\">\r\n    <targets>\r\n        <target name=\"AsyncFileWebHostApplicationLog\" \r\n          type=\"AsyncWrapper\"                       \r\n          overflowAction=\"Block\"                    \r\n          queueLimit=\"10000\"                     \r\n          batchSize=\"100\"                          \r\n          timeToSleepBetweenBatches=\"50\">\r\n                 <target name=\"webHostApplicationLog\"\r\n                    xsi:type=\"File\"\r\n                    layout=\"${message}\"\r\n                    fileName=\"C:\\logs\\application\\NonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush.txt\"\r\n                    archiveFileName=\"c:\\logs\\application\\archive\\NonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush.{########}.txt\"\r\n                    encoding=\"iso-8859-2\"\r\n                    archiveNumbering=\"Rolling\"    \r\n                    maxArchiveFiles=\"5\" \r\n                    archiveAboveSize=\"1073741824\"   \r\n                    archiveEvery=\"Day\"\r\n                    concurrentWrites=\"true\"       \r\n                    keepFileOpen=\"true\"           \r\n                    autoflush=\"true\"             \r\n                    bufferSize=\"1048576\"/>\r\n        </target>\r\n    </targets>\r\n    <rules>\r\n            <logger name=\"*\" minlevel=\"Debug\" writeTo=\"AsyncFileWebHostApplicationLog\" />\r\n    </rules>\r\n</nlog>\r\n```\r\n\r\nIn case of a BUG:\r\n\r\n- What is the current result?\r\nPerformance is extremely slow. Throughput is 414 operations per second for this configuration.\r\n\r\n\r\n- What is the expected result?\r\nAll other permutations of the configurations is over 500,000 operations per second. These permutations of configuration should yield the same results.\r\n\r\n- Did you checked the [Internal log](https://github.com/NLog/NLog/wiki/Internal-Logging)?\r\nNo\r\n\r\n- Please post full exception details (message, stacktrace, inner exceptions)\r\nThese are text files capturing the performance.\r\n\r\n[Debug1.0.0.505_bugNonLossyArchiveConcurrentWrites.txt]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 241359ms\r\n(throughput = 414.320 ops per second)\r\nMean latency = 63550.328mcs\r\n99% observations less than = 505022.672mcs\r\n99.99% observations less than = 1437954.501mcs\r\n0) 0.000 - 50502.2672 = 78685\r\n1) 50502.267 - 101004.5344 = 31\r\n2) 101004.534 - 151506.8016 = 0\r\n3) 151506.802 - 202009.0688 = 3\r\n4) 202009.069 - 252511.3360 = 7413\r\n5) 252511.336 - 303013.6032 = 8321\r\n6) 303013.603 - 353515.8704 = 3556\r\n7) 353515.870 - 404018.1376 = 327\r\n8) 404018.138 - 454520.4049 = 27\r\n9) 454520.405 - 505022.6721 = 638\r\n\r\n[Debug1.0.0.505_bugNonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 56145ms\r\n(throughput = 1781.080 ops per second)\r\nMean latency = 14254.963mcs\r\n99% observations less than = 84594.592mcs\r\n99.99% observations less than = 375048.607mcs\r\n0) 0.000 - 8459.4592 = 77196\r\n1) 8459.459 - 16918.9184 = 164\r\n2) 16918.918 - 25378.3777 = 133\r\n3) 25378.378 - 33837.8369 = 388\r\n4) 33837.837 - 42297.2961 = 1142\r\n5) 42297.296 - 50756.7553 = 2291\r\n6) 50756.755 - 59216.2146 = 4797\r\n7) 59216.215 - 67675.6738 = 6889\r\n8) 67675.674 - 76135.1330 = 4091\r\n9) 76135.133 - 84594.5922 = 1910\r\n\r\n[Debug2.0.0.2000_bugNonLossyArchiveConcurrentWrites]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 59986ms\r\n(throughput = 1667.045 ops per second)\r\nMean latency = 15286.983mcs\r\n99% observations less than = 92919.908mcs\r\n99.99% observations less than = 142945.547mcs\r\n0) 0.000 - 9291.9908 = 75748\r\n1) 9291.991 - 18583.9817 = 942\r\n2) 18583.982 - 27875.9725 = 317\r\n3) 27875.972 - 37167.9633 = 76\r\n4) 37167.963 - 46459.9541 = 602\r\n5) 46459.954 - 55751.9450 = 2136\r\n6) 55751.945 - 65043.9358 = 11107\r\n7) 65043.936 - 74335.9266 = 5988\r\n8) 74335.927 - 83627.9174 = 1654\r\n9) 83627.917 - 92919.9083 = 431\r\n\r\n[Debug2.0.0.2000_bugNonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 56193ms\r\n(throughput = 1779.576 ops per second)\r\nMean latency = 13841.953mcs\r\n99% observations less than = 69901.181mcs\r\n99.99% observations less than = 102046.130mcs\r\n0) 0.000 - 6990.1181 = 76894\r\n1) 6990.118 - 13980.2362 = 378\r\n2) 13980.236 - 20970.3543 = 518\r\n3) 20970.354 - 27960.4724 = 34\r\n4) 27960.472 - 34950.5905 = 34\r\n5) 34950.591 - 41940.7086 = 91\r\n6) 41940.709 - 48930.8267 = 714\r\n7) 48930.827 - 55920.9448 = 1628\r\n8) 55920.945 - 62911.0630 = 9699\r\n9) 62911.063 - 69901.1811 = 9011\r\n\r\n[Debug3.1.0_bugNonLossyArchiveConcurrentWrites]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 60631ms\r\n(throughput = 1649.317 ops per second)\r\nMean latency = 15477.736mcs\r\n99% observations less than = 96102.625mcs\r\n99.99% observations less than = 147756.304mcs\r\n0) 0.000 - 9610.2625 = 76140\r\n1) 9610.263 - 19220.5251 = 769\r\n2) 19220.525 - 28830.7876 = 218\r\n3) 28830.788 - 38441.0502 = 115\r\n4) 38441.050 - 48051.3127 = 690\r\n5) 48051.313 - 57661.5753 = 2974\r\n6) 57661.575 - 67271.8378 = 11092\r\n7) 67271.838 - 76882.1003 = 4475\r\n8) 76882.100 - 86492.3629 = 1748\r\n9) 86492.363 - 96102.6254 = 780\r\n\r\n[Debug3.1.0_bugNonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 56250ms\r\n(throughput = 1777.767 ops per second)\r\nMean latency = 13836.612mcs\r\n99% observations less than = 70875.040mcs\r\n99.99% observations less than = 129753.977mcs\r\n0) 0.000 - 7087.5040 = 76799\r\n1) 7087.504 - 14175.0080 = 413\r\n2) 14175.008 - 21262.5120 = 657\r\n3) 21262.512 - 28350.0160 = 53\r\n4) 28350.016 - 35437.5200 = 46\r\n5) 35437.520 - 42525.0240 = 127\r\n6) 42525.024 - 49612.5280 = 1020\r\n7) 49612.528 - 56700.0320 = 1855\r\n8) 56700.032 - 63787.5360 = 12045\r\n9) 63787.536 - 70875.0401 = 5986\r\n\r\n[Debug4.2.3_bugNonLossyArchiveConcurrentWrites]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 61241ms\r\n(throughput = 1632.873 ops per second)\r\nMean latency = 15625.678mcs\r\n99% observations less than = 98882.419mcs\r\n99.99% observations less than = 151075.863mcs\r\n0) 0.000 - 9888.2419 = 76120\r\n1) 9888.242 - 19776.4838 = 856\r\n2) 19776.484 - 29664.7257 = 181\r\n3) 29664.726 - 39552.9676 = 149\r\n4) 39552.968 - 49441.2094 = 842\r\n5) 49441.209 - 59329.4513 = 4062\r\n6) 59329.451 - 69217.6932 = 10596\r\n7) 69217.693 - 79105.9351 = 4077\r\n8) 79105.935 - 88994.1770 = 1329\r\n9) 88994.177 - 98882.4189 = 789\r\n\r\n[Debug4.2.3_bugNonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush]\r\nStopwatch.IsHighResolution = True\r\nCountPerThread = 3125\r\nTotalCount = 100000\r\nProucersCount = 32\r\nGenerated 100000 values in 56241ms\r\n(throughput = 1778.051 ops per second)\r\nMean latency = 14301.288mcs\r\n99% observations less than = 69542.731mcs\r\n99.99% observations less than = 109927.850mcs\r\n0) 0.000 - 6954.2731 = 75738\r\n1) 6954.273 - 13908.5462 = 384\r\n2) 13908.546 - 20862.8193 = 942\r\n3) 20862.819 - 27817.0924 = 47\r\n4) 27817.092 - 34771.3655 = 22\r\n5) 34771.366 - 41725.6386 = 69\r\n6) 41725.639 - 48679.9117 = 997\r\n7) 48679.912 - 55634.1848 = 1444\r\n8) 55634.185 - 62588.4579 = 10012\r\n9) 62588.458 - 69542.7310 = 9346\r\n\r\n\r\n\r\n\r\n- Are there any work arrounds? yes/no\r\nNo\r\n\r\nThe following settings are non-performant:\r\n* NonLossyArchiveConcurrentWrites (overflow action block)\r\n* NonLossyArchiveConcurrentWritesKeepFileOpenAutoFlush (overflow action block)\r\n\r\n- Is there a version in which it did worked? \r\nThis never worked for performance.\r\n\r\n- Can you help us by writing an unit test?\r\n\r\nNLogPerformance.exe 100000 32 1 > Results\\results.txt\r\n\r\n\r\n\r\n```c#\r\n\r\nusing System;\r\nusing System.Collections.Generic;\r\nusing System.Diagnostics;\r\nusing System.Linq;\r\nusing System.Threading;\r\nusing System.Threading.Tasks;\r\nusing NLog;\r\nusing NLog.Targets.Wrappers;\r\n\r\nnamespace NLogPerformance\r\n{\r\n    internal class Program\r\n    {\r\n        // Create a static instance of the logger.\r\n        private static readonly Logger Logger = LogManager.GetLogger(\"MyLogger\");\r\n\r\n\r\n        private static int _countPerThread = 10000000;\r\n        private static int _producersCount = 1;\r\n        private static int _totalCount;\r\n\r\n        private static void Main(string[] args)\r\n        {\r\n            if ((args.Length >= 1) && (!int.TryParse(args[0], out _countPerThread)) || (_countPerThread < 1))\r\n            {\r\n                Console.WriteLine(\"Usage: LoggingPerformance.exe [CountPerThread] [ProducersCount] [ConsumersCount]\");\r\n                throw new ArgumentException(\r\n                    \"Invalid first argument! Provide items count per thread as a first application argument.\");\r\n            }\r\n            if ((args.Length >= 2) && (!int.TryParse(args[1], out _producersCount)) || (_producersCount < 1))\r\n            {\r\n                Console.WriteLine(\"Usage: LoggingPerformance.exe [CountPerThread] [ProducersCount] [ConsumersCount]\");\r\n                throw new ArgumentException(\r\n                    \"Invalid second argument! Provide producers count as a second application argument.\");\r\n            }\r\n\r\n            Console.WriteLine(\"Stopwatch.IsHighResolution = {0}\", Stopwatch.IsHighResolution);\r\n\r\n            _countPerThread = _countPerThread/_producersCount;\r\n            _totalCount = _countPerThread*_producersCount;\r\n\r\n            Console.WriteLine(\"CountPerThread = {0}\", _countPerThread);\r\n            Console.WriteLine(\"TotalCount = {0}\", _totalCount);\r\n            Console.WriteLine(\"ProucersCount = {0}\", _producersCount);\r\n\r\n            try\r\n            {\r\n                var results = new double[_totalCount];\r\n                for (var i = 0; i < _totalCount; i++)\r\n                    results[i] = 0;\r\n\r\n                // Start the stopwatch timer.\r\n                var stopWatch = Stopwatch.StartNew();\r\n\r\n                // Create and start producer tasks.\r\n                var producers = new Task[_producersCount];\r\n                for (var producerIndex = 0; producerIndex < _producersCount; producerIndex++)\r\n                {\r\n                    producers[producerIndex] = Task.Factory.StartNew(state =>\r\n                    {\r\n                        var index = (int) state;\r\n                        for (var i = 0; i < _countPerThread; i++)\r\n                        {\r\n                            var id = index*_countPerThread + i;\r\n                            results[id] = stopWatch.ElapsedTicks;\r\n\r\n                            // Different loggers will be used here for testing...\r\n                            Logger.Info(\"Log message {0} / {1}\", id + 1, _totalCount);\r\n\r\n                            results[id] = stopWatch.ElapsedTicks - results[id];\r\n                        }\r\n                    }, producerIndex, TaskCreationOptions.LongRunning);\r\n                }\r\n\r\n                // Wait for producing complete.\r\n                Task.WaitAll(producers);\r\n                stopWatch.Stop();\r\n                LogManager.Flush();\r\n                // Adjust result table.\r\n                var frequency = Stopwatch.Frequency/(1000.0*1000.0);\r\n                for (var i = 0; i < _totalCount; i++)\r\n                    results[i] /= frequency;\r\n                Array.Sort(results);\r\n\r\n                // Show report message.\r\n                var throughput = _totalCount/((double) stopWatch.ElapsedTicks/Stopwatch.Frequency);\r\n                Console.WriteLine(\"Generated {0} values in {1}ms\", _totalCount,\r\n                    stopWatch.ElapsedMilliseconds);\r\n                Console.WriteLine(\"(throughput = {0:F3} ops per second)\", throughput);\r\n\r\n                // Show latency histogram.\r\n                ShowHistogram(results, 10);\r\n            }\r\n            catch (Exception ex)\r\n            {\r\n                Console.WriteLine(ex.Message);\r\n            }\r\n            finally\r\n            {\r\n                LogManager.Flush();\r\n\r\n                Console.WriteLine(\"[Done]\");\r\n            }\r\n        }\r\n\r\n        #region Utility methods\r\n\r\n        private static void ShowHistogram(IList<double> values, int count, double? maxValue = null)\r\n        {\r\n            // Calculate mean value.\r\n            var mean = values.Aggregate((s, v) => s + v)/values.Count;\r\n            Console.WriteLine(\"Mean latency = {0:F3}mcs\", mean);\r\n\r\n            // Calculate bounds values.\r\n            var bound99 = (int) (values.Count*99.0/100.0);\r\n            Console.WriteLine(\"99% observations less than = {0:F3}mcs\", values[bound99]);\r\n            var bound9999 = (int) (values.Count*99.99/100.0);\r\n            Console.WriteLine(\"99.99% observations less than = {0:F3}mcs\", values[bound9999]);\r\n\r\n            var min = values[0];\r\n            var max = maxValue ?? values[bound99];\r\n            var step = (max - min)/count;\r\n\r\n            for (var i = 0; i < count; i++)\r\n            {\r\n                var lower = min + i*step;\r\n                var upper = min + ((i + 1)*step);\r\n                Console.WriteLine(\"{0}) {1:F3} - {2:F4} = {3}\", i, lower, upper,\r\n                    values.Count(v => (v >= lower) && (v <= upper)));\r\n            }\r\n        }\r\n\r\n        #endregion\r\n    }\r\n}\r\n```\r\n\r\n\r\n\r\n\r\n"},"comment":{"url":"https://api.github.com/repos/NLog/NLog/issues/comments/191976608","html_url":"https://github.com/NLog/NLog/issues/1283#issuecomment-191976608","issue_url":"https://api.github.com/repos/NLog/NLog/issues/1283","id":191976608,"user":{"login":"Psyphon","id":5082321,"avatar_url":"https://avatars.githubusercontent.com/u/5082321?v=3","gravatar_id":"","url":"https://api.github.com/users/Psyphon","html_url":"https://github.com/Psyphon","followers_url":"https://api.github.com/users/Psyphon/followers","following_url":"https://api.github.com/users/Psyphon/following{/other_user}","gists_url":"https://api.github.com/users/Psyphon/gists{/gist_id}","starred_url":"https://api.github.com/users/Psyphon/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/Psyphon/subscriptions","organizations_url":"https://api.github.com/users/Psyphon/orgs","repos_url":"https://api.github.com/users/Psyphon/repos","events_url":"https://api.github.com/users/Psyphon/events{/privacy}","received_events_url":"https://api.github.com/users/Psyphon/received_events","type":"User","site_admin":false},"created_at":"2016-03-03T21:42:29Z","updated_at":"2016-03-03T21:42:29Z","body":"Ok. so it looks like its a problem with the batch size. \r\n\r\nif the batch size is 10, NonLossyArchiveConcurrentWrites and NonLossyArchiveConcurrentWritesAutoFlush is super slow.\r\n\r\nThe queue size i've left at around 10000"}}