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;
}