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
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
|
#! /usr/bin/env stap
// NOTE: a popup mutex is one that is seen in contention but the init
// of it was not detected not sure why there are popups - static mutex
// init?
// stack trace where mutex was initialized, if known
global mutex_init_stack
// stack trace where mutex was first referenced, if init stack not known
global mutex_uninit
// stats about the contention on this mutex
global mutex_contention
// usymdata for this mutex
global mutex_names
// stack trace of last contention for this mutex
global mutex_last_cont_stack
// NOTE: the way 389 works is that many common mutexes are initialized
// in the same place. For example - each connection object has its
// own mutex - there may be thousands of these. They are all
// initialized in the same place - same with entry objects, where
// there may be millions. So, if we want to get aggregate contention
// statistics for _all_ connection objects, not just each individual
// one, we have to keep track of each unique call stack. This is what
// mutex_cont_stack is used for.
// stats about unique stacks
global mutex_cont_stack
// report mutexes that had more than this many contentions
global cont_count_threshold = 1
// usec - report mutexes that had a max time more than this
global cont_max_threshold = 100000
global verbose = 0
global keep_stats = 1
/* ... and a variant of the futexes.stp script: */
global FUTEX_WAIT = 0 /*, FUTEX_WAKE = 1 */
global FUTEX_PRIVATE_FLAG = 128 /* linux 2.6.22+ */
global FUTEX_CLOCK_REALTIME = 256 /* linux 2.6.29+ */
function process_mutex_init(mutex, ppfunc)
{
if (verbose && (mutex in mutex_init_stack)) {
printf("error: %s: mutex %p is already initialized at\n%s\n",
ppfunc, mutex, mutex_init_stack[mutex])
}
if (keep_stats) {
mutex_init_stack[mutex] = sprint_ubacktrace()
mutex_names[mutex] = usymdata (mutex)
}
else {
printf("init %p at\n%s\n", mutex, sprint_ubacktrace())
}
if (verbose) {
printf("%s: mutex %p %s\n", ppfunc, mutex, mutex_names[mutex])
}
}
function show_contention(mutex, stack, type)
{
count = @count(mutex_contention[mutex])
max = @max(mutex_contention[mutex])
if ((count > cont_count_threshold) || (max > cont_max_threshold)) {
printf("=======================================\nmutex %p (%s) contended %d times, %d avg usec, %d max usec, %d total usec, %s at\n%s\n",
mutex, mutex_names[mutex], count, @avg(mutex_contention[mutex]),
max, @sum(mutex_contention[mutex]), type, stack)
if (mutex in mutex_last_cont_stack) {
printf("\nmutex was last contended at\n%s\n",
mutex_last_cont_stack[mutex])
}
}
}
// we use @defined($muex) and @defined($rwlock) here because
// on 64 bit systems, the wildcard search takes us through
// both 64 bit and 32 bit libc (which doesn't have debuginfo),
// this means the probe point resolved from the 32 bit library
// has no context info
probe process("/lib*/libc.so*").function("pthread_mutex_init")
{
if(@defined($mutex))
process_mutex_init($mutex, ppfunc())
}
probe process("/lib*/libpthread.so*").function("__pthread_mutex_init")
{
if(@defined($mutex))
process_mutex_init($mutex, ppfunc())
}
probe process("/lib*/libpthread.so*").function("__pthread_rwlock_init")
{
if(@defined($rwlock))
process_mutex_init($rwlock, ppfunc())
}
global entry_times%, uaddrs%
probe syscall.futex {
if (pid() != target()) next // skip irrelevant processes
if ((op & ~(FUTEX_PRIVATE_FLAG|FUTEX_CLOCK_REALTIME)) != FUTEX_WAIT) next
entry_times[tid()] = gettimeofday_us()
uaddrs[tid()] = futex_uaddr
}
probe syscall.futex.return
{
if (!(tid() in entry_times)) next
entry = entry_times[tid()]
delete entry_times[tid()]
uaddr = uaddrs[tid()]
delete uaddrs[tid()]
elapsed = gettimeofday_us() - entry
if (keep_stats) {
mutex_contention[uaddr] <<< elapsed
stack = sprint_ubacktrace()
mutex_last_cont_stack[uaddr] = stack
mutex_cont_stack[stack] <<< elapsed
if (uaddr in mutex_init_stack) {
if (verbose) {
printf("contention time %d on mutex %p initialized at\n%s\n",
elapsed, uaddr, mutex_init_stack[uaddr])
}
}
else if (uaddr in mutex_uninit) {
if (verbose) {
printf("contention time %d on popup mutex %p at\n%s\n",
elapsed, uaddr, stack)
}
}
else {
if (verbose) {
printf("contention time %d on popup mutex %p at\n%s\n",
elapsed, uaddr, stack)
}
mutex_uninit[uaddr] = stack
mutex_names[uaddr] = usymdata (uaddr)
}
}
else {
printf("contention %p elapsed %d at\n%s\n", uaddr, elapsed,
sprint_ubacktrace())
}
}
probe end
{
if (!keep_stats) {
printf("======== END\n")
next
}
printf("<<<<<<<< aggregate stats\n")
foreach (stack in mutex_cont_stack-) {
count = @count(mutex_cont_stack[stack])
max = @max(mutex_cont_stack[stack])
if ((count > cont_count_threshold) || (max > cont_max_threshold)) {
printf("=======================================\nstack contended %d times, %d avg usec, %d max usec, %d total usec, at\n%s\n",
@count(mutex_cont_stack[stack]), @avg(mutex_cont_stack[stack]),
@max(mutex_cont_stack[stack]), @sum(mutex_cont_stack[stack]),
stack)
}
}
printf(">>>>>>>> aggregate stats\n")
foreach (mutex in mutex_contention-) {
if (mutex in mutex_init_stack) {
stack = mutex_init_stack[mutex]
type = "init"
}
else if (mutex in mutex_uninit) {
stack = mutex_uninit[mutex]
type = "popup"
}
show_contention(mutex, stack, type)
}
}
|
