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