{"action":"created","issue":{"url":"https://api.github.com/repos/xianyi/OpenBLAS/issues/731","labels_url":"https://api.github.com/repos/xianyi/OpenBLAS/issues/731/labels{/name}","comments_url":"https://api.github.com/repos/xianyi/OpenBLAS/issues/731/comments","events_url":"https://api.github.com/repos/xianyi/OpenBLAS/issues/731/events","html_url":"https://github.com/xianyi/OpenBLAS/issues/731","id":124970476,"number":731,"title":"Pathological threading behavior in OpenBLAS -> makes my test suite 4x slower than if using reference BLAS","user":{"login":"njsmith","id":609896,"avatar_url":"https://avatars.githubusercontent.com/u/609896?v=3","gravatar_id":"","url":"https://api.github.com/users/njsmith","html_url":"https://github.com/njsmith","followers_url":"https://api.github.com/users/njsmith/followers","following_url":"https://api.github.com/users/njsmith/following{/other_user}","gists_url":"https://api.github.com/users/njsmith/gists{/gist_id}","starred_url":"https://api.github.com/users/njsmith/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/njsmith/subscriptions","organizations_url":"https://api.github.com/users/njsmith/orgs","repos_url":"https://api.github.com/users/njsmith/repos","events_url":"https://api.github.com/users/njsmith/events{/privacy}","received_events_url":"https://api.github.com/users/njsmith/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":18,"created_at":"2016-01-05T13:50:54Z","updated_at":"2016-01-16T20:55:55Z","closed_at":null,"body":"I maintain a python library called \"patsy\", which runs tests on Travis-CI, and I was trying to figure out why some of my test runs were failing due to timeouts.\r\n\r\nI eventually tracked it down to, it turns out that some of the test configurations I was using were linked to OpenBLAS, and some were not. The OpenBLAS runs were taking >4x longer to complete. This is true even though the test suite actually spends most of its time doing other things besides linear algebra...\r\n\r\nIt turns out that the problem is some truly pathological behavior in OpenBLAS's threading code. Here's a simple example of two identical runs of the test suite, one with OpenBLAS in its default mode, and one with `OMP_NUM_THREADS=1`: https://travis-ci.org/pydata/patsy/builds/100343158\r\n\r\nThe biggest culprit appears to be the fact that one of the tests does a few tens of thousands of SVDs on small matrices. Here's a simple test case:\r\n```\r\nimport numpy as np\r\n\r\n# Generate a 20x2 matrix\r\nr = np.random.RandomState(0)\r\nm = r.randn(20, 2)\r\n\r\n# Calculate the svd\r\nfor i in xrange(100000):\r\n    np.linalg.svd(m)\r\n```\r\n\r\nRunning `time python svd-demo.py` on my laptop in different configurations:\r\n```\r\n# Reference BLAS:\r\n1.98s user 0.26s system 113% cpu 1.973 total\r\n# OpenBLAS with OMP_NUM_THREADS=1\r\n2.06s user 0.01s system 99% cpu 2.070 total\r\n# OpenBLAS with no tweaks\r\n5.80s user 10.87s system 379% cpu 4.392 total\r\n```\r\n\r\nSo having access to multiple threads makes things take more than 2x longer by wall clock time, and 8x more CPU time.\r\n\r\nHere's the top few lines from a `perf report`, showing that OpenBLAS is spending the vast majority of that time simply churning through the kernel scheduler, accomplishing nothing useful:\r\n```\r\nOverhead  Command  Shared Object                    Symbol                     ◆\r\n   9.87%  python   [kernel.kallsyms]                [k] __schedule             ▒\r\n   7.22%  python   [kernel.kallsyms]                [k] entry_SYSCALL_64       ▒\r\n   7.21%  python   [kernel.kallsyms]                [k] pick_next_task_fair    ▒\r\n   7.06%  python   libc-2.21.so                     [.] __sched_yield          ▒\r\n   5.55%  python   [kernel.kallsyms]                [k] entry_SYSCALL_64_after_▒\r\n   4.77%  python   libopenblas_nehalemp-r0.2.14.so  [.] blas_thread_server     ▒\r\n   4.70%  python   [kernel.kallsyms]                [k] native_sched_clock     ▒\r\n   4.56%  python   [kernel.kallsyms]                [k] cpuacct_charge         ▒\r\n   4.39%  python   [kernel.kallsyms]                [k] _raw_spin_lock_irq     ▒\r\n   4.18%  python   [kernel.kallsyms]                [k] _raw_spin_lock         ▒\r\n   3.56%  python   [kernel.kallsyms]                [k] update_curr            ▒\r\n   2.46%  python   [kernel.kallsyms]                [k] system_call_fast_compar▒\r\n   2.33%  python   [kernel.kallsyms]                [k] pick_next_entity       ▒\r\n```\r\n"},"comment":{"url":"https://api.github.com/repos/xianyi/OpenBLAS/issues/comments/172257342","html_url":"https://github.com/xianyi/OpenBLAS/issues/731#issuecomment-172257342","issue_url":"https://api.github.com/repos/xianyi/OpenBLAS/issues/731","id":172257342,"user":{"login":"brada4","id":16061801,"avatar_url":"https://avatars.githubusercontent.com/u/16061801?v=3","gravatar_id":"","url":"https://api.github.com/users/brada4","html_url":"https://github.com/brada4","followers_url":"https://api.github.com/users/brada4/followers","following_url":"https://api.github.com/users/brada4/following{/other_user}","gists_url":"https://api.github.com/users/brada4/gists{/gist_id}","starred_url":"https://api.github.com/users/brada4/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/brada4/subscriptions","organizations_url":"https://api.github.com/users/brada4/orgs","repos_url":"https://api.github.com/users/brada4/repos","events_url":"https://api.github.com/users/brada4/events{/privacy}","received_events_url":"https://api.github.com/users/brada4/received_events","type":"User","site_admin":false},"created_at":"2016-01-16T20:55:55Z","updated_at":"2016-01-16T20:55:55Z","body":"Total benchmark time includes (mostly) rand() on main thread\r\nDropping measurement loop start a bit down in benchmarks/swap.c I can measure small (20%) speedup 2 threads vs 1\r\n"}}