{"action":"created","issue":{"url":"https://api.github.com/repos/dotnet/corert/issues/6041","repository_url":"https://api.github.com/repos/dotnet/corert","labels_url":"https://api.github.com/repos/dotnet/corert/issues/6041/labels{/name}","comments_url":"https://api.github.com/repos/dotnet/corert/issues/6041/comments","events_url":"https://api.github.com/repos/dotnet/corert/issues/6041/events","html_url":"https://github.com/dotnet/corert/issues/6041","id":337693810,"node_id":"MDU6SXNzdWUzMzc2OTM4MTA=","number":6041,"title":"Odd threading behavior - Thread.CurrentThread.ManagedThreadId != Environment.ManagedThreadId","user":{"login":"christianscheuer","id":4005316,"node_id":"MDQ6VXNlcjQwMDUzMTY=","avatar_url":"https://avatars1.githubusercontent.com/u/4005316?v=4","gravatar_id":"","url":"https://api.github.com/users/christianscheuer","html_url":"https://github.com/christianscheuer","followers_url":"https://api.github.com/users/christianscheuer/followers","following_url":"https://api.github.com/users/christianscheuer/following{/other_user}","gists_url":"https://api.github.com/users/christianscheuer/gists{/gist_id}","starred_url":"https://api.github.com/users/christianscheuer/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/christianscheuer/subscriptions","organizations_url":"https://api.github.com/users/christianscheuer/orgs","repos_url":"https://api.github.com/users/christianscheuer/repos","events_url":"https://api.github.com/users/christianscheuer/events{/privacy}","received_events_url":"https://api.github.com/users/christianscheuer/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":16,"created_at":"2018-07-02T23:16:15Z","updated_at":"2018-07-07T21:29:51Z","closed_at":null,"author_association":"CONTRIBUTOR","body":"I'm getting a `The write lock is being released without being held` exception when exiting write mode on a `ReaderWriterLockSlim` on macOS.\r\n\r\nDebugging this issue has led me to conclude, that apparently my call to`ExitWriteLock` happens on a different thread than where I started, albeit in a weird way.\r\n\r\nWhen I debug it, `Thread.CurrentThread.ManagedThreadId` will indicate I'm still on thread 1 where I acquired the lock, but `Environment.ManagedThreadId` which is what `ReaderWriterLockSlim` uses, indicates I'm on thread 6.\r\nThis does not seem to happen on CoreCLR.\r\n\r\nThe code paths involved do not include any calls to Thread.Start or asynchronous Task code. It really all should be happening on the same thread (which `Thread.CurrentThread.ManagedThreadId` also seems to indicate is true).\r\nThe rest of the app does have asynchronous Task code though.\r\n\r\nUnfortunately, I haven't yet been able to make a repro case. It does seem to make a difference though if GC is invoked between the calls to EnterWriteLock and ExitWriteLock.\r\nAny ideas as how to better debug this?\r\n\r\n\r\nThis is basically what I'm doing, but I don't think this helps much.\r\n\r\n```\r\nusing System;\r\nusing System.Collections.Generic;\r\nusing System.Threading;\r\n\r\nnamespace Test\r\n{\r\n\r\n    public struct WriteLock : IDisposable\r\n    {\r\n        private readonly LockManager lockManager;\r\n\r\n        internal WriteLock(LockManager lockManager)\r\n        {\r\n            this.lockManager = lockManager;\r\n        }\r\n\r\n        public void Dispose()\r\n        {\r\n            this.lockManager.ReleaseWriteLock();\r\n        }\r\n    }\r\n\r\n    public class LockManager : IDisposable\r\n    {\r\n        private ReaderWriterLockSlim readerWriterLock;\r\n\r\n        public LockManager()\r\n        {\r\n            this.readerWriterLock = new ReaderWriterLockSlim(LockRecursionPolicy.NoRecursion);\r\n        }\r\n\r\n        public IDisposable AcquireWriteLock()\r\n        {\r\n            // Enter the lock\r\n            if (!this.readerWriterLock.TryEnterWriteLock(-1))\r\n            {\r\n                throw new Exception(\"Could not enter write lock\");\r\n            }\r\n            Console.WriteLine(\"Entered write lock: \" + Thread.CurrentThread.ManagedThreadId);\r\n\r\n            // Return a new instance of a write lock\r\n            return new WriteLock(this);\r\n        }\r\n\r\n        public void Dispose()\r\n        {\r\n            this.Dispose(true);\r\n            GC.SuppressFinalize(this);\r\n        }\r\n\r\n        internal void ReleaseReadLock()\r\n        {\r\n            this.readerWriterLock.ExitReadLock();\r\n        }\r\n\r\n        internal void ReleaseWriteLock()\r\n        {\r\n            this.readerWriterLock.ExitWriteLock();\r\n        }\r\n\r\n        protected virtual void Dispose(bool disposing)\r\n        {\r\n            Console.WriteLine(\"Disposing lock manager... disposing: \" + disposing);\r\n            if (disposing)\r\n            {\r\n                if (this.readerWriterLock != null)\r\n                {\r\n                    this.readerWriterLock.Dispose();\r\n                    this.readerWriterLock = null;\r\n                }\r\n            }\r\n        }   \r\n  \r\n\r\n        public static void Main(string[] args)\r\n        {\r\n            using (var lockMan = new LockManager())\r\n            using (var locky = lockMan.AcquireWriteLock())\r\n            {\r\n                //Lots of stuff happening in here. No Task awaits though...\r\n            }\r\n        }\r\n    }\r\n\r\n}\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/dotnet/corert/issues/comments/403243972","html_url":"https://github.com/dotnet/corert/issues/6041#issuecomment-403243972","issue_url":"https://api.github.com/repos/dotnet/corert/issues/6041","id":403243972,"node_id":"MDEyOklzc3VlQ29tbWVudDQwMzI0Mzk3Mg==","user":{"login":"jkotas","id":6668460,"node_id":"MDQ6VXNlcjY2Njg0NjA=","avatar_url":"https://avatars2.githubusercontent.com/u/6668460?v=4","gravatar_id":"","url":"https://api.github.com/users/jkotas","html_url":"https://github.com/jkotas","followers_url":"https://api.github.com/users/jkotas/followers","following_url":"https://api.github.com/users/jkotas/following{/other_user}","gists_url":"https://api.github.com/users/jkotas/gists{/gist_id}","starred_url":"https://api.github.com/users/jkotas/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jkotas/subscriptions","organizations_url":"https://api.github.com/users/jkotas/orgs","repos_url":"https://api.github.com/users/jkotas/repos","events_url":"https://api.github.com/users/jkotas/events{/privacy}","received_events_url":"https://api.github.com/users/jkotas/received_events","type":"User","site_admin":false},"created_at":"2018-07-07T21:29:51Z","updated_at":"2018-07-07T21:29:51Z","author_association":"MEMBER","body":"> it seems like my code is still running while the GC is running\r\n\r\nI think it is just a problem with output buffering. You can try to add `fflush(stdout)` at the end of the GC and see whether it goes away.\r\n\r\nSo far, the simplest explanation for the symptoms is that some part of the thread static object graph is not getting marked by the GC and the GC considers it garbage. Here are some ideas what to try:\r\n\r\n- Turn on heap verification by `export RH_HeapVerify=1`. This will turn on GC heap integrity checks before and after the GC. I expect that this integrity check should catch this problem even faster than your tracing. It would be useful to confirm it.\r\n\r\n- Add extra tracing to GC to verify that the whole graph from the GCHandle is getting marked correctly. Add a line like `printf (\"*%p*, pMT=%p, newly marked: %d\\n\", (size_t)o, *(void**)o, marked);` to `BOOL gc_heap::gc_mark1 (uint8_t* o)` method in gc.cpp. When I have done this in a simple program that just prints `Environment.CurrentManagedThreadId`, I see that the thread static object graph is getting marked correctly:\r\n\r\n```\r\n*00000218D2746B00*, pMT=00007FF62C0E6491, newly marked: 1 // pMT is __Array<Object>::`vftable'\r\n*00000218D2746B60*, pMT=00007FF62C0EEEC9, newly marked: 1 // pMT is _GCStaticEEType_01::`vftable'\r\n*00000218D2746BA8*, pMT=00007FF62C09D051, newly marked: 1 // pMT is S_P_CoreLib_System_Threading_ManagedThreadId::`vftable':\r\nGCHeap::Promote: Promote GC Root *00000218EABC2218 = 00000218D2746B00 MT = 00007FF62C0E6490T <- this is the threadStaticsStorageHandle GCHandle \r\n```\r\n\r\n- Could you please find out which link of the chain from the GCHandle to the ManagedThreadId object is broken after the GC? The chain should be: `GCHandle` -> `object[]` -> `GCStaticEEType` -> `System.Threading.ManagedThreadId`. You can do this by setting a breakpoint at RhGetThreadStaticStorageForModule and stepping through the code. When the GCHandle is fetched, you should see get object with `object[]` EEType. When the element of this array is fetched, you should get object with GCStaticEEType. When the field of this object is fetched, you should get object with ManagedThreadId.\r\n\r\n- Revert the change that adds RhpEnableConservativeStackReporting. We know that it is not helping, and it just adds a lot of clutter to the stack scanning.\r\n\r\n- It is interesting that the offending GC is the first GC with \"requested generation = 2\". You may be able to use this condition to turn on verbose tracing to reduce the size of the log if it becomes too hard to manage.\r\n\r\nThanks for helping us to trace this problem down!\r\n"}}
{"actor":{"display_login":"jkotas"}}