1%% 2%% %CopyrightBegin% 3%% 4%% Copyright Ericsson AB 2002-2018. All Rights Reserved. 5%% 6%% Licensed under the Apache License, Version 2.0 (the "License"); 7%% you may not use this file except in compliance with the License. 8%% You may obtain a copy of the License at 9%% 10%% http://www.apache.org/licenses/LICENSE-2.0 11%% 12%% Unless required by applicable law or agreed to in writing, software 13%% distributed under the License is distributed on an "AS IS" BASIS, 14%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 15%% See the License for the specific language governing permissions and 16%% limitations under the License. 17%% 18%% %CopyrightEnd% 19%% 20-module(multitrace). 21-author('siri@erix.ericsson.se'). 22 23-export([debug/1,gc/1,schedule/1,stop/0,format/1,format/2]). 24-export([handle_debug/4,handle_gc/4,handle_schedule/4]). 25 26%% 27%% Tool API 28%% 29debug(Func) -> 30 case running() of 31 false -> 32 {ok,_} = ttb:tracer(all, 33 [{file,"debug_trace"}, 34 {handler, {{?MODULE,handle_debug},initial}}]), 35 init(), 36 {ok,_} = ttb:p(all,[timestamp,c]), 37 tp(Func), 38 ok; 39 true -> 40 {error, tracer_already_running} 41 end. 42 43tp([Func|Funcs]) -> 44 tp(Func), 45 tp(Funcs); 46tp([]) -> ok; 47tp({M,F,A}) -> do_tp(M,F,A); 48tp({M,F}) -> do_tp(M,F,'_'); 49tp(M) -> do_tp(M,'_','_'). 50 51do_tp(M,F,A) -> 52 {ok,_}=ttb:tp(M,F,A,[{'_',[],[{message,{caller}},{return_trace}]}]). 53 54gc(Proc) -> 55 case running() of 56 false -> 57 {ok,_} = ttb:tracer(all,[{file,"gc_trace"}, 58 {handler,{{?MODULE,handle_gc},initial}}, 59 {process_info,false}]), 60 init(), 61 {ok,_} = ttb:p(Proc,[timestamp,garbage_collection]), 62 ok; 63 true -> 64 {error, tracer_already_running} 65 end. 66 67schedule(Proc) -> 68 case running() of 69 false -> 70 {ok,_} = ttb:tracer(all, 71 [{file,"schedule_trace"}, 72 {handler,{{?MODULE,handle_schedule},initial}}, 73 {process_info,false}]), 74 init(), 75 {ok,_} = ttb:p(Proc,[timestamp,running]), 76 ok; 77 true -> 78 {error, tracer_already_running} 79 end. 80 81stop() -> 82 ttb:stop(). 83 84format(File) -> 85 ttb:format(File). 86format(File,Out) -> 87 ttb:format(File,[{out,Out}]). 88 89 90%% 91%% Print call trace 92%% 93handle_debug(Out,Trace,TI,initial) -> 94 print_header(Out,TI), 95 handle_debug(Out,Trace,TI,0); 96handle_debug(_Out,end_of_trace,_TI,N) -> 97 N; 98handle_debug(Out,Trace,_TI,N) -> 99 print_func(Out,Trace,N), 100 N+1. 101 102print_func(Out,{trace_ts,P,call,{M,F,A},C,Ts},N) -> 103 io:format(Out, 104 "~w: ~s~n" 105 "Process : ~w~n" 106 "Call : ~w:~tw/~w~n" 107 "Arguments : ~tp~n" 108 "Caller : ~tw~n~n", 109 [N,ts(Ts),P,M,F,length(A),A,C]); 110print_func(Out,{trace_ts,P,return_from,{M,F,A},R,Ts},N) -> 111 io:format(Out, 112 "~w: ~s~n" 113 "Process : ~w~n" 114 "Return from : ~w:~tw/~w~n" 115 "Return value : ~tp~n~n", 116 [N,ts(Ts),P,M,F,A,R]). 117 118 119%% 120%% Print GC trace 121%% 122handle_gc(_Out,end_of_trace,_TI,S) -> 123 S; 124handle_gc(Out,Trace,TI,initial) -> 125 print_header(Out,TI), 126 print_gc_header(Out), 127 handle_gc(Out,Trace,TI,dict:new()); 128handle_gc(_Out,{trace_ts,P,gc_start,Info,Ts},_TI,S) -> 129 dict:store(P,{Info,Ts},S); 130handle_gc(Out,{trace_ts,P,gc_end,Info,Ts},_TI,S) -> 131 case dict:find(P,S) of 132 {ok,{StartInfo,StartTime}} -> 133 {EM,ER,ES,EO,EH,EOB,EB} = sort(Info), 134 {SM,SR,SS,SO,SH,SOB,SB} = sort(StartInfo), 135 io:format(Out, 136 "start\t~w\t~w\t~w\t~w\t~w\t~w\t~w\t~w~n" 137 "end\t~w\t~w\t~w\t~w\t~w\t~w\t~w\t~w~n~n", 138 [SM,SR,SS,SO,SH,SOB,SB,P,EM,ER,ES,EO,EH,EOB,EB,diff(StartTime,Ts)]), 139 dict:erase(P,S); 140 error -> 141 S 142 end. 143 144print_gc_header(Out) -> 145 io:format(Out, 146 "\tMBuf\tRecent\tStack\tOldHeap\tHeap\tOldBL\tBlock\t" 147 "Process/Time(micro sec)~n" 148 "=============================================" 149 "============================================~n",[]). 150 151sort(GC) -> 152 sort(GC,{0,0,0,0,0,'_','_'}). 153sort([{mbuf_size,M}|Rest],{_,R,S,O,H,OB,B}) -> 154 sort(Rest,{M,R,S,O,H,OB,B}); 155sort([{recent_size,R}|Rest],{M,_,S,O,H,OB,B}) -> 156 sort(Rest,{M,R,S,O,H,OB,B}); 157sort([{stack_size,S}|Rest],{M,R,_,O,H,OB,B}) -> 158 sort(Rest,{M,R,S,O,H,OB,B}); 159sort([{old_heap_size,O}|Rest],{M,R,S,_,H,OB,B}) -> 160 sort(Rest,{M,R,S,O,H,OB,B}); 161sort([{heap_size,H}|Rest],{M,R,S,O,_,OB,B}) -> 162 sort(Rest,{M,R,S,O,H,OB,B}); 163sort([{old_heap_block_size,OB}|Rest],{M,R,S,O,H,_,B}) -> 164 sort(Rest,{M,R,S,O,H,OB,B}); 165sort([{heap_block_size,B}|Rest],{M,R,S,O,H,OB,_}) -> 166 sort(Rest,{M,R,S,O,H,OB,B}); 167sort([],GC) -> 168 GC. 169 170 171%% 172%% Print scheduling trace 173%% 174handle_schedule(Out,Trace,TI,initial) -> 175 print_header(Out,TI), 176 handle_schedule(Out,Trace,TI,[]); 177handle_schedule(Out,end_of_trace,_TI,S) -> 178 summary(Out,S); 179handle_schedule(Out,{trace_ts,P,out,Info,Ts},_TI,S) -> 180 io:format(Out, 181 "out:~n" 182 "Process : ~w~n" 183 "Time : ~s~n" 184 "Function : ~tw~n~n",[P,ts(Ts),Info]), 185 case lists:keysearch(P,1,S) of 186 {value,{P,List}} -> 187 lists:keyreplace(P,1,S,{P,[{out,Ts}|List]}); 188 false -> 189 [{P,[{out,Ts}]} | S] 190 end; 191handle_schedule(Out,{trace_ts,P,in,Info,Ts},_TI,S) -> 192 io:format(Out, 193 "in:~n" 194 "Process : ~w~n" 195 "Time : ~s~n" 196 "Function : ~tw~n~n",[P,ts(Ts),Info]), 197 case lists:keysearch(P,1,S) of 198 {value,{P,List}} -> 199 lists:keyreplace(P,1,S,{P,[{in,Ts}|List]}); 200 false -> 201 [{P,[{in,Ts}]} | S] 202 end. 203 204 205summary(Out,[{P,List}|Rest]) -> 206 Sum = proc_summary(List,0), 207 io:format(Out,"Total time 'in' for process ~w: ~w micro seconds~n",[P,Sum]), 208 summary(Out,Rest); 209summary(_Out,[]) -> 210 ok. 211 212proc_summary([{in,_Start}|Rest],Acc) -> 213 proc_summary(Rest,Acc); 214proc_summary([{out,End},{in,Start}|Rest],Acc) -> 215 Diff = diff(Start,End), 216 proc_summary(Rest,Acc+Diff); 217proc_summary([],Acc) -> 218 Acc. 219 220 221%% 222%% Library functions 223%% 224ts({_, _, Micro} = Now) -> 225 {{Y,M,D},{H,Min,S}} = calendar:now_to_local_time(Now), 226 io_lib:format("~4.4.0w-~2.2.0w-~2.2.0w ~2.2.0w:~2.2.0w:~2.2.0w,~6.6.0w", 227 [Y,M,D,H,Min,S,Micro]). 228 229 230diff({SMeg,SS,SMic},{EMeg,ES,EMic}) -> 231 (EMeg-SMeg)*1000000000000 + (ES-SS)*1000000 + (EMic-SMic). 232 233 234init() -> 235 ttb:write_trace_info(start_time,fun() -> now() end). 236 237print_header(Out,TI) -> 238 {value,{node,[Node]}} = lists:keysearch(node,1,TI), 239 {value,{flags,Flags}} = lists:keysearch(flags,1,TI), 240 case lists:keysearch(start_time,1,TI) of 241 {value,{start_time,[ST]}} -> 242 io:format(Out, 243 "~nTracing started on node ~w at ~s~n" 244 "Flags: ~p~n~n~n", 245 [Node,ts(ST),Flags]); 246 false -> % in case this file was not loaded on the traced node 247 io:format(Out, 248 "~nTracing from node ~w~n" 249 "Flags: ~p~n~n~n", 250 [Node,Flags]) 251 end. 252 253running() -> 254 case whereis(ttb) of 255 undefined -> false; 256 _Pid -> true 257 end. 258