def __init__(self):
TestBase.__init__(self, 'exception', lang='C++', result="""
# DURATION TID FUNCTION
2.777 us [10827] | __cxa_atexit();
[10827] | foo() {
[10827] | __static_initialization_and_destruction_0() {
108.818 us [10827] | std::ios_base::Init::Init();
0.350 us [10827] | __cxa_atexit();
111.039 us [10827] | } /* __static_initialization_and_destruction_0 */
111.488 us [10827] | } /* foo */
[10827] | main() {
0.078 us [10827] | foo();
[10827] | test() {
[10827] | oops() {
1.752 us [10827] | __cxa_allocate_exception();
0.088 us [10827] | std::exception::exception();
9.640 us [10827] | __gxx_personality_v0();
9.640 us [10827] | __gxx_personality_v0();
9.640 us [10827] | __gxx_personality_v0();
84.367 us [10827] | } /* oops */
9.640 us [10827] | __gxx_personality_v0();
1.903 us [10827] | __gxx_personality_v0();
0.873 us [10827] | std::exception::~exception();
84.652 us [10827] | } /* test */
0.090 us [10827] | bar();
85.590 us [10827] | } /* main */
2.352 us [10827] | std::ios_base::Init::~Init();
""")
def __init__(self):
TestBase.__init__(self, 'lib', """
# DURATION TID FUNCTION
[17459] | lib_b() {
6.911 us [17459] | lib_c();
8.279 us [17459] | } /* lib_b */
""", sort='simple')
def __init__(self):
TestBase.__init__(self, 'taskname', ldflags='-pthread', serial=True, result="""
{"traceEvents":[
{"ts":0,"ph":"M","pid":4694,"name":"process_name","args":{"name":"[4694] bar"}},
{"ts":0,"ph":"M","pid":4694,"name":"thread_name","args":{"name":"[4694] bar"}},
{"ts":13453314717.085,"ph":"B","pid":4694,"name":"main"},
{"ts":13453314717.245,"ph":"B","pid":4694,"name":"task_name1"},
{"ts":13453314717.814,"ph":"B","pid":4694,"name":"prctl"},
{"ts":0,"ph":"M","pid":4694,"name":"process_name","args":{"name":"[4694] foo"}},
{"ts":0,"ph":"M","pid":4694,"name":"thread_name","args":{"name":"[4694] foo"}},
{"ts":13453314720.072,"ph":"E","pid":4694,"name":"prctl"},
{"ts":13453314720.665,"ph":"E","pid":4694,"name":"task_name1"},
{"ts":13453314720.793,"ph":"B","pid":4694,"name":"task_name2"},
{"ts":13453314720.920,"ph":"B","pid":4694,"name":"pthread_self"},
{"ts":13453314721.080,"ph":"E","pid":4694,"name":"pthread_self"},
{"ts":13453314721.264,"ph":"B","pid":4694,"name":"pthread_setname_np"},
{"ts":0,"ph":"M","pid":4694,"name":"process_name","args":{"name":"[4694] bar"}},
{"ts":0,"ph":"M","pid":4694,"name":"thread_name","args":{"name":"[4694] bar"}},
{"ts":13453314722.478,"ph":"E","pid":4694,"name":"pthread_setname_np"},
{"ts":13453314722.631,"ph":"E","pid":4694,"name":"task_name2"},
{"ts":13453314722.695,"ph":"E","pid":4694,"name":"main"}
], "displayTimeUnit": "ns", "metadata": {
"command_line":"../uftrace --no-pager -L.. record -d xxx t-taskname",
"recorded_time":"Tue Jan 30 16:05:24 2018"
} }
""", sort='chrome')
def __init__(self):
TestBase.__init__(self, 'posix_spawn', """
# DURATION TID FUNCTION
[ 9874] | main() {
142.145 us [ 9874] | posix_spawn();
[ 9874] | waitpid() {
[ 9875] | main() {
[ 9875] | a() {
[ 9875] | b() {
[ 9875] | c() {
0.976 us [ 9875] | getpid();
1.992 us [ 9875] | } /* c */
2.828 us [ 9875] | } /* b */
3.658 us [ 9875] | } /* a */
7.713 us [ 9875] | } /* main */
2.515 ms [ 9874] | } /* waitpid */
142.145 us [ 9874] | posix_spawn();
[ 9874] | waitpid() {
[ 9876] | main() {
2.828 us [ 9876] | fopen();
3.658 us [ 9876] | fclose();
7.713 us [ 9876] | } /* main */
2.515 ms [ 9874] | } /* waitpid */
2.708 ms [ 9874] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'dlopen', """1
# DURATION TID FUNCTION
1.404 us [22207] | __cxa_atexit();
[22207] | main() {
70.963 us [22207] | dlopen();
1.546 us [22207] | dlsym();
[22207] | lib_a() {
[22207] | lib_b() {
0.678 us [22207] | lib_c();
1.301 us [22207] | } /* lib_b */
2.104 us [22207] | } /* lib_a */
14.446 us [22207] | dlclose();
[22207] | dlopen() {
[22207] | s_libfoo.cpp() {
88.318 us [22207] | __static_initialization_and_destruction_0();
88.719 us [22207] | } /* s_libfoo.cpp */
148.243 us [22207] | } /* dlopen */
0.844 us [22207] | dlsym();
[22207] | foo() {
19.601 us [22207] | print_int();
19.869 us [22207] | } /* foo */
13.391 us [22207] | dlclose();
274.723 us [22207] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'longjmp3', """
# DURATION TID FUNCTION
1.164 us [ 4107] | __monstartup();
0.657 us [ 4107] | __cxa_atexit();
[ 4107] | main() {
0.705 us [ 4107] | _setjmp() = 0;
1.823 us [ 4107] | getpid();
0.182 us [ 4107] | _setjmp() = 0;
[ 4107] | foo() {
[ 4107] | longjmp(1) {
8.790 us [ 4107] | } = 1; /* _setjmp */
0.540 us [ 4107] | getpid();
[ 4107] | bar() {
[ 4107] | baz() {
[ 4107] | longjmp(2) {
1.282 us [ 4107] | } = 2; /* _setjmp */
0.540 us [ 4107] | getpid();
[ 4107] | foo() {
[ 4107] | longjmp(3) {
0.578 us [ 4107] | } = 3; /* _setjmp */
[ 4107] | bar() {
[ 4107] | baz() {
[ 4107] | longjmp(4) {
0.642 us [ 4107] | } = 4; /* _setjmp */
18.019 us [ 4107] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'sleep', result="""
# DURATION TID FUNCTION
[18260] | main() {
2.088 ms [18260] | foo();
2.090 ms [18260] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'abc', """
# DURATION TID FUNCTION
[28141] | a() {
1.915 us [28141] | b();
2.405 us [28141] | } /* a */
""", sort='simple')
def __init__(self):
TestBase.__init__(self, 'fork', """
# DURATION TID FUNCTION
[26125] | __cxa_atexit() {
68.297 us [26125] | } /* __cxa_atexit */
[26125] | main() {
[26125] | fork() {
101.456 us [26125] | } /* fork */
[26125] | wait() {
298.356 us [26126] | } /* fork */
[26126] | a() {
[26126] | b() {
[26126] | c() {
[26126] | getpid() {
1.206 us [26126] | } /* getpid */
1.925 us [26126] | } /* c */
2.531 us [26126] | } /* b */
3.151 us [26126] | } /* a */
333.039 us [26126] | } /* main */
19.376 us [26125] | } /* wait */
[26125] | a() {
[26125] | b() {
[26125] | c() {
[26125] | getpid() {
5.031 us [26125] | } /* getpid */
5.934 us [26125] | } /* c */
6.520 us [26125] | } /* b */
7.140 us [26125] | } /* a */
420.059 us [26125] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'sleep', serial=True, result="""
{"traceEvents":[
{"ts":0,"ph":"M","pid":306,"name":"process_name","args":{"name":"[306] t-sleep"}},
{"ts":0,"ph":"M","pid":306,"name":"thread_name","args":{"name":"[306] t-sleep"}},
{"ts":112150305218.363,"ph":"B","pid":306,"name":"__monstartup"},
{"ts":112150305220.090,"ph":"E","pid":306,"name":"__monstartup"},
{"ts":112150305224.313,"ph":"B","pid":306,"name":"__cxa_atexit"},
{"ts":112150305225.219,"ph":"E","pid":306,"name":"__cxa_atexit"},
{"ts":112150305226.496,"ph":"B","pid":306,"name":"main"},
{"ts":112150305226.752,"ph":"B","pid":306,"name":"foo"},
{"ts":112150305226.825,"ph":"B","pid":306,"name":"mem_alloc"},
{"ts":112150305226.921,"ph":"B","pid":306,"name":"malloc"},
{"ts":112150305227.641,"ph":"E","pid":306,"name":"malloc"},
{"ts":112150305228.173,"ph":"E","pid":306,"name":"mem_alloc"},
{"ts":112150305228.317,"ph":"B","pid":306,"name":"bar"},
{"ts":112150305228.436,"ph":"B","pid":306,"name":"usleep"},
{"ts":112150305241.755,"ph":"B","pid":306,"name":"linux:schedule"},
{"ts":112150307301.727,"ph":"E","pid":306,"name":"linux:schedule"},
{"ts":112150307318.143,"ph":"E","pid":306,"name":"usleep"},
{"ts":112150307321.099,"ph":"E","pid":306,"name":"bar"},
{"ts":112150307322.007,"ph":"B","pid":306,"name":"mem_free"},
{"ts":112150307323.132,"ph":"B","pid":306,"name":"free"},
{"ts":112150307328.403,"ph":"E","pid":306,"name":"free"},
{"ts":112150307328.615,"ph":"E","pid":306,"name":"mem_free"},
{"ts":112150307328.742,"ph":"E","pid":306,"name":"foo"},
{"ts":112150307328.905,"ph":"E","pid":306,"name":"main"}
], "displayTimeUnit": "ns", "metadata": {
"command_line":"uftrace record -d xxx -E linux:schedule t-sleep ",
"recorded_time":"Fri Aug 25 14:23:29 2017"
} }
""", sort='chrome')
def __init__(self):
TestBase.__init__(self, 'abc', """
main 1
main;a 1
main;a;b 1
main;a;b;c 1
""")
def __init__(self):
TestBase.__init__(self, 'allocfree', """
# DURATION TID FUNCTION
3.937 us [ 447] | __monstartup();
1.909 us [ 447] | __cxa_atexit();
[ 447] | main() {
[ 447] | alloc1() {
[ 447] | alloc2() {
[ 447] | alloc3() {
[ 447] | alloc4() {
[ 447] | alloc5() {
8.408 us [ 447] | malloc(1);
10.642 us [ 447] | } /* alloc5 */
11.502 us [ 447] | } /* alloc4 */
12.057 us [ 447] | } /* alloc3 */
12.780 us [ 447] | } /* alloc2 */
13.400 us [ 447] | } /* alloc1 */
[ 447] | free1() {
[ 447] | free2() {
[ 447] | free3() {
[ 447] | free4() {
[ 447] | free5() {
2.072 us [ 447] | free();
3.951 us [ 447] | } /* free5 */
4.561 us [ 447] | } /* free4 */
5.151 us [ 447] | } /* free3 */
5.713 us [ 447] | } /* free2 */
6.341 us [ 447] | } /* free1 */
21.174 us [ 447] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'sleep', result="""
# DURATION TID FUNCTION
[18229] | bar() {
2.078 ms [18229] | usleep();
2.080 ms [18229] | } /* bar */
""", sort='simple')
def __init__(self):
TestBase.__init__(self, 'abc', """
a enter
b enter
b exit
a exit
""")
def __init__(self):
TestBase.__init__(self, 'abc', """
uftrace file header: magic = 4674726163652100
uftrace file header: version = 4
uftrace file header: header size = 40
uftrace file header: endian = 1 (little)
uftrace file header: class = 2 (64 bit)
uftrace file header: features = 0x363 (PLTHOOK | TASK_SESSION | SYM_REL_ADDR | MAX_STACK | PERF_EVENT | AUTO_ARGS)
uftrace file header: info = 0x3bff
reading 5231.dat
58348.873430946 5231: [entry] __monstartup(4004d0) depth: 0
58348.873433169 5231: [exit ] __monstartup(4004d0) depth: 0
58348.873439477 5231: [entry] __cxa_atexit(4004f0) depth: 0
58348.873440994 5231: [exit ] __cxa_atexit(4004f0) depth: 0
58348.873444506 5231: [entry] main(400512) depth: 0
58348.873444843 5231: [entry] a(4006b2) depth: 1
58348.873445107 5231: [entry] b(4006a0) depth: 2
58348.873445348 5231: [entry] c(400686) depth: 3
58348.873445830 5231: [entry] getpid(4004b0) depth: 4
58348.873447154 5231: [exit ] getpid(4004b0) depth: 4
58348.873448318 5231: [exit ] c(400686) depth: 3
58348.873448707 5231: [exit ] b(4006a0) depth: 2
58348.873448996 5231: [exit ] a(4006b2) depth: 1
58348.873449309 5231: [exit ] main(400512) depth: 0
""", sort='dump')
def __init__(self):
TestBase.__init__(
self,
"signal2",
"""
# DURATION TID FUNCTION
3.966 us [24050] | __monstartup();
0.342 us [24050] | __cxa_atexit();
[24050] | main() {
0.483 us [24050] | signal();
1.476 us [24050] | setitimer();
[24050] | foo() {
[24050] | bar() {
0.401 us [24050] | sighandler();
4.074 ms [24050] | } /* bar */
[24050] | bar() {
0.086 us [24050] | sighandler();
3.330 ms [24050] | } /* bar */
[24050] | bar() {
0.099 us [24050] | sighandler();
3.331 ms [24050] | } /* bar */
10.736 ms [24050] | } /* foo */
10.738 ms [24050] | } /* main */
""",
)
def __init__(self):
TestBase.__init__(self, 'forkexec', result="""
# Function Call Graph for 'main' (session: 327202376e209585)
=============== BACKTRACE ===============
backtrace #0: hit 1, time 5.824 us
[0] main (0x400530)
========== FUNCTION CALL GRAPH ==========
5.824 us : (1) main
5.411 us : (1) a
5.141 us : (1) b
4.670 us : (1) c
0.967 us : (1) getpid
# Function Call Graph for 'main' (session: f34056bd485963b3)
=============== BACKTRACE ===============
backtrace #0: hit 1, time 3.679 ms
[0] main (0x4005b0)
========== FUNCTION CALL GRAPH ==========
3.679 ms : (1) main
127.172 us : +-(1) fork
: |
3.527 ms : +-(1) waitpid
""")
def __init__(self):
TestBase.__init__(self, 'fork', """
# DURATION TID FUNCTION
[ 1661] | main() {
[ 1661] | fork() {
5.135 us [ 1661] | sys_writev();
32.391 us [ 1661] | do_syscall_64();
12.192 us [ 1661] | __do_page_fault();
10.982 us [ 1661] | __do_page_fault();
9.183 us [ 1661] | __do_page_fault();
130.930 us [ 1661] | } /* fork */
17.134 us [ 1661] | __do_page_fault();
12.813 us [ 1661] | __do_page_fault();
9.465 us [ 1661] | __do_page_fault();
3.187 us [ 1661] | __do_page_fault();
6.873 us [ 1661] | __do_page_fault();
[ 1661] | wait() {
6.508 us [ 1661] | __do_page_fault();
7.074 us [ 1661] | sys_wait4();
691.873 us [ 1661] | } /* wait */
[ 1661] | a() {
[ 1661] | b() {
[ 1661] | c() {
4.234 us [ 1661] | getpid();
5.680 us [ 1661] | } /* c */
6.094 us [ 1661] | } /* b */
6.602 us [ 1661] | } /* a */
849.948 us [ 1661] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'fork', """
uftrace file header: magic = 4674726163652100
uftrace file header: version = 4
uftrace file header: header size = 40
uftrace file header: endian = 1 (little)
uftrace file header: class = 2 (64 bit)
uftrace file header: features = 0x363 (PLTHOOK | TASK_SESSION | SYM_REL_ADDR | MAX_STACK | PERF_EVENT | AUTO_ARGS)
uftrace file header: info = 0x3bff
reading 5186.dat
58071.916834908 5186: [entry] main(400590) depth: 0
58071.916835853 5186: [entry] fork(400580) depth: 1
58071.917056572 5186: [exit ] fork(400580) depth: 1
58071.917091028 5186: [entry] wait(400570) depth: 1
58071.918038822 5186: [exit ] wait(400570) depth: 1
58071.918040938 5186: [entry] a(400774) depth: 1
58071.918041182 5186: [entry] b(400741) depth: 2
58071.918041482 5186: [entry] c(400706) depth: 3
58071.918042306 5186: [entry] getpid(400530) depth: 4
58071.918045615 5186: [exit ] getpid(400530) depth: 4
58071.918048103 5186: [exit ] c(400706) depth: 3
58071.918048457 5186: [exit ] b(400741) depth: 2
58071.918048760 5186: [exit ] a(400774) depth: 1
58071.918049117 5186: [exit ] main(400590) depth: 0
reading 5188.dat
""", sort='dump')
def __init__(self):
TestBase.__init__(self, 'hello', """
# system information
# ==================
# program version : uftrace v0.8.1-133-g7f71
# recorded on : Mon Nov 27 09:40:31 2017
# cmdline : ../uftrace --no-pager -L.. record -d xxx t-hello \\"uftrace\\"
# cpu info : Intel(R) Core(TM) i7-3930K CPU @ 3.20GHz
# number of cpus : 12 / 12 (online / possible)
# memory info : 13.2 / 23.5 GB (free / total)
# system load : 3.25 / 3.17 / 3.11 (1 / 5 / 15 min)
# kernel version : Linux 4.13.11-1-ARCH
# hostname : sejong
# distro : "Arch Linux"
#
# process information
# ===================
# number of tasks : 1
# task list : 10217
# exe image : /home/namhyung/project/uftrace/tests/t-hello
# build id : 7fde527c74f398c5f48b5ec30173d2c17366dd90
# exit status : exited with code: 0
# elapsed time : 0.004278080 sec
# cpu time : 0.002 / 0.002 sec (sys / user)
# context switch : 1 / 0 (voluntary / involuntary)
# max rss : 3284 KB
# page fault : 0 / 197 (major / minor)
# disk iops : 0 / 16 (read / write)""")
def __init__(self):
TestBase.__init__(self, 'namespace', lang="C++", result="""
# Function Call Graph for 'main' (session: b508f628ffe7287f)
=============== BACKTRACE ===============
backtrace #0: hit 1, time 17.931 us
[0] main (0x400790)
========== FUNCTION CALL GRAPH ==========
17.931 us : (1) main
2.087 us : +-(2) operator new
: |
0.183 us : +-(1) ns::ns1::foo::foo
: |
4.816 us : +-(1) ns::ns1::foo::bar
2.810 us : | +-(1) ns::ns1::foo::bar1
2.536 us : | | (1) ns::ns1::foo::bar2
2.240 us : | | (1) ns::ns1::foo::bar3
: | |
1.356 us : | +-(1) free
: |
2.624 us : +-(2) operator delete
: |
0.093 us : +-(1) ns::ns2::foo::foo
: |
1.997 us : +-(1) ns::ns2::foo::bar
1.286 us : +-(1) ns::ns2::foo::bar1
1.017 us : | (1) ns::ns2::foo::bar2
0.740 us : | (1) ns::ns2::foo::bar3
: |
0.187 us : +-(1) free
""", sort='graph')
def __init__(self):
TestBase.__init__(
self,
"thread-exec",
"""
# DURATION TID FUNCTION
[23290] | main() {
29.452 us [23290] | pthread_create();
[23292] | thread_func() {
[23292] | execl() {
[23290] | main() {
[23290] | a() {
[23290] | b() {
[23290] | c() {
0.379 us [23290] | getpid();
0.772 us [23290] | } /* c */
1.159 us [23290] | } /* b */
1.289 us [23290] | } /* a */
1.461 us [23290] | } /* main */
uftrace stopped tracing with remaining functions
================================================
task: 23290
[0] main
""",
)
def __init__(self):
TestBase.__init__(self, 'allocfree', """
# DURATION TID FUNCTION
101.601 us [31924] | __monstartup();
2.047 us [31924] | __cxa_atexit();
[31924] | main() {
[31924] | alloc1() {
[31924] | alloc2() {
3.010 us [31924] | alloc3();
4.068 us [31924] | } /* alloc2 */
4.611 us [31924] | } /* alloc1 */
[31924] | free1() {
[31924] | free2() {
[31924] | free3() {
[31924] | free4() {
[31924] | free5() {
backtrace [31924] | /* [ 0] main */
backtrace [31924] | /* [ 1] free1 */
backtrace [31924] | /* [ 2] free2 */
backtrace [31924] | /* [ 3] free3 */
backtrace [31924] | /* [ 4] free4 */
backtrace [31924] | /* [ 5] free5 */
1.894 us [31924] | free();
2.921 us [31924] | } /* free5 */
3.504 us [31924] | } /* free4 */
4.059 us [31924] | } /* free3 */
4.588 us [31924] | } /* free2 */
5.177 us [31924] | } /* free1 */
11.175 us [31924] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'allocfree', """
# DURATION TID FUNCTION
2.417 us [32130] | __monstartup();
1.535 us [32130] | __cxa_atexit();
[32130] | main() {
[32130] | alloc1(1) {
[32130] | alloc2(1) {
[32130] | alloc3(1) {
[32130] | alloc4(1) {
[32130] | alloc5(1) {
1.850 us [32130] | malloc(1);
4.284 us [32130] | } /* alloc5 */
11.517 us [32130] | } /* alloc4 */
12.357 us [32130] | } /* alloc3 */
13.036 us [32130] | } /* alloc2 */
14.543 us [32130] | } /* alloc1 */
[32130] | free1() {
[32130] | free2() {
[32130] | free3() {
[32130] | free4() {
[32130] | free5() {
1.394 us [32130] | free();
2.970 us [32130] | } /* free5 */
3.531 us [32130] | } /* free4 */
4.064 us [32130] | } /* free3 */
4.641 us [32130] | } /* free2 */
5.271 us [32130] | } /* free1 */
21.319 us [32130] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'malloc', """
# DURATION TID FUNCTION
[16726] | main() {
0.426 us [16726] | malloc();
0.397 us [16726] | free();
3.074 us [16726] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'malloc-hook', ldflags='-ldl', result="""
# DURATION TID FUNCTION
[ 4408] | main() {
0.470 us [ 4408] | malloc();
0.390 us [ 4408] | free();
1.512 us [ 4408] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'dynamic', """
# DURATION TID FUNCTION
[ 63876] | main() {
0.739 us [ 63876] | foo();
0.833 us [ 63876] | bar();
1.903 us [ 63876] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'openclose', """
# DURATION TID FUNCTION
[15973] | main() {
5.903 us [15973] | fopen();
4.374 us [15973] | fclose();
15.262 us [15973] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'hello', """
# DURATION TID FUNCTION
62.202 us [28141] | __cxa_atexit();
[28141] | main() {
2.405 us [28141] | printf("Hello %s\\n", "01234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234...");
3.005 us [28141] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'exp-char', result="""
# DURATION TID FUNCTION
[18279] | main() {
0.371 ms [18279] | foo('f', 'o', 'o');
0.923 ms [18279] | bar('\\x00', 'B', 97, 0x72);
3.281 ms [18279] | } /* main */
""")
def __init__(self):
TestBase.__init__(
self, 'diff', """
#
# uftrace diff
# [0] base: xxx (from uftrace record -d xxx -F main tests/t-diff 0 )
# [1] diff: yyy (from uftrace record -d yyy -F main tests/t-diff 1 )
#
Total time Self time Calls Function
========== ========== ========== ====================
-5.40% -5.40% +0 atoi
+999.99% +875.84% +0 bar
+999.99% +498.85% +0 foo
+999.99% +10.47% +0 main
+999.99% +999.99% +3 usleep
""")
def __init__(self):
TestBase.__init__(
self, 'abc', """
# DURATION TID FUNCTION
62.202 us [28141] | __cxa_atexit();
[28141] | main() {
[28141] | a() {
[28141] | b() {
[28141] | c() {
0.753 us [28141] | getpid();
1.430 us [28141] | } /* c */
1.915 us [28141] | } /* b */
2.405 us [28141] | } /* a */
3.005 us [28141] | } /* main */
""")
self.gen_port()
def __init__(self):
TestBase.__init__(
self, 'abc', """
# DURATION TID FUNCTION
[32766] | main() {
[32766] | a() {
[32766] | b() {
[32766] | /* read:page-fault (major=0, minor=188) */
[32766] | c() {
0.609 us [32766] | getpid();
13.722 us [32766] | } /* c */
[32766] | /* diff:page-fault (major=+0, minor=+1) */
24.950 us [32766] | } /* b */
25.564 us [32766] | } /* a */
26.963 us [32766] | } /* main */
""")
def __init__(self):
TestBase.__init__(self,
'dwarf1',
"""
# DURATION TID FUNCTION
[ 29831] | main() {
0.495 us [ 29831] | foo(-1, 32768) = 32767;
[ 29831] | bar("string argument", 'c', 0.000010, &null) {
0.660 us [ 29831] | null("NULL");
442.163 us [ 29831] | } = -1.000000; /* bar */
[ 29831] | baz(ONE) {
0.323 us [ 29831] | foo(1, -1) = 0;
1.291 us [ 29831] | } /* baz */
449.927 us [ 29831] | } = 0; /* main */
""",
cflags='-g')
def __init__(self):
TestBase.__init__(
self, 'abc', """
#
# uftrace diff
# [0] base: xxx (from uftrace record -d xxx tests/t-abc )
# [1] diff: yyy (from uftrace record -d yyy tests/t-abc )
#
Total time (diff) Self time (diff) Nr. called (diff) Function
================================ ================================ ================================ ====================================
6.974 us 6.268 us -10.12% 0.560 us 0.511 us -8.75% 1 1 +0 main
6.414 us 5.757 us -10.24% 0.489 us 0.372 us -23.93% 1 1 +0 a
5.925 us 5.385 us -9.11% 0.786 us 0.554 us -29.52% 1 1 +0 b
5.139 us 4.831 us -5.99% 3.517 us 3.137 us -10.80% 1 1 +0 c
1.622 us 1.694 us +4.44% 1.622 us 1.694 us +4.44% 1 1 +0 getpid
""")
def __init__(self):
TestBase.__init__(
self, 'abc', """
# DURATION TID FUNCTION
[32417] | main() {
[32417] | a() {
[32417] | b() {
[32417] | /* read:proc/statm (size=6812KB, rss=780KB, shared=716KB) */
[32417] | c() {
0.479 us [32417] | getpid();
3.014 us [32417] | } /* c */
[32417] | /* diff:proc/statm (size=+0KB, rss=+0KB, shared=+0KB) */
16.914 us [32417] | } /* b */
17.083 us [32417] | } /* a */
17.873 us [32417] | } /* main */
""")
def __init__(self):
TestBase.__init__(self,
'sleep',
result="""
# Function Call Graph for 'main' (session: b78e9c27042adaa7)
=============== BACKTRACE ===============
backtrace #0: hit 1, time 2.109 ms
[0] main (0x400570)
========== FUNCTION CALL GRAPH ==========
2.109 ms : (1) main
2.109 ms : (1) foo
2.098 ms : (1) bar
2.096 ms : (1) usleep
""",
sort='graph')
def __init__(self):
TestBase.__init__(
self, 'abc', """
# DURATION TID FUNCTION
[32417] | main() {
[32417] | a() {
[32417] | b() {
[32417] | /* read:pmu-cache (refers=2105, misses=271) */
[32417] | c() {
0.479 us [32417] | getpid();
3.014 us [32417] | } /* c */
[32417] | /* diff:pmu-cache (refers=+23, misses=+5, hit=78%) */
16.914 us [32417] | } /* b */
17.083 us [32417] | } /* a */
17.873 us [32417] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'abc', """
{"traceEvents":[
{"ts":58348873444,"ph":"B","pid":5231,"name":"main"},
{"ts":58348873444,"ph":"B","pid":5231,"name":"a"},
{"ts":58348873445,"ph":"B","pid":5231,"name":"b"},
{"ts":58348873445,"ph":"B","pid":5231,"name":"c"},
{"ts":58348873448,"ph":"E","pid":5231,"name":"c"},
{"ts":58348873448,"ph":"E","pid":5231,"name":"b"},
{"ts":58348873448,"ph":"E","pid":5231,"name":"a"},
{"ts":58348873449,"ph":"E","pid":5231,"name":"main"}
], "metadata": {
"command_line":"uftrace record -d abc.data t-abc ",
"recorded_time":"Sat Oct 1 18:19:06 2016"
} }
""", sort='chrome')
def __init__(self):
TestBase.__init__(
self, 'abc', """
# DURATION TID FUNCTION
[32417] | main() {
[32417] | a() {
[32417] | b() {
[32417] | /* read:pmu-branch (branch=15482, misses=1192) */
[32417] | c() {
0.479 us [32417] | getpid();
3.014 us [32417] | } /* c */
[32417] | /* diff:pmu-branch (branch=+785, misses=+71, predict=90%) */
16.914 us [32417] | } /* b */
17.083 us [32417] | } /* a */
17.873 us [32417] | } /* main */
""")
def __init__(self):
TestBase.__init__(
self, 'diff', """
#
# uftrace diff
# [0] base: xxx (from uftrace record -d yyy -F main tests/t-diff 1 )
# [1] diff: yyy (from uftrace record -d xxx -F main tests/t-diff 0 )
#
Total time (diff) Self time (diff) Calls (diff) Function
=================================== =================================== ================================ ================================================
1.075 us 1.048 us -0.027 us 1.075 us 1.048 us -0.027 us 1 1 +0 atoi
158.971 us 0.118 us -158.853 us 1.437 us 0.118 us -1.319 us 1 1 +0 bar
1.235 ms 0.645 us -1.235 ms 3.276 us 0.527 us -2.749 us 1 1 +0 foo
1.309 ms 3.975 us -1.305 ms 2.601 us 2.282 us -0.319 us 1 1 +0 main
1.300 ms - -1.300 ms 1.300 ms - -1.300 ms 3 0 -3 usleep
""")
def __init__(self):
TestBase.__init__(self,
'sleep',
result="""
# DURATION TID FUNCTION
[13256] | main() {
[13256] | foo() {
[13256] | mem_alloc() {
1.000 us [13256] | malloc();
1.769 us [13256] | } /* mem_alloc */
[13256] | bar() {
2.073 ms [13256] | usleep();
2.075 ms [13256] | } /* bar */
2.084 ms [13256] | } /* foo */
2.085 ms [13256] | } /* main */
""")
def __init__(self):
TestBase.__init__(
self, 'sleep', """
# DURATION TID FUNCTION
[18219] | main() {
[18219] | foo() {
[18219] | /* read:proc/statm (size=6812KB, rss=784KB, shared=716KB) */
[18219] | bar() {
[18219] | /* read:proc/statm (size=6812KB, rss=784KB, shared=716KB) */
2.093 ms [18219] | usleep();
[18219] | /* diff:proc/statm (size=+0KB, rss=+0KB, shared=+0KB) */
2.095 ms [18219] | } /* bar */
[18219] | /* diff:proc/statm (size=+0KB, rss=+0KB, shared=+0KB) */
2.106 ms [18219] | } /* foo */
2.107 ms [18219] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'sort', result="""
# Function Call Graph for 'main' (session: 54047ea45c46ad91)
=============== BACKTRACE ===============
backtrace #0: hit 1, time 10.329 ms
[0] main (0x4004e0)
========== FUNCTION CALL GRAPH ==========
10.329 ms : (1) main
53.100 us : +-(2) foo
50.745 us : | (6) loop
: |
10.150 ms : +-(1) bar
10.102 ms : (1) usleep
10.088 ms : (1) linux:schedule
""", sort='graph')
def __init__(self):
TestBase.__init__(
self, 'abc', """
# DURATION TID FUNCTION
0.508 us [ 772] | __monstartup();
0.425 us [ 772] | __cxa_atexit();
[ 772] | main() {
[ 772] | a() {
[ 772] | b() {
[ 772] | c() {
0.419 us [ 772] | getpid();
0.844 us [ 772] | }
1.037 us [ 772] | }
1.188 us [ 772] | }
1.378 us [ 772] | }
""")
def __init__(self):
TestBase.__init__(
self, 'abc', """
# DURATION TID FUNCTION
[32417] | main() {
[32417] | a() {
[32417] | b() {
[32417] | /* read:pmu-cycle (cycle=133314, instructions=74485) */
[32417] | c() {
0.479 us [32417] | getpid();
3.014 us [32417] | } /* c */
[32417] | /* diff:pmu-cycle (cycle=+5014, instructions=+3514, IPC=0.70) */
16.914 us [32417] | } /* b */
17.083 us [32417] | } /* a */
17.873 us [32417] | } /* main */
""")
def __init__(self):
TestBase.__init__(
self, 'openclose', """
# DURATION TID FUNCTION
1.088 us [18343] | __monstartup();
0.640 us [18343] | __cxa_atexit();
[18343] | main() {
[18343] | fopen() {
86.790 us [18343] | sys_open();
89.018 us [18343] | } /* fopen */
[18343] | fclose() {
10.781 us [18343] | sys_close();
37.325 us [18343] | } /* fclose */
128.387 us [18343] | } /* main */
""")
self.gen_port()
def __init__(self):
TestBase.__init__(self,
'sleep',
result="""
# DURATION TID FUNCTION
[16873] | main() {
[16873] | foo() {
[16873] | mem_alloc() {
1.675 us [16873] | malloc();
6.867 us [16873] | } /* mem_alloc */
[16873] | bar() {
2.068 ms [16873] | usleep();
2.071 ms [16873] | } /* bar */
2.085 ms [16873] | } /* foo */
2.086 ms [16873] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'sort', """
# Function Call Graph for 'main' (session: 67af3e650b051216)
=============== BACKTRACE ===============
backtrace #0: hit 1, time 10.148 ms
[0] main (0x560e956bd610)
========== FUNCTION CALL GRAPH ==========
# TOTAL TIME SELF TIME ADDRESS FUNCTION
10.148 ms 37.889 us 560e956bd610 : (1) main
15.991 us 0.765 us 560e956bd7ce : +-(2) foo
15.226 us 15.226 us 560e956bd7a0 : | (6) loop
: |
10.094 ms 13.365 us 560e956bd802 : +-(1) bar
10.081 ms 10.081 ms 560e956bd608 : (1) usleep
""", sort='graph')
def __init__(self):
TestBase.__init__(
self, 'openclose', """
# DURATION TID FUNCTION
1.088 us [18343] | __monstartup();
0.640 us [18343] | __cxa_atexit();
[18343] | main() {
[18343] | open() {
86.790 us [18343] | sys_open();
89.018 us [18343] | } /* open */
[18343] | close() {
10.781 us [18343] | sys_close();
21.980 us [18343] | exit_to_usermode_loop();
37.325 us [18343] | } /* close */
128.387 us [18343] | } /* main */
""")
def __init__(self):
TestBase.__init__(
self, 'diff', """
#
# uftrace diff
# [0] base: xxx (from uftrace record -d xxx -F main tests/t-diff 0 )
# [1] diff: yyy (from uftrace record -d yyy -F main tests/t-diff 1 )
#
Total time Self time Calls Function
=========== =========== =========== ====================
+0.027 us +0.027 us +0 atoi
+158.853 us +1.319 us +0 bar
+1.235 ms +2.749 us +0 foo
+1.305 ms +0.319 us +0 main
+1.300 ms +1.300 ms +3 usleep
""")
def __init__(self):
TestBase.__init__(self,
'sort',
"""
Total time Self time Calls Function
========== ========== ========== ====================================
1.152 ms 71.683 us 1 main
1.080 ms 1.813 us 1 bar
1.078 ms 2.892 us 1 usleep
1.075 ms 1.075 ms 1 linux:schedule
70.176 us 70.176 us 1 __monstartup # ignore this
37.525 us 1.137 us 2 foo
36.388 us 36.388 us 6 loop
1.200 us 1.200 us 1 __cxa_atexit # and this too
""",
sort='report')
def __init__(self):
TestBase.__init__(self, 'namespace', lang="C++", result="""
# DURATION TID FUNCTION
4.843 us [29826] | operator new();
1.846 us [29826] | ns::ns1::foo::foo();
[29826] | ns::ns1::foo::bar() {
[29826] | ns::ns1::foo::bar1() {
[29826] | ns::ns1::foo::bar2() {
[29826] | ns::ns1::foo::bar3() {
0.597 us [29826] | operator new();
0.317 us [29826] | ns::ns2::foo::foo();
[29826] | ns::ns2::foo::bar() {
[29826] | ns::ns2::foo::bar1() {
[29826] | ns::ns2::foo::bar2() {
[29826] | ns::ns2::foo::bar3() {
""", sort='simple')
def __init__(self):
TestBase.__init__(self, 'namespace', lang="C++", result="""
# DURATION TID FUNCTION
[12683] | ns::ns2::foo::bar() {
[12683] | ns::ns2::foo::bar1() {
[12683] | ns::ns2::foo::bar2() {
[12683] | ns::ns2::foo::bar3() {
1.067 us [12683] | malloc();
2.390 us [12683] | } /* ns::ns2::foo::bar3 */
3.197 us [12683] | } /* ns::ns2::foo::bar2 */
4.177 us [12683] | } /* ns::ns2::foo::bar1 */
0.695 us [12683] | free();
105.025 us [12683] | } /* ns::ns2::foo::bar */
0.602 us [12683] | operator delete();
[12683] | } /* main */
""")
def __init__(self):
TestBase.__init__(self,
'allocfree',
"""
# DURATION TID FUNCTION
backtrace [ 4629] | /* [ 0] main */
backtrace [ 4629] | /* [ 1] alloc1 */
backtrace [ 4629] | /* [ 2] alloc2 */
backtrace [ 4629] | /* [ 3] alloc3 */
[ 4629] | alloc4() {
[ 4629] | alloc5() {
2.020 us [ 4629] | malloc();
4.334 us [ 4629] | } /* alloc5 */
4.671 us [ 4629] | } /* alloc4 */
""",
sort='simple')
def __init__(self):
TestBase.__init__(self,
'sleep',
serial=True,
result="""
# DURATION TID FUNCTION
[ 395] | main() {
[ 395] | foo() {
[ 395] | bar() {
[ 395] | usleep() {
2.088 ms [ 395] | /* linux:schedule */
2.105 ms [ 395] | } /* usleep */
2.109 ms [ 395] | } /* bar */
2.120 ms [ 395] | } /* foo */
2.121 ms [ 395] | } /* main */
""")
def __init__(self):
TestBase.__init__(
self, 'fork', """
# DURATION TID FUNCTION
[ 1661] | main() {
130.930 us [ 1661] | fork();
691.873 us [ 1661] | wait();
[ 1661] | a() {
[ 1661] | b() {
[ 1661] | c() {
4.234 us [ 1661] | getpid();
5.680 us [ 1661] | } /* c */
6.094 us [ 1661] | } /* b */
6.602 us [ 1661] | } /* a */
849.948 us [ 1661] | } /* main */
""")
def __init__(self):
TestBase.__init__(self, 'namespace', lang="C++", result="""
# DURATION TID FUNCTION
53.511 us [ 6624] | ns::ns1::foo::foo();
[ 6624] | ns::ns1::foo::bar2() {
[ 6624] | ns::ns1::foo::bar3() {
1.607 us [ 6624] | malloc();
2.520 us [ 6624] | } /* ns::ns1::foo::bar3 */
2.982 us [ 6624] | } /* ns::ns1::foo::bar2 */
0.174 us [ 6624] | ns::ns2::foo::foo();
[ 6624] | ns::ns2::foo::bar2() {
[ 6624] | ns::ns2::foo::bar3() {
0.365 us [ 6624] | malloc();
0.834 us [ 6624] | } /* ns::ns2::foo::bar3 */
1.200 us [ 6624] | } /* ns::ns2::foo::bar2 */
""", sort='simple')
def __init__(self):
TestBase.__init__(
self, 'diff', """
#
# uftrace diff
# [0] base: xxx (from uftrace record -d xxx -F main tests/t-diff 0 )
# [1] diff: yyy (from uftrace record -d yyy -F main tests/t-diff 1 )
#
Total time Calls Function
============ ========== ====================
+1.296 ms +0 main
+1.292 ms +3 usleep
+1.225 ms +0 foo
+158.450 us +0 bar
-0.066 us +0 atoi
""")
def __init__(self):
TestBase.__init__(self,
'namespace',
lang="C++",
result="""
# DURATION TID FUNCTION
4.843 us [29826] | operator new();
1.846 us [29826] | ns::ns1::foo::foo();
[29826] | ns::ns1::foo::bar() {
[29826] | ns::ns1::foo::bar1() {
[29826] | ns::ns1::foo::bar2() {
[29826] | ns::ns1::foo::bar3() {
0.597 us [29826] | operator new();
0.410 us [29826] | operator delete();
143.705 us [29826] | } /* main */
""")