{"action":"created","issue":{"url":"https://api.github.com/repos/dotnet/coreclr/issues/4910","repository_url":"https://api.github.com/repos/dotnet/coreclr","labels_url":"https://api.github.com/repos/dotnet/coreclr/issues/4910/labels{/name}","comments_url":"https://api.github.com/repos/dotnet/coreclr/issues/4910/comments","events_url":"https://api.github.com/repos/dotnet/coreclr/issues/4910/events","html_url":"https://github.com/dotnet/coreclr/issues/4910","id":154258939,"number":4910,"title":"[Request for help] Strange behavior for inlined unsafe calls","user":{"login":"ig-sinicyn","id":11225241,"avatar_url":"https://avatars.githubusercontent.com/u/11225241?v=3","gravatar_id":"","url":"https://api.github.com/users/ig-sinicyn","html_url":"https://github.com/ig-sinicyn","followers_url":"https://api.github.com/users/ig-sinicyn/followers","following_url":"https://api.github.com/users/ig-sinicyn/following{/other_user}","gists_url":"https://api.github.com/users/ig-sinicyn/gists{/gist_id}","starred_url":"https://api.github.com/users/ig-sinicyn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ig-sinicyn/subscriptions","organizations_url":"https://api.github.com/users/ig-sinicyn/orgs","repos_url":"https://api.github.com/users/ig-sinicyn/repos","events_url":"https://api.github.com/users/ig-sinicyn/events{/privacy}","received_events_url":"https://api.github.com/users/ig-sinicyn/received_events","type":"User","site_admin":false},"labels":[],"state":"closed","locked":false,"assignee":null,"milestone":null,"comments":2,"created_at":"2016-05-11T14:33:42Z","updated_at":"2016-05-11T16:21:53Z","closed_at":"2016-05-11T16:21:53Z","body":"Hi!\r\n\r\nWe've got a surprisingly wrong results when benchmarking some optimizations in our code. The real code runs definitely faster, but microbenchmarking shows that optimized version is slower that the original one.\r\n\r\nI've managed to write a simplified repro, here's [a gist](https://gist.github.com/ig-sinicyn/29a2d814060a58c531039c82bdd3704b) for it.\r\nNote that the timings for `FromAUnsafe` are depend on the method being called at the last line of each microbenchmark.\r\n\r\nThe output for the .net 4.6.1 (release, no debugger attached) is\r\n```\r\nx86\r\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\r\n              Original:   241ms, ips:         413 580 836,65 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n       OptimisedNoCall:   562ms, ips:         177 798 449,81 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n     OptimisedWithCall:   563ms, ips:         177 395 832,72 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n      OptimisedCallBox:   100ms, ips:         990 805 326,57 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n OptimisedCallBoxStore:   117ms, ips:         849 833 560,10 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n    OptimisedCallStore:    55ms, ips:       1 789 260 856,34 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n\r\n\r\nx64\r\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\r\n              Original:   794ms, ips:         125 802 810,64 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n       OptimisedNoCall:   535ms, ips:         186 786 882,70 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n     OptimisedWithCall:   530ms, ips:         188 459 743,02 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n      OptimisedCallBox:   474ms, ips:         210 602 930,92 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n OptimisedCallBoxStore:   474ms, ips:         210 695 315,61 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n    OptimisedCallStore:   474ms, ips:         210 662 248,38 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n```\r\n\r\n\r\nThe same code, but targeted to .net 3.5.\r\nThe x86 has the same problem but x64 runs ok.\r\n```\r\nx86\r\nmscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\r\n              Original:   115ms, ips:         865 049 658,18 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n       OptimisedNoCall:   311ms, ips:         320 990 087,51 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n     OptimisedWithCall:   310ms, ips:         322 460 190,68 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n      OptimisedCallBox:   119ms, ips:         834 264 233,17 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n OptimisedCallBoxStore:   118ms, ips:         841 590 741,16 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n    OptimisedCallStore:    56ms, ips:       1 773 455 276,12 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n\r\nx64\r\nmscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\r\n              Original:   123ms, ips:         812 746 465,37 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n       OptimisedNoCall:    29ms, ips:       3 409 315 613,98 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n     OptimisedWithCall:    64ms, ips:       1 558 472 323,09 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n      OptimisedCallBox:    62ms, ips:       1 589 976 786,34 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n OptimisedCallBoxStore:    63ms, ips:       1 585 205 593,24 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n    OptimisedCallStore:    62ms, ips:       1 608 482 493,28 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n```\r\n\r\nAnd the same code but with `[MethodImpl(MethodImplOptions.NoInlining)]` applied:\r\n```\r\nx86\r\nmscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\r\n              Original:   274ms, ips:         364 014 939,17 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n       OptimisedNoCall:   568ms, ips:         175 842 355,22 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n     OptimisedWithCall:   561ms, ips:         178 136 520,98 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n      OptimisedCallBox:   560ms, ips:         178 339 237,25 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n OptimisedCallBoxStore:   561ms, ips:         178 136 901,77 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n    OptimisedCallStore:   561ms, ips:         178 063 660,96 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\nDone...\r\n```\r\n\r\nNow, the question: is it a bug?\r\nAnd if it is, how can we avoid getting same slowdown in a production code?"},"comment":{"url":"https://api.github.com/repos/dotnet/coreclr/issues/comments/218511907","html_url":"https://github.com/dotnet/coreclr/issues/4910#issuecomment-218511907","issue_url":"https://api.github.com/repos/dotnet/coreclr/issues/4910","id":218511907,"user":{"login":"ig-sinicyn","id":11225241,"avatar_url":"https://avatars.githubusercontent.com/u/11225241?v=3","gravatar_id":"","url":"https://api.github.com/users/ig-sinicyn","html_url":"https://github.com/ig-sinicyn","followers_url":"https://api.github.com/users/ig-sinicyn/followers","following_url":"https://api.github.com/users/ig-sinicyn/following{/other_user}","gists_url":"https://api.github.com/users/ig-sinicyn/gists{/gist_id}","starred_url":"https://api.github.com/users/ig-sinicyn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/ig-sinicyn/subscriptions","organizations_url":"https://api.github.com/users/ig-sinicyn/orgs","repos_url":"https://api.github.com/users/ig-sinicyn/repos","events_url":"https://api.github.com/users/ig-sinicyn/events{/privacy}","received_events_url":"https://api.github.com/users/ig-sinicyn/received_events","type":"User","site_admin":false},"created_at":"2016-05-11T16:21:53Z","updated_at":"2016-05-11T16:21:53Z","body":"@mikedn \r\nWhoops, benchmark was done wrong, indeed. Here's [correct version](https://gist.github.com/ig-sinicyn/bcaeb004a84a22f44690d1ed4f7f7c3b) and the output is\r\n```\r\nx86\r\nmscorlib, Version=2.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089\r\n              Original:   279ms, ips:         357 493 200,48 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n       OptimisedNoCall:   640ms, ips:         156 071 663,74 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n     OptimisedWithCall:   581ms, ips:         171 837 308,56 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n      OptimisedCallBox:   590ms, ips:         169 301 276,70 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n OptimisedCallBoxStore:   578ms, ips:         172 962 023,07 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\n    OptimisedCallStore:   581ms, ips:         171 837 544,79 | Mem:      8,00 kb, GC 0/1/2: 0/0/0 => 100000000\r\nDone...\r\n```\r\nOk,  I'll check the original benchmark and if there's same flaw I'll close the issue.\r\n\r\nAs a sidenote, why the OptimisedNoCall run is the slowest one? (scratches head)."}}