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