From 84adefa331c4159d432d22840663c38f155cd4c1 Mon Sep 17 00:00:00 2001 From: Erlang/OTP Date: Fri, 20 Nov 2009 14:54:40 +0000 Subject: The R13B03 release. --- lib/observer/src/multitrace.erl | 256 ++++++++++++++++++++++++++++++++++++++++ 1 file changed, 256 insertions(+) create mode 100644 lib/observer/src/multitrace.erl (limited to 'lib/observer/src/multitrace.erl') diff --git a/lib/observer/src/multitrace.erl b/lib/observer/src/multitrace.erl new file mode 100644 index 0000000000..144697ce9c --- /dev/null +++ b/lib/observer/src/multitrace.erl @@ -0,0 +1,256 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2002-2009. All Rights Reserved. +%% +%% 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 online 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. +%% +%% %CopyrightEnd% +%% +-module(multitrace). +-author('siri@erix.ericsson.se'). + +-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. -- cgit v1.2.3