{"action":"created","issue":{"url":"https://api.github.com/repos/namhyung/uftrace/issues/111","repository_url":"https://api.github.com/repos/namhyung/uftrace","labels_url":"https://api.github.com/repos/namhyung/uftrace/issues/111/labels{/name}","comments_url":"https://api.github.com/repos/namhyung/uftrace/issues/111/comments","events_url":"https://api.github.com/repos/namhyung/uftrace/issues/111/events","html_url":"https://github.com/namhyung/uftrace/issues/111","id":237508645,"number":111,"title":"support scheduler event using perf syscall","user":{"login":"namhyung","id":48503,"avatar_url":"https://avatars0.githubusercontent.com/u/48503?v=4","gravatar_id":"","url":"https://api.github.com/users/namhyung","html_url":"https://github.com/namhyung","followers_url":"https://api.github.com/users/namhyung/followers","following_url":"https://api.github.com/users/namhyung/following{/other_user}","gists_url":"https://api.github.com/users/namhyung/gists{/gist_id}","starred_url":"https://api.github.com/users/namhyung/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/namhyung/subscriptions","organizations_url":"https://api.github.com/users/namhyung/orgs","repos_url":"https://api.github.com/users/namhyung/repos","events_url":"https://api.github.com/users/namhyung/events{/privacy}","received_events_url":"https://api.github.com/users/namhyung/received_events","type":"User","site_admin":false},"labels":[{"id":448384462,"url":"https://api.github.com/repos/namhyung/uftrace/labels/review","name":"review","color":"c2e0c6","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":24,"created_at":"2017-06-21T11:56:03Z","updated_at":"2017-08-30T06:18:59Z","closed_at":null,"author_association":"OWNER","body":"The Linux perf event system (from kernel v4.3) provides a way to trace scheduler context switch event without root privilege.  Using these events, one can know the program behavior more precisely IMHO.  Currently it only traces sched in/out events, but other events like page fault can be added easily if needed.  For now these sched events are always enabled if system supports.\r\n\r\nFollowing example shows a result of the t-sleep test program:\r\n\r\n```\r\n$ uftrace record -d sleep.data tests/t-sleep\r\n\r\n$ uftrace replay -d sleep.data\r\n# DURATION    TID     FUNCTION\r\n            [19307] | main() {\r\n            [19307] |   foo() {\r\n            [19307] |     mem_alloc() {\r\n   1.526 us [19307] |       malloc();\r\n   6.130 us [19307] |     } /* mem_alloc */\r\n            [19307] |     bar() {\r\n            [19307] |       usleep() {\r\n            [19307] |         /* perf_event: sched-out */\r\n   2.118 ms [19307] |         /* perf_event: sched-in */\r\n   2.135 ms [19307] |       } /* usleep */\r\n   2.137 ms [19307] |     } /* bar */\r\n            [19307] |     mem_free() {\r\n   3.700 us [19307] |       free();\r\n   4.655 us [19307] |     } /* mem_free */\r\n   2.149 ms [19307] |   } /* foo */\r\n   2.150 ms [19307] | } /* main */\r\n\r\n$ uftrace report -d sleep.data\r\n  Total time   Self time       Calls  Function\r\n  ==========  ==========  ==========  ====================================\r\n    2.150 ms    0.486 us           1  main\r\n    2.149 ms    1.121 us           1  foo\r\n    2.137 ms    2.218 us           1  bar\r\n    2.135 ms   16.918 us           1  usleep\r\n    6.130 us    4.604 us           1  mem_alloc\r\n    4.655 us    0.955 us           1  mem_free\r\n    3.700 us    3.700 us           1  free\r\n    1.526 us    1.526 us           1  malloc\r\n```\r\n\r\nThis is another example with two threads:\r\n\r\n```\r\n$ uftrace foobar\r\n# DURATION    TID     FUNCTION\r\n   1.185 us [19369] | __monstartup();\r\n   1.117 us [19369] | __cxa_atexit();\r\n            [19369] | main() {\r\n            [19369] |   foo() {\r\n   0.135 us [19369] |     bar();\r\n   0.732 us [19369] |   } /* foo */\r\n  76.508 us [19369] |   pthread_create();\r\n            [19369] |   pthread_join() {\r\n            [19369] |     /* perf_event: sched-out */\r\n            [19373] | /* perf_event: sched-in */\r\n            [19373] | foo() {\r\n   0.203 us [19373] |   bar();\r\n   1.656 us [19373] | } /* foo */\r\n 267.295 us [19369] |     /* perf_event: sched-in */\r\n 283.937 us [19369] |   } /* pthread_join */\r\n 363.592 us [19369] | } /* main */\r\n```\r\n\r\nPushed the code to [review/sched-event-v1](https://github.com/namhyung/uftrace/compare/review/sched-event-v1)."},"comment":{"url":"https://api.github.com/repos/namhyung/uftrace/issues/comments/325893265","html_url":"https://github.com/namhyung/uftrace/issues/111#issuecomment-325893265","issue_url":"https://api.github.com/repos/namhyung/uftrace/issues/111","id":325893265,"user":{"login":"honggyukim","id":19642328,"avatar_url":"https://avatars3.githubusercontent.com/u/19642328?v=4","gravatar_id":"","url":"https://api.github.com/users/honggyukim","html_url":"https://github.com/honggyukim","followers_url":"https://api.github.com/users/honggyukim/followers","following_url":"https://api.github.com/users/honggyukim/following{/other_user}","gists_url":"https://api.github.com/users/honggyukim/gists{/gist_id}","starred_url":"https://api.github.com/users/honggyukim/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/honggyukim/subscriptions","organizations_url":"https://api.github.com/users/honggyukim/orgs","repos_url":"https://api.github.com/users/honggyukim/repos","events_url":"https://api.github.com/users/honggyukim/events{/privacy}","received_events_url":"https://api.github.com/users/honggyukim/received_events","type":"User","site_admin":false},"created_at":"2017-08-30T06:18:59Z","updated_at":"2017-08-30T06:18:59Z","author_association":"CONTRIBUTOR","body":"Here is report output:\r\n```\r\n$ uftrace report -s self\r\n  Total time   Self time       Calls  Function\r\n  ==========  ==========  ==========  ====================================\r\n   11.942 ms   11.942 ms           1  v8::internal::Deserializer::ReadData\r\n    7.812 ms    7.812 ms           1  v8::internal::Genesis::Genesis\r\n    7.005 ms    6.909 ms           1  pthread_create\r\n   16.307 ms    4.362 ms           1  v8::internal::Heap::IterateStrongRoots\r\n   43.855 ms    2.763 ms           1  v8::Shell::Main\r\n   10.746 ms    2.469 ms           1  v8::Shell::RunMain\r\n   18.748 ms    2.440 ms           1  v8::internal::Deserializer::Deserialize\r\n   20.946 ms    2.198 ms           1  v8::internal::Isolate::Init\r\n    8.352 ms    1.130 ms           1  v8::platform::DefaultPlatform::EnsureInitialized\r\n  703.328 us  703.328 us          10  linux:schedule\r\n   21.553 ms  583.072 us           1  v8::Isolate::New\r\n    8.277 ms  412.977 us           1  v8::Shell::CreateEvaluationContext\r\n    8.392 ms   40.520 us           1  v8::platform::CreateDefaultPlatform\r\n    7.851 ms   39.107 us           1  v8::internal::Bootstrapper::CreateEnvironment\r\n   20.970 ms   23.550 us           1  v8::internal::Snapshot::Initialize\r\n    7.863 ms   11.797 us           1  v8::NewContext\r\n    7.010 ms    5.427 us           1  v8::base::Thread::Start\r\n    7.013 ms    3.320 us           1  v8::platform::WorkerThread::WorkerThread\r\n   43.856 ms    1.436 us           1  main\r\n   11.944 ms    1.246 us           1  v8::internal::Deserializer::VisitPointers\r\n    7.864 ms    0.409 us           1  v8::Context::New\r\n```\r\ngraph output:\r\n```\r\n$ uftrace graph\r\n#\r\n# function graph for 'main' (session: a3e4199ff2bbf40a)\r\n#\r\n\r\nbacktrace\r\n=====================================\r\n backtrace #0: hit 1, time  43.856 ms\r\n   [0] main (0x411da1)\r\n\r\ncalling functions\r\n=====================================\r\n  43.856 ms : (1) main\r\n  43.855 ms : (1) v8::Shell::Main\r\n   8.392 ms :  +-(1) v8::platform::CreateDefaultPlatform\r\n   8.352 ms :  | (1) v8::platform::DefaultPlatform::EnsureInitialized\r\n   7.013 ms :  |  +-(1) v8::platform::WorkerThread::WorkerThread\r\n   7.010 ms :  |  | (1) v8::base::Thread::Start\r\n   7.005 ms :  |  | (1) pthread_create\r\n  95.608 us :  |  | (4) linux:schedule\r\n            :  |  |\r\n 208.085 us :  |  +-(5) linux:schedule\r\n            :  |\r\n  21.553 ms :  +-(1) v8::Isolate::New\r\n  20.970 ms :  | (1) v8::internal::Snapshot::Initialize\r\n  20.946 ms :  | (1) v8::internal::Isolate::Init\r\n  18.748 ms :  | (1) v8::internal::Deserializer::Deserialize\r\n  16.307 ms :  | (1) v8::internal::Heap::IterateStrongRoots\r\n  11.944 ms :  | (1) v8::internal::Deserializer::VisitPointers\r\n  11.942 ms :  | (1) v8::internal::Deserializer::ReadData\r\n            :  |\r\n  10.746 ms :  +-(1) v8::Shell::RunMain\r\n   8.277 ms :  | (1) v8::Shell::CreateEvaluationContext\r\n   7.864 ms :  | (1) v8::Context::New\r\n   7.863 ms :  | (1) v8::NewContext\r\n   7.851 ms :  | (1) v8::internal::Bootstrapper::CreateEnvironment\r\n   7.812 ms :  | (1) v8::internal::Genesis::Genesis\r\n            :  |\r\n 399.635 us :  +-(1) linux:schedule\r\n```"}}
{"actor":{"display_login":"honggyukim"}}