systemtap使用调试记录(二)

socket sendbubf探究stp脚本

  • centos7 3.10.0-514.16.1.el7.x86_64

该systap脚本是在调用协议栈sk->sk_sndbuf可能改变的位置增加探测点,探究snd_buf变更规律使用

脚本

socket.stp

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
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
%{
#include <linux/tcp.h>
#include<linux/rtc.h>
#include <net/tcp.h>

static const char tcp_state_array[][16] = {
"NULL",
"ESTABLISHED",
"SYN_SENT",
"SYN_RECV",
"FIN_WAIT1",
"FIN_WAIT2",
"TIME_WAIT",
"CLOSE",
"CLOSE_WAIT",
"LAST_ACK",
"LISTEN",
"CLOSING"
};
%}

function get_short_time:string()
%{
struct timeval tv;
struct rtc_time tm;
unsigned long time;

do_gettimeofday(&tv);
time = tv.tv_sec + 8 * 3600;
rtc_time_to_tm(time, &tm);

sprintf(STAP_RETVALUE, "%02d:%02d:%02d",
tm.tm_hour, tm.tm_min, tm.tm_sec);
%}

function get_full_time:string()
%{
struct timeval tv;
struct rtc_time tm;
unsigned long time;

do_gettimeofday(&tv);
time = tv.tv_sec + 8 * 3600;
rtc_time_to_tm(time, &tm);

sprintf(STAP_RETVALUE, "%d/%d/%d,%02d:%02d:%02d",
tm.tm_year+1900, tm.tm_mon+1, tm.tm_mday,
tm.tm_hour, tm.tm_min, tm.tm_sec);
%}

function get_conn_lifetime:long (sk:long)
%{
struct sock *sk = (struct sock *)STAP_ARG_sk;
struct stap_info *info = sk->sk_protinfo;
STAP_RETVALUE = jiffies_to_msecs(tcp_time_stamp - info->estab_t);
%}

function get_conn_data:long (sk:long)
%{
struct sock *sk = (struct sock *)STAP_ARG_sk;
struct tcp_sock *tp = tcp_sk(sk);
struct stap_info *info = sk->sk_protinfo;
u32 len = tp->snd_nxt - info->isn;

STAP_RETVALUE = len ? len - 1 : len;
%}

function filter_http_transtime:long (sk:long)
%{
struct sock *sk = (struct sock *)STAP_ARG_sk;
struct stap_info *info = sk->sk_protinfo;

STAP_RETVALUE = info->http_filter;
%}

function get_socket_addr:string (sk:long)
{
laddr = tcpmib_local_addr(sk)
lport = tcpmib_local_port(sk)
raddr = tcpmib_remote_addr(sk)
rport = tcpmib_remote_port(sk)

local_addr = sprintf("%s:%d", ip_ntop(htonl(laddr)), lport)
remote_addr = sprintf("%s:%d", ip_ntop(htonl(raddr)), rport)

return sprintf("local=%s,remote=%s", local_addr, remote_addr)
}


function get_socket_state:string (sk:long)
%{
struct sock *sk = (struct sock *)STAP_ARG_sk;
sprintf(STAP_RETVALUE, "%s", tcp_state_array[sk->sk_state]);
%}

function get_socket_sk_sndbuf:string(sk:long)
%{
struct sock *sk=(struct sock*)STAP_ARG_sk;
sprintf(STAP_RETVALUE,"%d:%d", sk->sk_wmem_queued, sk->sk_sndbuf);
%}



function socket_state_num2str:string (state:long)
%{
sprintf(STAP_RETVALUE, "%s", tcp_state_array[STAP_ARG_state]);
%}

function sshfilter:long(sk:long)
{
lport = tcpmib_local_port(sk)
if(lport == 22)
return 1
return 0
}


probe kernel.function("tcp_send_ack").call{
if(sshfilter($sk))
next
printf("tcp_send_ack[%s]%s state:%s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk));
}

probe kernel.function("tcp_sendmsg").call{
if(sshfilter($sk))
next
printf("tcp_sendmsg[%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.function("tcp_sendmsg").return{
if(sshfilter($sk))
next
printf("tcp_sendmsg return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.statement("*@net/core/sock.c:711"){

if(sshfilter($sk))
next
printf("sock:711 return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.statement("*@net/core/sock.c:715"){
if(sshfilter($sk))
next
printf("sock:715 return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.statement("*@net/ipv4/ip_output.c:1581"){
if(sshfilter($sk))
next
printf("ip_output:1581 return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.statement("*@net/ipv4/ip_output.c:1583"){
if(sshfilter($sk))
next
printf("ip_output:1583 return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.statement("*@net/ipv4/tcp_input.c:304"){
if(sshfilter($sk))
next
printf("tcp_input:304 return [%s]%s state:%s,sndbubf %s sndmem : %d permss %d\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk),$sndmem,$per_mss);
print_backtrace()
}

probe kernel.function("__sk_mem_schedule").call{
if(sshfilter($sk))
next
printf("__sk_mem_schedule[%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.function("__sk_mem_schedule").return{
if(sshfilter($sk))
next
printf("__sk_mem_schedule return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}


probe kernel.function("sk_page_frag_refill").call{
if(sshfilter($sk))
next
printf("sk_page_frag_refill[%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.function("sk_page_frag_refill").return{
if(sshfilter($sk))
next
printf("sk_page_frag_refill return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}


probe kernel.function("sk_stream_alloc_skb").call{
if(sshfilter($sk))
next
printf("sk_stream_alloc_skb[%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.function("sk_stream_alloc_skb").return{
if(sshfilter($sk))
next
printf("sk_stream_alloc_skb return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}


probe kernel.function("tcp_v4_connect").call{
if(sshfilter($sk))
next
printf("tcp_v4_connect[%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

probe kernel.function("tcp_v4_connect").return{
if(sshfilter($sk))
next
printf("tcp_v4_connect return [%s]%s state:%s,sndbubf %s\n",get_full_time(),get_socket_addr($sk),get_socket_state($sk),get_socket_sk_sndbuf($sk));
}

执行步骤

stap -g socket.stp

执行结果

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
[root@localhost stp]# stap -g socket.stp
WARNING: Eliding unused function 'filter_http_transtime': identifier 'filter_http_transtime' at socket.stp:68:10
source: function filter_http_transtime:long (sk:long)
^
WARNING: Eliding unused function 'get_conn_data': identifier 'get_conn_data' at :58:10
source: function get_conn_data:long (sk:long)
^
WARNING: Eliding unused function 'get_conn_lifetime': identifier 'get_conn_lifetime' at :51:10
source: function get_conn_lifetime:long (sk:long)
^
WARNING: Eliding unused function 'get_short_time': identifier 'get_short_time' at :22:10
source: function get_short_time:string()
^
WARNING: Eliding unused function 'socket_state_num2str': identifier 'socket_state_num2str' at :104:10
source: function socket_state_num2str:string (state:long)
^
sock:711 return [2017/6/20,14:42:35]local=0.0.0.0:0,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:16384
sock:715 return [2017/6/20,14:42:35]local=0.0.0.0:0,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:32768
tcp_v4_connect[2017/6/20,14:42:35]local=0.0.0.0:3000,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:32768
tcp_v4_connect return [2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:SYN_SENT,sndbubf 1280:32768
tcp_send_ack[2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:ESTABLISHED
tcp_sendmsg[2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:ESTABLISHED,sndbubf 0:32768
sk_stream_alloc_skb[2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:ESTABLISHED,sndbubf 0:32768
sk_stream_alloc_skb return [2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:ESTABLISHED,sndbubf 0:32768
tcp_sendmsg return [2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:ESTABLISHED,sndbubf 2304:32768
tcp_send_ack[2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:ESTABLISHED
tcp_send_ack[2017/6/20,14:42:35]local=192.168.55.178:3000,remote=180.97.33.108:80 state:ESTABLISHED
ip_output:1583 return [2017/6/20,14:42:35]local=0.0.0.0:6,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:212992
ip_output:1581 return [2017/6/20,14:42:35]local=0.0.0.0:6,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:212992
ip_output:1583 return [2017/6/20,14:42:35]local=0.0.0.0:6,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:212992
ip_output:1581 return [2017/6/20,14:42:35]local=0.0.0.0:6,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:212992
ip_output:1583 return [2017/6/20,14:42:35]local=0.0.0.0:6,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:212992
ip_output:1581 return [2017/6/20,14:42:35]local=0.0.0.0:6,remote=0.0.0.0:0 state:CLOSE,sndbubf 0:212992