multitrace.erl

来自「OTP是开放电信平台的简称」· ERL 代码 · 共 256 行

%% ``The contents of this file are subject to the Erlang Public License,
%% Version 1.1, (the "License"); you may not use this file except in
%% compliance with the License. You should have received a copy of the
%% Erlang Public License along with this software. If not, it can be
%% retrieved via the world wide web at http://www.erlang.org/.
%% 
%% Software distributed under the License is distributed on an "AS IS"
%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See
%% the License for the specific language governing rights and limitations
%% under the License.
%% 
%% The Initial Developer of the Original Code is Ericsson Utvecklings AB.
%% Portions created by Ericsson are Copyright 1999, Ericsson Utvecklings
%% AB. All Rights Reserved.''
%% 
%%     $Id$
%%
-module(multitrace).
-author('[e-mail]').

-export([debug/1,gc/1,schedule/1,stop/0,format/1,format/2]).
-export([handle_debug/4,handle_gc/4,handle_schedule/4]).

%%
%% Tool API
%%
debug(Func) ->
    case running() of
	false ->
	    {ok,_} = ttb:tracer(all,
				[{file,"debug_trace"},
				 {handler, {{?MODULE,handle_debug},initial}}]),
	    init(),
	    {ok,_} = ttb:p(all,[timestamp,c]),
	    tp(Func),
	    ok;
	true ->
	    {error, tracer_already_running}
    end.

tp([Func|Funcs]) ->
    tp(Func),
    tp(Funcs);
tp([]) -> ok;
tp({M,F,A}) -> do_tp(M,F,A);
tp({M,F}) -> do_tp(M,F,'_');
tp(M) -> do_tp(M,'_','_').

do_tp(M,F,A) ->
    {ok,_}=ttb:tp(M,F,A,[{'_',[],[{message,{caller}},{return_trace}]}]).

gc(Proc) ->
    case running() of
	false ->
	    {ok,_} = ttb:tracer(all,[{file,"gc_trace"},
				     {handler,{{?MODULE,handle_gc},initial}},
				     {process_info,false}]),
	    init(),
	    {ok,_} = ttb:p(Proc,[timestamp,garbage_collection]),
	    ok;
	true ->
	    {error, tracer_already_running}
    end.

schedule(Proc) ->
    case running() of
	false ->
	    {ok,_} = ttb:tracer(all,
				[{file,"schedule_trace"},
				 {handler,{{?MODULE,handle_schedule},initial}},
				 {process_info,false}]),
	    init(),
	    {ok,_} = ttb:p(Proc,[timestamp,running]),
	    ok;
	true ->
	    {error, tracer_already_running}
    end.
    
stop() ->
    ttb:stop().

format(File) ->
    ttb:format(File).
format(File,Out) ->
    ttb:format(File,[{out,Out}]).


%%
%% Print call trace
%%
handle_debug(Out,Trace,TI,initial) ->
    print_header(Out,TI),
    handle_debug(Out,Trace,TI,0);
handle_debug(_Out,end_of_trace,_TI,N) ->
    N;
handle_debug(Out,Trace,_TI,N) ->
    print_func(Out,Trace,N),
    N+1.

print_func(Out,{trace_ts,P,call,{M,F,A},C,Ts},N) ->
    io:format(Out,
	      "~w: ~s~n"
	      "Process   : ~w~n"
	      "Call      : ~w:~w/~w~n"
	      "Arguments : ~p~n"
	      "Caller    : ~w~n~n",
	      [N,ts(Ts),P,M,F,length(A),A,C]);
print_func(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) ->
    io:format(Out,
	      "~w: ~s~n"
	      "Process      : ~w~n"
	      "Return from  : ~w:~w/~w~n"
	      "Return value : ~p~n~n",
	      [N,ts(Ts),P,M,F,A,R]).


%%
%% Print GC trace
%%
handle_gc(_Out,end_of_trace,_TI,S) ->
    S;
handle_gc(Out,Trace,TI,initial) ->
    print_header(Out,TI),
    print_gc_header(Out),
    handle_gc(Out,Trace,TI,dict:new());
handle_gc(_Out,{trace_ts,P,gc_start,Info,Ts},_TI,S) ->
    dict:store(P,{Info,Ts},S);
handle_gc(Out,{trace_ts,P,gc_end,Info,Ts},_TI,S) ->
    case dict:find(P,S) of
	{ok,{StartInfo,StartTime}} ->
	    {EM,ER,ES,EO,EH,EOB,EB} = sort(Info),
	    {SM,SR,SS,SO,SH,SOB,SB} = sort(StartInfo),
	    io:format(Out,
		      "start\t~w\t~w\t~w\t~w\t~w\t~w\t~w\t~w~n"
		      "end\t~w\t~w\t~w\t~w\t~w\t~w\t~w\t~w~n~n", 
		      [SM,SR,SS,SO,SH,SOB,SB,P,EM,ER,ES,EO,EH,EOB,EB,diff(StartTime,Ts)]),
	    dict:erase(P,S);
	error ->
	    S
    end.

print_gc_header(Out) ->
    io:format(Out,
	      "\tMBuf\tRecent\tStack\tOldHeap\tHeap\tOldBL\tBlock\t"
              "Process/Time(micro sec)~n"
              "============================================="
              "============================================~n",[]).

sort(GC) ->
    sort(GC,{0,0,0,0,0,'_','_'}).
sort([{mbuf_size,M}|Rest],{_,R,S,O,H,OB,B}) ->
    sort(Rest,{M,R,S,O,H,OB,B});
sort([{recent_size,R}|Rest],{M,_,S,O,H,OB,B}) ->
    sort(Rest,{M,R,S,O,H,OB,B});
sort([{stack_size,S}|Rest],{M,R,_,O,H,OB,B}) ->
    sort(Rest,{M,R,S,O,H,OB,B});
sort([{old_heap_size,O}|Rest],{M,R,S,_,H,OB,B}) ->
    sort(Rest,{M,R,S,O,H,OB,B});
sort([{heap_size,H}|Rest],{M,R,S,O,_,OB,B}) ->
    sort(Rest,{M,R,S,O,H,OB,B});
sort([{old_heap_block_size,OB}|Rest],{M,R,S,O,H,_,B}) ->
    sort(Rest,{M,R,S,O,H,OB,B});
sort([{heap_block_size,B}|Rest],{M,R,S,O,H,OB,_}) ->
    sort(Rest,{M,R,S,O,H,OB,B});
sort([],GC) ->
    GC.


%%
%% Print scheduling trace
%%
handle_schedule(Out,Trace,TI,initial) ->
    print_header(Out,TI),
    handle_schedule(Out,Trace,TI,[]);
handle_schedule(Out,end_of_trace,_TI,S) ->
    summary(Out,S);
handle_schedule(Out,{trace_ts,P,out,Info,Ts},_TI,S) ->
    io:format(Out,
	      "out:~n"
	      "Process  : ~w~n"
	      "Time     : ~s~n"
	      "Function : ~w~n~n",[P,ts(Ts),Info]),
    case lists:keysearch(P,1,S) of
	{value,{P,List}} ->
	    lists:keyreplace(P,1,S,{P,[{out,Ts}|List]});
	false ->
	    [{P,[{out,Ts}]} | S]
    end;
handle_schedule(Out,{trace_ts,P,in,Info,Ts},_TI,S) ->
    io:format(Out,
	      "in:~n"
	      "Process  : ~w~n"
	      "Time     : ~s~n"
	      "Function : ~w~n~n",[P,ts(Ts),Info]),
    case lists:keysearch(P,1,S) of
	{value,{P,List}} ->
	    lists:keyreplace(P,1,S,{P,[{in,Ts}|List]});
	false ->
	    [{P,[{in,Ts}]} | S]
    end.


summary(Out,[{P,List}|Rest]) ->
    Sum = proc_summary(List,0),
    io:format(Out,"Total time 'in' for process ~w: ~w micro seconds~n",[P,Sum]),
    summary(Out,Rest);
summary(_Out,[]) ->
    ok.

proc_summary([{in,_Start}|Rest],Acc) ->
    proc_summary(Rest,Acc);
proc_summary([{out,End},{in,Start}|Rest],Acc) ->
    Diff = diff(Start,End),
    proc_summary(Rest,Acc+Diff);
proc_summary([],Acc) ->
    Acc.
    

%%
%% Library functions
%%
ts({_, _, Micro} = Now) ->
    {{Y,M,D},{H,Min,S}} = calendar:now_to_local_time(Now),
    io_lib:format("~4.4.0w-~2.2.0w-~2.2.0w ~2.2.0w:~2.2.0w:~2.2.0w,~6.6.0w",
		  [Y,M,D,H,Min,S,Micro]).


diff({SMeg,SS,SMic},{EMeg,ES,EMic}) ->
    (EMeg-SMeg)*1000000000000 + (ES-SS)*1000000 + (EMic-SMic).


init() ->
    ttb:write_trace_info(start_time,fun() -> now() end).

print_header(Out,TI) ->
    {value,{node,[Node]}} = lists:keysearch(node,1,TI),
    {value,{flags,Flags}} = lists:keysearch(flags,1,TI),
    case lists:keysearch(start_time,1,TI) of
	{value,{start_time,[ST]}} ->
	    io:format(Out,
		      "~nTracing started on node ~w at ~s~n"
		      "Flags: ~p~n~n~n",
		      [Node,ts(ST),Flags]);
	false -> % in case this file was not loaded on the traced node 
	    io:format(Out,
		      "~nTracing from node ~w~n"
		      "Flags: ~p~n~n~n",
		      [Node,Flags])
    end.

running() ->
    case whereis(ttb) of
	undefined -> false;
	_Pid -> true
    end.