Archive

Posts Tagged ‘trace’

从FTP模块学习先进的诊断技术(Erlang Trace机制)

April 12th, 2010 2 comments

原创文章,转载请注明: 转载自系统技术非业余研究

本文链接地址: 从FTP模块学习先进的诊断技术(Erlang Trace机制)

我们开发好了一个软件的时候,通常是经过严格测试的,才分发给用户使用, 但是即使这样也不能保证用户的环境和我们的相同, 我们的软件还是会失败的. 问题是如何诊断这些问题.
通常的做法是写log,这是个很有效的方式. 但是写log要代码支持,而且会带来负面的性能影响. Erlang提供了强大的Trace机制, 帮助我们解决这个问题. OTP本身有很多模块利用了这个技术手段,我们从ftp模块学习下:

上代码:
lib/inets/src/ftp/ftp.erl

 771    %% Maybe activate dbg                                                                                                                                                                                  
 772    case key_search(debug, Options, disable) of
 773        trace ->
 774            dbg:tracer(),
 775            dbg:p(all, [call]),  %% 我们关心函数调用
 776            dbg:tpl(ftp, [{'_', [], [{return_trace}]}]), %%以及返回值
 777            dbg:tpl(ftp_response, [{'_', [], [{return_trace}]}]),
 778            dbg:tpl(ftp_progress, [{'_', [], [{return_trace}]}]);
 779        debug ->
 780            dbg:tracer(),
 781            dbg:p(all, [call]),
 782            dbg:tp(ftp, [{'_', [], [{return_trace}]}]),
 783            dbg:tp(ftp_response, [{'_', [], [{return_trace}]}]),
 784            dbg:tp(ftp_progress, [{'_', [], [{return_trace}]}]);
 785        _ ->
 786            %% Keep silent                                                                                                                                                                                 
 787            ok
 788    end,

我们可以在启动参数里面加上debug标志, 在需要的时候打开这些诊断功能!

现在我们演示下,代码片段从inets userguide来的, 用户名密码不用试验了, 我不会告诉你的, 呵呵:

root@ubuntu:~# erl
Erlang R14A (erts-5.8) [source] [smp:2:2] [rq:2] [async-threads:0] [kernel-poll:false]

Eshell V5.8  (abort with ^G)
1> inets:start().  
ok
2> {ok,Pid} = inets:start(ftpc, [{host,"ftp.yufeng.info"},{debug,debug}])
2> .
(<0.45.0>) call ftp:handle_call({<0.31.0>,
 {open,ip_comm,
       [{host,"ftp.yufeng.info"},
        {progress,ignore},
        {timeout,60000},
        {ipfamily,inet},
        {port,21},
        {mode,passive}]}},{<0.31.0>,#Ref<0.0.0.45>},{state,undefined,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,undefined,undefined,inet,ignore})
(<0.45.0>) call ftp_progress:start_link(ignore)
(<0.45.0>) returned from ftp_progress:start_link/1 -> ignore
(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.45>},
                                                open,inet,ignore},
                                               59493}
(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,
     <<"220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.45>},
       open,inet,ignore})
(<0.45.0>) call ftp_response:parse_lines(<<"220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n">>,[],start)
(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,
                                                        "220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n",
                                                        <<>>}
(<0.45.0>) call ftp_response:interpret("220---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n")
{ok,<0.45.0>}
(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,
                                                      "---------- Welcome to Pure-FTPd [privsep] [TLS] ----------\r\n220-You are user number 7 of 1000 allowed.\r\n220-Local time is now 02:33. Server port: 21.\r\n220-IPv6 connections are also welcome on this server.\r\n220 You will be disconnected after 15 minutes of inactivity.\r\n"}
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,undefined,undefined,
                                                inet,ignore}}
3> ftp:user(Pid, "username", "password").
(<0.31.0>) call ftp:user(<0.45.0>,"username","password")
(<0.45.0>) call ftp:handle_call({<0.31.0>,{user,"username","password"}},{<0.31.0>,#Ref<0.0.0.64>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,undefined,undefined,inet,ignore})
(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.64>},
                                                {handle_user,"password",[]},
                                                inet,ignore}}
(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,<<"331 User yufengin OK. Password required\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.64>},
       {handle_user,"password",[]},
       inet,ignore})
(<0.45.0>) call ftp_response:parse_lines(<<"331 User yufengin OK. Password required\r\n">>,[],start)
(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,
                                                        "331 User yufengin OK. Password required\r\n",
                                                        <<>>}
(<0.45.0>) call ftp_response:interpret("331 User yufengin OK. Password required\r\n")
(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_interm,
                                                      " User yufengin OK. Password required\r\n"}
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.64>},
                                                {handle_user_passwd,[]},
                                                inet,ignore}}
(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,
     <<"230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.64>},
       {handle_user_passwd,[]},
       inet,ignore})
(<0.45.0>) call ftp_response:parse_lines(<<"230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n">>,[],start)
(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,
                                                        "230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n",
                                                        <<>>}
(<0.45.0>) call ftp_response:interpret("230-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n")
ok
(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,
                                                      "-User yufengin has group access to:  yufengin  \r\n230 OK. Current restricted directory is /\r\n"}
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,undefined,undefined,
                                                inet,ignore}}
(<0.31.0>) returned from ftp:user/3 -> ok
4> 
4>  ftp:pwd(Pid).
(<0.31.0>) call ftp:pwd(<0.45.0>)
(<0.45.0>) call ftp:handle_call({<0.31.0>,pwd},{<0.31.0>,#Ref<0.0.0.84>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,undefined,undefined,inet,ignore})
(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.84>},
                                                pwd,inet,ignore}}
(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,<<"257 \"/\" is your current location\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.84>},
       pwd,inet,ignore})
(<0.45.0>) call ftp_response:parse_lines(<<"257 \"/\" is your current location\r\n">>,[],start)
(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,
                                                        "257 \"/\" is your current location\r\n",
                                                        <<>>}
(<0.45.0>) call ftp_response:interpret("257 \"/\" is your current location\r\n")
{ok,"/"}
(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,
                                                      " \"/\" is your current location\r\n"}
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,undefined,undefined,
                                                inet,ignore}}
(<0.31.0>) returned from ftp:pwd/1 -> {ok,"/"}
7> ftp:recv(Pid, "favicon.ico").
(<0.31.0>) call ftp:recv(<0.45.0>,"favicon.ico")
(<0.45.0>) call ftp:handle_call({<0.31.0>,{recv,"favicon.ico","favicon.ico"}},{<0.31.0>,#Ref<0.0.0.120>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.112>},
       undefined,inet,ignore})
(<0.45.0>) returned from ftp:handle_call/3 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.120>},
                                                {setup_data_connection,
                                                 {recv_file,"favicon.ico",
                                                  {file_descriptor,prim_file,
                                                   {#Port<0.1087>,9}}}},
                                                inet,ignore}}
(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,
     <<"227 Entering Passive Mode (74,220,215,202,156,59)\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,
    passive,60000,<<>>,
    {<<>>,[],start},
    <0.31.0>,
    {<0.31.0>,#Ref<0.0.0.120>},
    {setup_data_connection,
        {recv_file,"favicon.ico",
            {file_descriptor,prim_file,{#Port<0.1087>,9}}}},
    inet,ignore})
(<0.45.0>) call ftp_response:parse_lines(<<"227 Entering Passive Mode (74,220,215,202,156,59)\r\n">>,[],start)
(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,
                                                        "227 Entering Passive Mode (74,220,215,202,156,59)\r\n",
                                                        <<>>}
(<0.45.0>) call ftp_response:interpret("227 Entering Passive Mode (74,220,215,202,156,59)\r\n")
(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,
                                                      " Entering Passive Mode (74,220,215,202,156,59)\r\n"}
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                #Port<0.1093>,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.120>},
                                                {recv_file,
                                                 {file_descriptor,prim_file,
                                                  {#Port<0.1087>,9}}},
                                                inet,ignore}}
(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,<<"150 Accepted data connection\r\n">>},{state,#Port<0.1086>,#Port<0.1093>,false,"/root",ftp_server_default,false,
       passive,60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.120>},
       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},
       inet,ignore})
(<0.45.0>) call ftp_response:parse_lines(<<"150 Accepted data connection\r\n">>,[],start)
(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,
                                                        "150 Accepted data connection\r\n",
                                                        <<>>}
(<0.45.0>) call ftp_response:interpret("150 Accepted data connection\r\n")
(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_prel,
                                                      " Accepted data connection\r\n"}
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                #Port<0.1093>,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.120>},
                                                {recv_file,
                                                 {file_descriptor,prim_file,
                                                  {#Port<0.1087>,9}}},
                                                inet,ignore}}
ok
8> (<0.45.0>) call ftp:handle_info({tcp,#Port<0.1093>,
     <<71,73,70,56,57,97,1,0,1,0,128,0,0,255,255,255,255,255,255,33,249,4,1,7,
       0,1,0,44,0,0,0,0,1,0,1,0,0,2,2,76,1,0,59>>},{state,#Port<0.1086>,#Port<0.1093>,false,"/root",ftp_server_default,false,
       passive,60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.120>},
       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},
       inet,ignore})
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                #Port<0.1093>,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.120>},
                                                {recv_file,
                                                 {file_descriptor,prim_file,
                                                  {#Port<0.1087>,9}}},
                                                inet,ignore}}
(<0.45.0>) call ftp:handle_info({tcp_closed,#Port<0.1093>},{state,#Port<0.1086>,#Port<0.1093>,false,"/root",ftp_server_default,false,
       passive,60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.120>},
       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},
       inet,ignore})
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,
                                                {<0.31.0>,#Ref<0.0.0.120>},
                                                {recv_file,
                                                 {file_descriptor,prim_file,
                                                  {#Port<0.1087>,9}}},
                                                inet,ignore}}
(<0.45.0>) call ftp:handle_info({tcp,#Port<0.1086>,
     <<"226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n">>},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,
       {<0.31.0>,#Ref<0.0.0.120>},
       {recv_file,{file_descriptor,prim_file,{#Port<0.1087>,9}}},
       inet,ignore})
(<0.45.0>) call ftp_response:parse_lines(<<"226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n">>,[],start)
(<0.45.0>) returned from ftp_response:parse_lines/3 -> {ok,
                                                        "226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n",
                                                        <<>>}
(<0.45.0>) call ftp_response:interpret("226-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n")
(<0.45.0>) returned from ftp_response:interpret/1 -> {pos_compl,
                                                      "-File successfully transferred\r\n226 0.020 seconds (measured here), 2.07 Kbytes per second\r\n"}
(<0.45.0>) returned from ftp:handle_info/2 -> {noreply,
                                               {state,#Port<0.1086>,
                                                undefined,false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,undefined,undefined,
                                                inet,ignore}}
(<0.31.0>) returned from ftp:recv/2 -> ok

8> inets:stop(ftpc, Pid).
ok
9> (<0.31.0>) call ftp:stop_service(<0.45.0>)
(<0.31.0>) returned from ftp:stop_service/1 -> ok
(<0.45.0>) call ftp:handle_cast({<0.31.0>,close},{state,#Port<0.1086>,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,undefined,undefined,inet,ignore})
(<0.45.0>) returned from ftp:handle_cast/2 -> {stop,normal,
                                               {state,undefined,undefined,
                                                false,"/root",
                                                ftp_server_default,false,
                                                passive,60000,<<>>,
                                                {<<>>,[],start},
                                                <0.31.0>,undefined,undefined,
                                                inet,ignore}}
(<0.45.0>) call ftp:terminate(normal,{state,undefined,undefined,false,"/root",ftp_server_default,false,passive,
       60000,<<>>,
       {<<>>,[],start},
       <0.31.0>,undefined,undefined,inet,ignore})
(<0.45.0>) returned from ftp:terminate/2 -> ok
9> h().      
1: inets:start()
-> ok
2: {ok,Pid} =
       inets:start(ftpc, [{host,"ftp.yufeng.info"},{debug,debug}])
-> {ok,<0.45.0>}
3: ftp:user(Pid, "username", "password")
-> ok
4: ftp:pwd(Pid)
-> {ok,"/"}
5: ftp:cd(Pid, "public_html")
-> ok
6: ftp:lpwd(Pid)
-> {ok,"/root"}
7: ftp:recv(Pid, "favicon.ico")
-> ok
8: inets:stop(ftpc, Pid)
-> ok

Bingo! 我们非常的清楚了看到了整个系统交互的流程. 不废吹灰之力.

Post Footer automatically generated by wp-posturl plugin for wordpress.

Categories: Erlang探索 Tags: , , , , ,