strace跟踪程序执行时间

strace可以帮助你打印函数执行时间,帮助你查看程序消耗,针对于复杂的工作进程例如nginx或者janus,我暂且没有尝试,但是对复杂程序性能调整作用不大。

遇到复杂程序你可以考虑valgrind –tool=callgrind工具

http://valgrind.org/docs/manual/cl-manual.html#cl-manual.options.separation

服务端程序执行

1
2
3
4
5
6
7
8
9
[root@localhost ~]# ./server
listening...
hello
hello
hello
hello
hello
hello
hello

客户端程序执行

1
[root@localhost ~]# ./client

打印用户程序调用时间

查找进程id

1
2
3
[root@localhost ~]# ps aux|grep server
root 1636 0.0 0.0 4168 344 pts/1 S+ 07:34 0:00 ./server
root 1642 0.0 0.0 112660 972 pts/2 S+ 07:34 0:00 grep --color=auto server

strace跟踪应用程序打印出应用程序调用时间

1
2
[root@localhost ~]# strace -o server.strace -Ttt -p 1636
strace: Process 1636 attached

查看函数结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
[root@localhost ~]# cat server.strace
07:35:29.195639 select(8, [3 4], NULL, NULL, {0, 894993}) = 1 (in [4], left {0, 3979}) <0.891038>
07:35:30.086907 recvfrom(4, "hello", 6, 0, NULL, NULL) = 5 <0.000009>
07:35:30.086970 write(1, "hello\n", 6) = 6 <0.000033>
07:35:30.087027 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000007>
07:35:30.087066 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 <0.000007>
07:35:30.087091 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000006>
07:35:30.087112 nanosleep({1, 0}, 0x7fff50f89b90) = 0 <1.000453>
07:35:31.087646 sendto(4, "hello\0", 6, 0, NULL, 0) = 6 <0.000099>
07:35:31.087817 select(8, [3 4], NULL, NULL, {1, 0}) = 1 (in [4], left {0, 0}) <1.004789>
07:35:32.092709 recvfrom(4, "hello", 6, 0, NULL, NULL) = 5 <0.000015>
07:35:32.092786 write(1, "hello\n", 6) = 6 <0.000050>
07:35:32.092869 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000026>
07:35:32.092924 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 <0.000006>
07:35:32.092948 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000010>
07:35:32.093035 nanosleep({1, 0}, 0x7fff50f89b90) = 0 <1.000253>
07:35:33.093365 sendto(4, "hello\0", 6, 0, NULL, 0) = 6 <0.000062>
07:35:33.093471 select(8, [3 4], NULL, NULL, {1, 0}) = 1 (in [4], left {0, 554}) <0.999464>
07:35:34.092994 recvfrom(4, "hello", 6, 0, NULL, NULL) = 5 <0.000007>
07:35:34.093038 write(1, "hello\n", 6) = 6 <0.000025>
07:35:34.093078 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000005>
07:35:34.093099 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 <0.000004>
07:35:34.093116 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000005>
07:35:34.093132 nanosleep({1, 0}, <detached ...>

结果分析

如上得知07:35:30.087112 nanosleep({1, 0}, 0x7fff50f89b90) = 0 \<1.000453> 耗费了1.000453 s时间

服务端程序

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
[root@localhost ~]# cat server.c
#include <stdio.h>
#include <sys/socket.h>
#include <netinet/in.h>
#include <string.h>

#define BACKLOG 5
#define BUFF_SIZE 6
#define PORT 9999

int fd[BACKLOG];
int con_num;

void ha_ha(void)
{
sleep(1);
}

int main(int argc, char** argv)
{
int sock_fd, new_fd;
struct sockaddr_in server_addr;
struct sockaddr_in client_addr;
socklen_t sin_size;

fd_set fdsr;
struct timeval tv;
char buf[BUFF_SIZE+1];

int ret = 0;
int i = 0;

sock_fd = socket(AF_INET, SOCK_STREAM, 0);

server_addr.sin_family = AF_INET;
server_addr.sin_port = htons(PORT);
server_addr.sin_addr.s_addr = INADDR_ANY;

memset(server_addr.sin_zero, 0, sizeof(server_addr.sin_zero));

bind(sock_fd, (struct sockaddr*)&server_addr, sizeof(server_addr));

listen(sock_fd, BACKLOG);

printf("listening...\n");

while(1)
{
FD_ZERO(&fdsr);
FD_SET(sock_fd, &fdsr);

tv.tv_sec = 1;
tv.tv_usec = 0;

for(i = 0; i < BACKLOG; i++)
{
if(fd[i] != 0)
{
FD_SET(fd[i], &fdsr);
}
}

select(sock_fd+BACKLOG, &fdsr, NULL, NULL, &tv);

if(FD_ISSET(sock_fd, &fdsr))
{
new_fd = accept(sock_fd, (struct sockaddr*)&client_addr, &sin_size);
if(con_num < BACKLOG)
{
fd[con_num++] = new_fd;
}
}

for(i = 0; i < con_num; i++)
{
if(FD_ISSET(fd[i], &fdsr))
{
ret = recv(fd[i], buf, BUFF_SIZE*sizeof(char), 0);
memset(&buf[ret], '\0', 1);
printf("%s\n", buf);
ha_ha();
send(fd[i], buf, BUFF_SIZE, 0);
}
}
}

return 0;

}

客户端程序

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
[root@localhost ~]# cat client.c
#include <stdio.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/socket.h>
#include <netinet/in.h>
#include <string.h>
#include <sys/stat.h>
#include <fcntl.h>


#define DEST_IP "127.0.0.1"
#define DEST_PORT 9999

int main(int argc, char** argv)
{
int sockfd = 0;
int len = 0;
struct sockaddr_in dest_addr;

char* msg = "hello";

sockfd = socket(AF_INET, SOCK_STREAM, 0);

dest_addr.sin_family = AF_INET;
dest_addr.sin_port = htons(DEST_PORT);
dest_addr.sin_addr.s_addr = inet_addr(DEST_IP);


memset(dest_addr.sin_zero, 0, sizeof(dest_addr.sin_zero));

connect(sockfd, (struct sockaddr*)&dest_addr, sizeof(struct sockaddr_in));
len = strlen(msg);
while(1)
{
sleep(2);
send(sockfd, msg, len, 0);
}

return 0;
}