{"action":"created","issue":{"url":"https://api.github.com/repos/frerich/clcache/issues/251","repository_url":"https://api.github.com/repos/frerich/clcache","labels_url":"https://api.github.com/repos/frerich/clcache/issues/251/labels{/name}","comments_url":"https://api.github.com/repos/frerich/clcache/issues/251/comments","events_url":"https://api.github.com/repos/frerich/clcache/issues/251/events","html_url":"https://github.com/frerich/clcache/issues/251","id":193056240,"number":251,"title":"CacheLockException: Failed to acquire lock","user":{"login":"TiloW","id":845881,"avatar_url":"https://avatars.githubusercontent.com/u/845881?v=3","gravatar_id":"","url":"https://api.github.com/users/TiloW","html_url":"https://github.com/TiloW","followers_url":"https://api.github.com/users/TiloW/followers","following_url":"https://api.github.com/users/TiloW/following{/other_user}","gists_url":"https://api.github.com/users/TiloW/gists{/gist_id}","starred_url":"https://api.github.com/users/TiloW/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/TiloW/subscriptions","organizations_url":"https://api.github.com/users/TiloW/orgs","repos_url":"https://api.github.com/users/TiloW/repos","events_url":"https://api.github.com/users/TiloW/events{/privacy}","received_events_url":"https://api.github.com/users/TiloW/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":4,"created_at":"2016-12-02T08:02:20Z","updated_at":"2016-12-02T10:52:40Z","closed_at":null,"body":"Here's some general info about our system:\r\n\r\n> Windows Server 2012 R2 x64\r\n   6 GB RAM\r\n   E5-2650\r\n\r\nWe are using this machine for CI.\r\nBuild duration is usually 5 to 8 minutes and mostly spent on compilation.\r\nEvery build triggers up to 4 compiler calls in parallel and there can be two parallel builds (up to 8 concurrent compiler calls). \r\n\r\nSince trying out clcache for a few days we have disabled it again because of cache errors still existing after #244. \r\n\r\nHere's the error message we are receiving every now and then:\r\n```\r\n  Traceback (most recent call last):\r\n    File \"clcache.py\", line 1672, in <module>\r\n    File \"clcache.py\", line 1509, in main\r\n    File \"clcache.py\", line 1542, in processCompileRequest\r\n    File \"clcache.py\", line 1622, in processDirect\r\n    File \"clcache.py\", line 290, in __enter__\r\n    File \"clcache.py\", line 314, in acquire\r\n  __main__.CacheLockException: Failed to acquire lock Local\\C--Users-ogdf-clcache-manifests-45 after 30000ms; try setti\r\n  ng CLCACHE_OBJECT_CACHE_TIMEOUT_MS environment variable to a larger value.\r\n  Failed to execute script clcache\r\n```\r\n\r\nAs suggested in #229 I've upped the `CLCACHE_OBJECT_CACHE_TIMEOUT_MS` to 120.000 ms which **seems** to cause our builds to succeed. I've noted that the error seems to only occur when there are cache misses.\r\nOur cache is pretty much filled.\r\n```\r\n current cache dir         : C:\\Users\\ogdf\\clcache\r\n cache size                : 10,281,914,308 bytes\r\n maximum cache size        : 10,737,418,240 bytes\r\n cache entries             : 9229\r\n cache hits                : 63053\r\n cache misses\r\n   total                      : 33459\r\n   evicted                    : 383\r\n   header changed             : 22131\r\n   source changed             : 10945\r\n passed to real compiler\r\n   called w/ invalid argument : 0\r\n   called for preprocessing   : 0\r\n   called for linking         : 0\r\n   called for external debug  : 692\r\n   called w/o source          : 4\r\n   called w/ multiple sources : 0\r\n   called w/ PCH              : 0\r\n```\r\n\r\nI've re-enabled `clcache` in our CI now and will report if any errors arise with `CLCACHE_OBJECT_CACHE_TIMEOUT_MS=120000`.\r\n\r\nI don't know how exactly your locking mechanism works but already a default timeout of 10 seconds seems extremly high to me. You stated that [\"it might be the (unlikely) case that multiple clcache invocations are accessing the same manifest section\"](https://github.com/frerich/clcache/issues/229#issuecomment-264118051). How is this section determined?"},"comment":{"url":"https://api.github.com/repos/frerich/clcache/issues/comments/264427655","html_url":"https://github.com/frerich/clcache/issues/251#issuecomment-264427655","issue_url":"https://api.github.com/repos/frerich/clcache/issues/251","id":264427655,"user":{"login":"frerich","id":533425,"avatar_url":"https://avatars.githubusercontent.com/u/533425?v=3","gravatar_id":"","url":"https://api.github.com/users/frerich","html_url":"https://github.com/frerich","followers_url":"https://api.github.com/users/frerich/followers","following_url":"https://api.github.com/users/frerich/following{/other_user}","gists_url":"https://api.github.com/users/frerich/gists{/gist_id}","starred_url":"https://api.github.com/users/frerich/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/frerich/subscriptions","organizations_url":"https://api.github.com/users/frerich/orgs","repos_url":"https://api.github.com/users/frerich/repos","events_url":"https://api.github.com/users/frerich/events{/privacy}","received_events_url":"https://api.github.com/users/frerich/received_events","type":"User","site_admin":false},"created_at":"2016-12-02T10:52:40Z","updated_at":"2016-12-02T10:52:40Z","body":"> As you can see, already for 10 parallel calls there is a chance of about 20% for requesting the same section at least once.\r\n\r\nIndeed, for 10 concurrent calls, there is a ~17% chance that at least two of them access the same of 256 uniformly distributed sections.\r\n\r\nHowever, each section should only be held for a very short time (typically in the order of < 150ms). In particular, note that no lock is held while the compiler runs. The relevant code here is the [`processDirect`](https://github.com/frerich/clcache/blob/master/clcache.py#L1579) function. It first acquires a manifest lock to see whether there's an existing entry. If not, it releases all locks again (which should happen due to the `with` statement), invokes the real compiler, then acquires the lock again and adds the entry (unless it's there already due to another clcache invocation).\r\n\r\nIf you find that the default timeout of 10 seconds does not help with 8 concurrent compilers, then I suspect there is something else fishy.\r\n\r\nMy gut feeling is that there may be a deadlock due to a wrong order in which the locks are acquired and released (though I could not find any such place in the code after a review), or that there is some lock handle not being released properly, or maybe some operation which is performed under the lock is a lot slower for you than expected.\r\n\r\nYou don't happen to have the cache directory on a network drive or some aggressive virus scanner which tracks file accesses, do you? :-)\r\n"}}
{"actor":{"display_login":"frerich"}}