blob: edfa5aa75da20863b448973c8548c4366c88d1a1 (
plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
|
The following are examples of rb_cputime.d.
This script traces the on-CPU time of Ruby functions and prints a report.
Here it traces the example program, Code/Ruby/func_slow.rb
# rb_cputime.d
Tracing... Hit Ctrl-C to end.
^C
Count,
FILE TYPE NAME COUNT
. obj-new NoMemoryError 1
. obj-new SystemStackError 1
. obj-new ThreadGroup 1
. obj-new fatal 1
func_slow.rb func Object::func_a 1
func_slow.rb func Object::func_b 1
func_slow.rb func Object::func_c 1
. obj-new Object 3
func_slow.rb func IO::write 3
func_slow.rb func Module::method_added 3
func_slow.rb func Object::print 3
func_slow.rb func Fixnum::< 600003
func_slow.rb func Fixnum::+ 1200000
- total - 1800015
Elapsed times (us),
FILE TYPE NAME TOTAL
. obj-new SystemStackError 2
. obj-new NoMemoryError 2
. obj-new fatal 11
. obj-new ThreadGroup 12
. obj-new Object 19
Exclusive function on-CPU times (us),
FILE TYPE NAME TOTAL
func_slow.rb func Module::method_added 4
func_slow.rb func Object::print 57
func_slow.rb func IO::write 180
func_slow.rb func Object::func_a 405946
func_slow.rb func Fixnum::< 691125
func_slow.rb func Object::func_b 809970
func_slow.rb func Object::func_c 1225235
func_slow.rb func Fixnum::+ 1285200
- total - 4417721
Inclusive function on-CPU times (us),
FILE TYPE NAME TOTAL
func_slow.rb func Module::method_added 4
func_slow.rb func IO::write 180
func_slow.rb func Object::print 238
func_slow.rb func Fixnum::< 691125
func_slow.rb func Fixnum::+ 1285200
func_slow.rb func Object::func_c 2212572
func_slow.rb func Object::func_b 3683688
func_slow.rb func Object::func_a 4417717
You can see the results are printed in four sections.
The first section reports how many times each subroutine was called, and it's
type.
The second section reports on the on-CPU time of anything that was not of type
"func", in this case the only elements reported here are of type obj-new.
The exclusive function on-CPU times shows, amongst other results, that func_a
spent around 0.4 seconds on-CPU. This time excludes time spent in other
subroutines.
The inclusive function on-CPU times show that func_a spent around 4.4
seconds on-CPU. This includes the time spent in other subroutines called.
These on-CPU times are the time the thread spent running on a CPU, from when
the subroutine began to when it completed. This does not include time
spent off-CPU time such as sleeping for I/O or waiting for scheduling.
On-CPU times are useful for showing who is causing the CPUs to be busy.
See Notes/ALLoncpu_notes.txt for more details. Also see
Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
detailed explanation of exclusive vs inclusive subroutine time.
|
