ssh: ssh_benchmark_SUITE re-organized

1 files changed, 151 insertions, 100 deletions

diff --git a/lib/ssh/test/ssh_benchmark_SUITE.erl b/lib/ssh/test/ssh_benchmark_SUITE.erl
index 0d7239c5b5..fe22aa9f20 100644
--- a/lib/ssh/test/ssh_benchmark_SUITE.erl
+++ b/lib/ssh/test/ssh_benchmark_SUITE.erl
@@ -24,7 +24,10 @@
 -include_lib("common_test/include/ct.hrl").
 
 -include_lib("ssh/src/ssh.hrl").
+-include_lib("ssh/src/ssh_transport.hrl").
 -include_lib("ssh/src/ssh_connect.hrl").
+-include_lib("ssh/src/ssh_userauth.hrl").
+
 
 suite() -> [{ct_hooks,[{ts_install_cth,[{nodenames,2}]}]}].
 %%suite() -> [{ct_hooks,[ts_install_cth]}].
@@ -115,14 +118,14 @@ openssh_client_shell(Config) ->
 			     Parent ! {self(),os:cmd(Cmd)}
 		     end),
     receive
-	{SlavePid, ClientResponse} ->
-%%	    ct:pal("ClientResponse = ~p",[ClientResponse]),
+	{SlavePid, _ClientResponse} ->
+%%	    ct:pal("ClientResponse = ~p",[_ClientResponse]),
 	    {ok, List} = get_trace_list(TracerPid),
 	    Times = find_times(List),
-	    Algs = proplists:get_value(algorithms, List, #alg{}),
-	    ct:pal("List = ~p~n~nAlgorithms = ~p~n~nTimes = ~p",[List,Algs,Times]),
+	    Algs = find_algs(List),
+	    ct:pal("Algorithms = ~p~n~nTimes = ~p",[Algs,Times]),
 	    lists:foreach(
-	      fun({Tag0,MicroSeconds,Unit}) ->
+	      fun({Tag0,Value,Unit}) ->
 		      Tag = case Tag0 of
 				{A,B} -> lists:concat([A," ",B]);
 				_ when is_list(Tag0) -> lists:concat(Tag0);
@@ -130,7 +133,7 @@ openssh_client_shell(Config) ->
 			    end,
 		      DataName = 
 			  ["Erl server ",Tag,sp(algo(Tag,Algs))," [",Unit,"]"],
-		      EventData = [{value, MicroSeconds},
+		      EventData = [{value, Value},
 				   {suite, ?MODULE}, 
 				   {name, lists:concat(DataName)}
 				  ],
@@ -155,56 +158,109 @@ sp(A) -> lists:concat([" ",A]).
     
 %%%================================================================
 find_times(L) ->
-    [{accept_to_hello, find_time([tcp_accept,
-				  {send,hello}],  L, [])/1000,
-      millisec},
-     {kex,             find_time([{send,hello},
-				  {send,ssh_msg_newkeys}], L, []),
-      microsec},
-     {kex_to_auth,     find_time([{send,ssh_msg_newkeys},
-				  {recv,ssh_msg_userauth_request}], L, []),
-      microsec},
-     {auth,            find_time([{recv,ssh_msg_userauth_request},
-				  {send,ssh_msg_userauth_success}], L, []),
-      microsec},
-     {to_prompt,       find_time([tcp_accept,
-				  {recv,{ssh_msg_channel_request,"env"}}], L, []),
-      microsec}
-
-     | alg_times([encrypt,decrypt], L)
-    ].
-
-
-find_time([Event|Events], [{Event,T}|TraceList], Ts) ->
-    %% Important that the first one found is used!
-    find_time(Events, TraceList, [T|Ts]);
-find_time([], _, [T1,T0]) ->
-    now2micro_sec(now_diff(T1,T0));
-find_time(Events, [_|TraceList], Ts) ->
-    find_time(Events, TraceList, Ts);
-find_time(_, [], _Ts) ->
-    throw({error,not_found}).
-
+    Xs =  [accept_to_hello, kex, kex_to_auth, auth, to_prompt],
+    [find_time(X,L) || X <- Xs]	++
+	crypto_algs_times_sizes([encrypt,decrypt], L).
+
+-record(call, {
+	  mfa,
+	  pid,
+	  t_call,
+	  t_return,
+	  args,
+	  result
+	 }).
 
+%%%----------------
+-define(send(M), fun(C=#call{mfa = {ssh_message,encode,1},
+			     args = [M]}) ->
+			 C#call.t_return
+		 end).
+
+-define(recv(M), fun(C=#call{mfa = {ssh_message,decode,1},
+			     result = M}) ->
+			    C#call.t_call
+		 end).
+
+find_time(accept_to_hello, L) ->
+    [T0,T1] = find([fun(C=#call{mfa = {ssh_acceptor,handle_connection,5}}) ->
+			    C#call.t_call
+		    end,
+		    fun(C=#call{mfa = {ssh_connection_handler,hello,_},
+				args = [socket_control|_]}) ->
+			    C#call.t_return
+		    end
+		   ], L, []),
+    {accept_to_hello, now2micro_sec(now_diff(T1,T0)), microsec};
+find_time(kex, L) ->
+    [T0,T1] = find([fun(C=#call{mfa = {ssh_connection_handler,hello,_},
+				args = [socket_control|_]}) ->
+			    C#call.t_call
+		    end,
+		    ?send(#ssh_msg_newkeys{})
+		    ], L, []),
+    {kex, now2micro_sec(now_diff(T1,T0)), microsec};
+find_time(kex_to_auth, L) ->
+    [T0,T1] = find([?send(#ssh_msg_newkeys{}),
+		    ?recv(#ssh_msg_userauth_request{})
+		   ], L, []),
+    {kex_to_auth, now2micro_sec(now_diff(T1,T0)), microsec};
+find_time(auth, L) ->
+    [T0,T1] = find([?recv(#ssh_msg_userauth_request{}),
+		    ?send(#ssh_msg_userauth_success{})
+		   ], L, []),
+    {auth, now2micro_sec(now_diff(T1,T0)), microsec};
+find_time(to_prompt, L) ->
+    [T0,T1] = find([fun(C=#call{mfa = {ssh_acceptor,handle_connection,5}}) ->
+			    C#call.t_call
+		    end,
+		    ?recv(#ssh_msg_channel_request{request_type="env"})
+		   ], L, []),
+    {to_prompt, now2micro_sec(now_diff(T1,T0)), microsec}.
+
+
+find([F|Fs], [C|Cs], Acc) when is_function(F,1) ->
+    try
+	F(C)
+    of
+	T -> find(Fs, Cs, [T|Acc])
+    catch
+	_:_ -> find([F|Fs], Cs, Acc)
+    end;
+find([], _, Acc) ->
+    lists:reverse(Acc).
 
-alg_times(Ops, L) ->
-    OpAlgs = lists:usort([{Op,Alg} || Op <- Ops,
-				      {{{Op,Alg},_,_},_} <- L]),
-    [begin
-	 {[Op,"(",Alg,")"],
-	  sum_times(OpAlg, L, 0, 0),
-	  "microsec/kbyte"
-	 }
-     end || {Op,Alg} = OpAlg <- OpAlgs].
 
+find_algs(L) ->
+    {value,#call{result={ok,Algs}}} =
+	lists:keysearch({ssh_transport,select_algorithm,3}, #call.mfa, L),
+    Algs.
 
-sum_times(T, [{{T,start,Id={_,Nbytes}},TS0}|Events], SumBytes, SumMicroSec) ->
-    TS1 = proplists:get_value({T,stop,Id}, Events),
-    sum_times(T, Events, SumBytes+Nbytes, SumMicroSec+now2micro_sec(now_diff(TS1,TS0)));
-sum_times(T, [_|Events], SumBytes, SumMicroSec) ->
-    sum_times(T, Events, SumBytes, SumMicroSec);
-sum_times(T, [], SumBytes, SumMicroSec) ->
-    round(1024*SumMicroSec / SumBytes). % Microseconds per 1k bytes.
+%%%----------------
+crypto_algs_times_sizes(EncDecs, L) ->
+    Raw = [{_Algorithm = case EncDec of
+			     encrypt -> [encrypt," ",S#ssh.encrypt];
+			     decrypt -> [decrypt," ",S#ssh.decrypt]
+			 end, 
+	    size(Data),
+	    now2micro_sec(now_diff(T1, T0))
+	   }
+	   || EncDec <- EncDecs,
+	      #call{mfa = {ssh_transport,ED,2},
+		    args = [S,Data],
+		    t_call = T0,
+		    t_return = T1} <- L,
+	      ED == EncDec
+	  ],
+    [{Alg, round(1024*Time/Size), "microsec/kbyte"}  % Microseconds per 1k bytes.
+     || {Alg,Size,Time} <- lists:foldl(fun increment/2, [], Raw)].
+
+increment({Alg,Sz,T}, [{Alg,SumSz,SumT}|Acc]) ->
+    [{Alg,SumSz+Sz,SumT+T} | Acc];
+increment(Spec, [X|Acc]) ->
+    [X | increment(Spec,Acc)]; % Not so many Alg, 2 or 3
+increment({Alg,Sz,T},[]) ->
+    [{Alg,Sz,T}].
 
 %%%----------------------------------------------------------------
 %%%
@@ -213,26 +269,28 @@ sum_times(T, [], SumBytes, SumMicroSec) ->
 get_trace_list(TracerPid) ->
     TracerPid ! {get_trace_list,self()},
     receive
-	{trace_list,L} -> {ok,lists:reverse(L)}
+	{trace_list,L} -> {ok, pair_events(lists:reverse(L))}
     after 5000 -> {error,no_reply}
     end.
 
 erlang_trace() ->
     TracerPid = spawn(fun trace_loop/0),
     0 = erlang:trace(new, true, [call,timestamp,{tracer,TracerPid}]),
-    [init_trace(MFA, TP)
-     || {MFA,TP} <- [{{ssh_acceptor,handle_connection,5},  []},
-		     {{ssh_connection_handler,hello,2},    []},
-		     {{ssh_message,encode,1},              []},
-		     {{ssh_message,decode,1},              [{['_'],         [], [{return_trace}]}]},
-		     {{ssh_transport,select_algorithm,3},  [{['_','_','_'], [], [{return_trace}]}]},
-		     {{ssh_transport,encrypt,2},           [{['_','_'],     [], [{return_trace}]}]},
-		     {{ssh_transport,decrypt,2},           [{['_','_'],     [], [{return_trace}]}]}
-		    ]],
+    [init_trace(MFA, tp(MFA))
+     || MFA <- [{ssh_acceptor,handle_connection,5},
+		{ssh_connection_handler,hello,2},
+		{ssh_message,encode,1},
+		{ssh_message,decode,1},
+		{ssh_transport,select_algorithm,3},
+		{ssh_transport,encrypt,2},
+		{ssh_transport,decrypt,2}
+	       ]],
     {ok, TracerPid}.
 
+tp({_M,_F,Arity}) ->
+    [{lists:duplicate(Arity,'_'), [], [{return_trace}]}].
 
-%%%----------------
+%%%----------------------------------------------------------------
 init_trace(MFA = {Module,_,_}, TP) ->
     case code:is_loaded(Module) of
 	false -> code:load_file(Module);
@@ -246,50 +304,43 @@ trace_loop() ->
 
 trace_loop(L) ->
     receive
-	{trace_ts, Pid, call, {M,F,Args}, TS} = Ev -> 
-	    cond_pal(Ev),
-	    trace_loop(save_event(call, Pid, {M,F,Args}, TS, L));
-	{trace_ts, Pid, return_from, {M,F,Arity}, Ret, TS} = Ev -> 
-	    cond_pal(Ev),
-	    trace_loop(save_event(return_from, Pid, {M,F,Arity,Ret}, TS, L));
 	{get_trace_list, From} ->
 	    From ! {trace_list, L},
-	    trace_loop(L)
-
-	; Other -> io:format('~p got ~p~n',[self(),Other]), trace_loop(L)
+	    trace_loop(L);
+	Ev ->
+	    trace_loop([Ev|L])
     end.
-	    
-%%cond_pal(Ev) -> ct:pal("~p",[Ev]).
-cond_pal(Ev) -> ok.
-    
-
-save_event(_Type, _Pid, MFA, TimeStamp, L) ->
-    try	
-	event_name(MFA)
-    of
-	{Tag, 'TS'} -> [{Tag,TimeStamp} | L];
-	Val -> [Val | L]
-    catch
-	_:_ -> L
-    end.
-
-event_name({ssh_acceptor,handle_connection,_}) ->                      {tcp_accept, 'TS'};
-event_name({ssh_connection_handler,hello,[socket_control|_]}) ->       {{send,hello}, 'TS'};
-event_name({ssh_connection_handler,hello,[{version_exchange,_}|_]}) -> {{recv,hello}, 'TS'};
-event_name({ssh_message,encode,[Msg]}) ->                              {{send,element(1,Msg)}, 'TS'};
-event_name({ssh_message,decode,1,
-	    #ssh_msg_channel_request{request_type=ReqType}}) ->  {{recv,{ssh_msg_channel_request,ReqType}}, 'TS'};
-event_name({ssh_message,decode,1,Return}) ->                     {{recv,element(1,Return)}, 'TS'};
-event_name({ssh_transport,select_algorithm,3,{ok,Algs}}) ->      {algorithms,Algs};
-event_name({ssh_transport,encrypt,[S,Data]}) ->   {{{encrypt,S#ssh.encrypt},start, {S#ssh.send_sequence,size(Data)}}, 'TS'};
-event_name({ssh_transport,encrypt,2,{S,Ret}}) ->  {{{encrypt,S#ssh.encrypt},stop,  {S#ssh.send_sequence,size(Ret) }}, 'TS'};
-event_name({ssh_transport,decrypt,[S,Data]}) ->   {{{decrypt,S#ssh.decrypt},start, {S#ssh.recv_sequence,size(Data)}}, 'TS'};
-event_name({ssh_transport,decrypt,2,{S,Ret}}) ->  {{{decrypt,S#ssh.decrypt},stop,  {S#ssh.recv_sequence,size(Ret) }}, 'TS'}.
 
+pair_events(L) ->
+    pair_events(L, []).
+
+pair_events([{trace_ts,Pid,call,{M,F,Args},TS0} | L], Acc) ->
+    Arity = length(Args),
+    {ReturnValue,TS1} = find_return(Pid, {M,F,Arity}, L),
+    pair_events(L, [#call{mfa = {M,F,Arity},
+			  pid = Pid,
+			  t_call = TS0,
+			  t_return = TS1,
+			  args = Args,
+			  result = ReturnValue} | Acc]);
+pair_events([_|L], Acc) ->
+    pair_events(L, Acc);
+pair_events([], Acc) ->
+    lists:reverse(Acc).
+
+
+find_return(Pid, MFA, 
+	    [{trace_ts, Pid, return_from, MFA, ReturnValue, TS}|_]) ->
+    {ReturnValue, TS};
+find_return(Pid, MFA, [_|L]) ->
+    find_return(Pid, MFA, L);
+find_return(_, _, []) ->
+    {undefined, undefined}.
 
+%%%----------------------------------------------------------------
 now2sec({A,B,C}) -> A*1000000 + B + C/1000000.
 
 now2micro_sec({A,B,C}) -> (A*1000000 + B)*1000000 + C.
 		    
 now_diff({A1,B1,C1}, {A0,B0,C0}) -> {A1-A0, B1-B0, C1-C0}.
-    
+