testing through trace analysis

[Ulf Wiger]

On Tue, 12 Oct 1999, Ulf Wiger wrote:

etxuwi>Other uses are:
etxuwi>
etxuwi>1. Performance profiling, where we use trace messages with
etxuwi>'proc', 'gc' and 'timestamp' flags to see how much CPU time
etxuwi>is spent performing a certain task.

I thought I'd share a little invention: The macro SYS_TRACE_WRAP.
It is used as a wrapper around a syntactical expression, in order to get a
feeling for how long a certain block of code takes to execute.

What the macro does is send a message to itself and then remove it. This is
a very cheap operation (normally 10-20 us), and it does show on a
timestamped message trace.

(Never mind the debug:sys_trace() function. It's a debug filter, supposed
to return true | false. You can remove that.)

/Uffe


-ifdef(sys_trace).

%%% ----------------------------------------------------------
%%% #           SYS_TRACE(Msg)
%%% Description: Send trace message.
%%%              This macro sends a sys_trace message to its 
%%%              own process and immediately removes it from
%%%              the message queue. This is a "cheap" way to
%%%              add a trace point in a message trace.
%%% ----------------------------------------------------------
-define(SYS_TRACE(Term),
        case catch debug:sys_trace() of
            true ->
                begin
                    self() ! {sys_trace, Term},
                    receive
                        {sys_trace, _} ->
                            ok
                    end
                end;
           _ ->
               disabled
       end).

%%% ----------------------------------------------------------
%%% #           SYS_TRACE_WRAP(Expr, TraceInfo)
%%% Input:       Expression - simple or grouped with begin...end,
%%%              TraceInfo - any info you want to log to uniquely
%%%              identify the trace.
%%% Description: Introduces trace points before and after
%%%              an expression, such as a function call.
%%%              Before executing Expr, a SYS_TRACE message
%%%              of the form {enter, Module, TraceInfo} is sent,
%%%              and after Expr is executed, 
%%%              {exit, Module, TraceInfo} is sent.
%%%              The strange application of a function object
%%%              is used to avoid a variable binding, which 
%%%              would prevent using the macro twice in one
%%%              function. Expr is evaluated *outside* the 
%%%              fun, so exit messages should read as expected.
%%% ----------------------------------------------------------
-define(SYS_TRACE_WRAP(Expr, TraceInfo),
        case catch debug:sys_trace() of
            true ->
                begin
                    ?SYS_TRACE({begin_trace_wrap, ?MODULE, TraceInfo}),
                    (fun(Res) ->
                             ?SYS_TRACE({end_trace_wrap, ?MODULE,
                                         TraceInfo}),
                             Res
                     end)(Expr)
                end;
            _ -> % No filter Expr must be done
               Expr
       end).

-else.

-define(SYS_TRACE(Term), trace_disabled).
-define(SYS_TRACE_WRAP(Expr, _), Expr).

-endif. % sys_trace defined


Ulf Wiger, Chief Designer AXD 301
Ericsson Telecom AB                          tfn: +46  8 719 81 95
Varuvägen 9, Älvsjö                          mob: +46 70 519 81 95
S-126 25 Stockholm, Sweden                   fax: +46  8 719 43 44