{"action":"created","issue":{"url":"https://api.github.com/repos/serilog/serilog/issues/619","labels_url":"https://api.github.com/repos/serilog/serilog/issues/619/labels{/name}","comments_url":"https://api.github.com/repos/serilog/serilog/issues/619/comments","events_url":"https://api.github.com/repos/serilog/serilog/issues/619/events","html_url":"https://github.com/serilog/serilog/issues/619","id":123682526,"number":619,"title":"PeriodicBatchingSink.Emit produces too many contentions","user":{"login":"DmitryNaumov","id":866389,"avatar_url":"https://avatars.githubusercontent.com/u/866389?v=3","gravatar_id":"","url":"https://api.github.com/users/DmitryNaumov","html_url":"https://github.com/DmitryNaumov","followers_url":"https://api.github.com/users/DmitryNaumov/followers","following_url":"https://api.github.com/users/DmitryNaumov/following{/other_user}","gists_url":"https://api.github.com/users/DmitryNaumov/gists{/gist_id}","starred_url":"https://api.github.com/users/DmitryNaumov/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/DmitryNaumov/subscriptions","organizations_url":"https://api.github.com/users/DmitryNaumov/orgs","repos_url":"https://api.github.com/users/DmitryNaumov/repos","events_url":"https://api.github.com/users/DmitryNaumov/events{/privacy}","received_events_url":"https://api.github.com/users/DmitryNaumov/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":1,"created_at":"2015-12-23T15:58:45Z","updated_at":"2015-12-26T02:14:35Z","closed_at":null,"body":"During my investigations of why simple foreach loop with some logging produces log entries with millisecond-sized gaps between each. I suspected thread context switches to be the reason. High contention rate was also noted by performance counters and performance profiler:\r\n\r\nDA0039: (Average)Contention Rate / sec = 17.94; A very high rate of .NET Lock contentions is occurring.\r\n\r\nI took a look at sink implementation and imo we can do better to avoid _possible_ contention on every write to log. I _do_ understand that if's are fast, but still if thread encounters occupied Monitor, then it's moved from RUNNING state to end of the wait list of the threads with same priority (I do simplify things here). So simple operation like write to log or even do an increment eventually may take milliseconds!\r\n\r\nI didn't dive deeply in the logic behind checking _unloading & _started, but I think Monitor Enter/Exit can be easily replaced with Interlocked.CompareExchange operations which do not affect thread scheduling (thread won't go to WAIT state).\r\n\r\n        public void Emit(LogEvent logEvent)\r\n        {\r\n            if (logEvent == null) throw new ArgumentNullException(nameof(logEvent));\r\n\r\n            lock (_stateLock)\r\n            {\r\n                if (_unloading) return;\r\n                if (!_started)\r\n                {\r\n                    // Special handling to try to get the first event across as quickly\r\n                    // as possible to show we're alive!\r\n                    _started = true;\r\n                    SetTimer(TimeSpan.Zero);\r\n                }\r\n            }\r\n\r\n            _queue.Enqueue(logEvent);\r\n        }"},"comment":{"url":"https://api.github.com/repos/serilog/serilog/issues/comments/167271428","html_url":"https://github.com/serilog/serilog/issues/619#issuecomment-167271428","issue_url":"https://api.github.com/repos/serilog/serilog/issues/619","id":167271428,"user":{"login":"nblumhardt","id":342712,"avatar_url":"https://avatars.githubusercontent.com/u/342712?v=3","gravatar_id":"","url":"https://api.github.com/users/nblumhardt","html_url":"https://github.com/nblumhardt","followers_url":"https://api.github.com/users/nblumhardt/followers","following_url":"https://api.github.com/users/nblumhardt/following{/other_user}","gists_url":"https://api.github.com/users/nblumhardt/gists{/gist_id}","starred_url":"https://api.github.com/users/nblumhardt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/nblumhardt/subscriptions","organizations_url":"https://api.github.com/users/nblumhardt/orgs","repos_url":"https://api.github.com/users/nblumhardt/repos","events_url":"https://api.github.com/users/nblumhardt/events{/privacy}","received_events_url":"https://api.github.com/users/nblumhardt/received_events","type":"User","site_admin":false},"created_at":"2015-12-26T02:14:35Z","updated_at":"2015-12-26T02:14:35Z","body":"Thanks Dmitry. As far as I can tell this would be a good change, but it'd need some careful planning and testing no doubt."}}