From 0541bbab72df88b91d5725ad209aef1a951a4448 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 14 Mar 2013 10:56:09 +0100 Subject: [sasl] Fix tests that compare execution time Tests that compare execution time for release_handler:install_release sometimes fail. This has been corrected by multiplying the time with the CPU utilization in order to disregard wait time for e.g. file access and and non-erlang related load. --- lib/sasl/test/release_handler_SUITE.erl | 60 +++++++++++++++++++++++++++------ 1 file changed, 49 insertions(+), 11 deletions(-) (limited to 'lib/sasl/test') diff --git a/lib/sasl/test/release_handler_SUITE.erl b/lib/sasl/test/release_handler_SUITE.erl index 82b7a738bb..97ba70c9bd 100644 --- a/lib/sasl/test/release_handler_SUITE.erl +++ b/lib/sasl/test/release_handler_SUITE.erl @@ -1,7 +1,7 @@ %% %% %CopyrightBegin% %% -%% Copyright Ericsson AB 2011-2012. All Rights Reserved. +%% Copyright Ericsson AB 2011-2013. 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 @@ -1094,9 +1094,11 @@ otp_9395_update_many_mods(Conf) when is_list(Conf) -> [RelVsn2, filename:join(Rel2Dir, "sys.config")]), %% First, install release directly and check how much time it takes + rpc:call(Node,erlang,system_flag,[scheduler_wall_time,true]), {TInst0,{ok, _, []}} = timer:tc(rpc,call,[Node, release_handler, install_release, [RelVsn2]]), - ct:log("install_release: ~.2f",[TInst0/1000000]), + SWT0 = rpc:call(Node,erlang,statistics,[scheduler_wall_time]), +% ct:log("install_release: ~.2f",[TInst0/1000000]), %% Restore to old release, spawn processes again and load to get old code {_,RelVsn1} = init:script_id(), @@ -1113,15 +1115,32 @@ otp_9395_update_many_mods(Conf) when is_list(Conf) -> {TCheck,{ok, _RelVsn1, []}} = timer:tc(rpc,call,[Node, release_handler, check_install_release, [RelVsn2,[purge]]]), - ct:log("check_install_release with purge: ~.2f",[TCheck/1000000]), +% ct:log("check_install_release with purge: ~.2f",[TCheck/1000000]), %% Finally install release after check and purge, and check that %% this install was faster than the first. + rpc:call(Node,erlang,system_flag,[scheduler_wall_time,false]), + rpc:call(Node,erlang,system_flag,[scheduler_wall_time,true]), {TInst2,{ok, _RelVsn1, []}} = timer:tc(rpc,call,[Node, release_handler, install_release, [RelVsn2]]), - ct:log("install_release: ~.2f",[TInst2/1000000]), - - true = (TInst2 < TInst0), + SWT2 = rpc:call(Node,erlang,statistics,[scheduler_wall_time]), +% ct:log("install_release: ~.2f",[TInst2/1000000]), + + %% Calculate and print real time and CPU utilization + SumFun = fun({_,A,T},{AAcc,TAcc}) -> {A+AAcc,T+TAcc} end, + {SumA0,SumT0} = lists:foldl(SumFun,{0,0},SWT0), + {SumA2,SumT2} = lists:foldl(SumFun,{0,0},SWT2), + TI0=TInst0/1000000, + TI2=TInst2/1000000, + CPU0=SumA0/SumT0, + CPU2=SumA2/SumT2, + X0 = TI0*CPU0, + X2 = TI2*CPU2, + ct:log("First run: T=~.2fsec, CPU=~.2f, T*CPU=~.2f~n" + "Second run: T=~.2fsec, CPU=~.2f, T*CPU=~.2f~n", + [TI0, CPU0, X0, TI2, CPU2, X2]), + + true = (X2 =< X0), % disregarding wait time for file access etc. ok. @@ -1172,9 +1191,11 @@ otp_9395_rm_many_mods(Conf) when is_list(Conf) -> [RelVsn2, filename:join(Rel2Dir, "sys.config")]), %% First, install release directly and check how much time it takes + rpc:call(Node,erlang,system_flag,[scheduler_wall_time,true]), {TInst0,{ok, _, []}} = timer:tc(rpc,call,[Node, release_handler, install_release, [RelVsn2]]), - ct:log("install_release: ~.2f",[TInst0/1000000]), + SWT0 = rpc:call(Node,erlang,statistics,[scheduler_wall_time]), +% ct:log("install_release: ~.2f",[TInst0/1000000]), %% Restore to old release, spawn processes again and load to get old code {_,RelVsn1} = init:script_id(), @@ -1191,15 +1212,32 @@ otp_9395_rm_many_mods(Conf) when is_list(Conf) -> {TCheck,{ok, _RelVsn1, []}} = timer:tc(rpc,call,[Node, release_handler, check_install_release, [RelVsn2,[purge]]]), - ct:log("check_install_release with purge: ~.2f",[TCheck/1000000]), +% ct:log("check_install_release with purge: ~.2f",[TCheck/1000000]), %% Finally install release after check and purge, and check that %% this install was faster than the first. + rpc:call(Node,erlang,system_flag,[scheduler_wall_time,false]), + rpc:call(Node,erlang,system_flag,[scheduler_wall_time,true]), {TInst2,{ok, _RelVsn1, []}} = timer:tc(rpc,call,[Node, release_handler, install_release, [RelVsn2]]), - ct:log("install_release: ~.2f",[TInst2/1000000]), - - true = (TInst2 =< TInst0), + SWT2 = rpc:call(Node,erlang,statistics,[scheduler_wall_time]), +% ct:log("install_release: ~.2f",[TInst2/1000000]), + + %% Calculate and print real time and CPU utilization + SumFun = fun({_,A,T},{AAcc,TAcc}) -> {A+AAcc,T+TAcc} end, + {SumA0,SumT0} = lists:foldl(SumFun,{0,0},SWT0), + {SumA2,SumT2} = lists:foldl(SumFun,{0,0},SWT2), + TI0=TInst0/1000000, + TI2=TInst2/1000000, + CPU0=SumA0/SumT0, + CPU2=SumA2/SumT2, + X0 = TI0*CPU0, + X2 = TI2*CPU2, + ct:log("First run: T=~.2fsec, CPU=~.2f, T*CPU=~.2f~n" + "Second run: T=~.2fsec, CPU=~.2f, T*CPU=~.2f~n", + [TI0, CPU0, X0, TI2, CPU2, X2]), + + true = (X2 =< X0), % disregarding wait time for file access etc. ok. -- cgit v1.2.3