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
|
#!/usr/bin/stap
/*
* Copyright (c) 2011, 2013 Oracle and/or its affiliates. All rights reserved.
*
* lockstimesid.d - Display lock wait times grouped by fileid.
*
* Graphs the time spent in DB lock waits
*
* The result times in nanoseconds/cycles? are grouped by
* (fileid, pgno, lock_mode)
*
* Markers used:
* lock__suspend(struct __db_dbt *, db_lockmode_t lock_ mode)
* lock__resume(struct __db_dbt *, db_lockmode_t lock_ mode)
*/
global lockcount, locktimes, maxcount, modes, suspend, top;
function getns()
{
t = gettimeofday_ns();
/*
* On some virtual machine monitors gettimeofday_ns() returns 0. When
* that happens approximate it as if this has a 2 Ghz processor.
*/
if (t == 0)
t = get_cycles() / 2;
return (t);
}
function fileidstr:string(fileid)
{
return sprintf("%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x",
user_char(fileid + 0) & 0xff,
user_char(fileid + 1) & 0xff,
user_char(fileid + 2) & 0xff,
user_char(fileid + 3) & 0xff,
user_char(fileid + 4) & 0xff,
user_char(fileid + 5) & 0xff,
user_char(fileid + 6) & 0xff,
user_char(fileid + 7) & 0xff,
user_char(fileid + 8) & 0xff,
user_char(fileid + 9) & 0xff,
user_char(fileid + 10) & 0xff,
user_char(fileid + 11) & 0xff,
user_char(fileid + 12) & 0xff,
user_char(fileid + 13) & 0xff,
user_char(fileid + 14) & 0xff,
user_char(fileid + 15) & 0xff,
user_char(fileid + 16) & 0xff,
user_char(fileid + 17) & 0xff,
user_char(fileid + 18) & 0xff,
user_char(fileid + 19) & 0xff)
}
probe begin
{
maxcount = 0;
lockcount = 0;
%( $# >= 2 %? maxcount = $2; %)
top = 0;
topdesc = "";
%( $# >= 3 %? top = $3; topdesc = sprintf("top %d ", top) %)
printf("Tracing %sDB lock wait times grouped by ", topdesc);
printf("(binary fileid, pgno, lock_mode)\n^C to display summary\n");
modes[0] = "NOTGRANTED";
modes[1] = "READ";
modes[2] = "WRITE";
modes[3] = "WAIT";
modes[4] = "INTENT_WRITE";
modes[5] = "INTENT_READ";
modes[6] = "INTENT_WR";
modes[7] = "READ_UNCOMMITTED";
modes[8] = "WAS_WRITE";
}
probe process(@1).mark("lock__suspend")
{
/* printf("%s\n", pp()); */
suspend[tid()] = getns();
}
/* lock__resume(DBT *lockobj, db_lockmode_t lock_mode) */
probe process(@1).mark("lock__resume")
{
start = suspend[tid()];
if (start != 0) {
ilock = @cast($arg1, "DBT", "<db.h>")->data;
idstr = fileidstr(@cast(ilock, "DB_LOCK_ILOCK", "<db.h>")->fileid);
duration = getns() - start;
locktimes[idstr,
@cast(ilock, "DB_LOCK_ILOCK", "<db.h>")->pgno, $arg2] <<< duration;
suspend[tid()] = 0;
/* Stop if we've reached the request sample size. */
if (maxcount != 0 && ++lockcount >= maxcount)
exit();
}
}
function printstats(fileid, pgno, lock_mode)
{
printf("Wait time for fileid %s %s pgno %u; %d waits totalling %d\n",
fileid, modes[lock_mode], pgno,
@count(locktimes[fileid, pgno, lock_mode]),
@sum(locktimes[fileid, pgno, lock_mode]));
print(@hist_log(locktimes[fileid, pgno, lock_mode]))
}
probe end
{
/*
* Order results by lock wait count if top <n> results were requested,
* otherwise order by fileid.
*/
if (top != 0)
foreach ([fileid, pgno, lock_mode] in locktimes- limit top)
printstats(fileid, pgno, lock_mode)
else
foreach ([fileid+, pgno, lock_mode] in locktimes)
printstats(fileid, pgno, lock_mode)
}
|
