Registrations currently disabled due to spam. Contact me externally if you need an account

Skip to content
  • George Joseph's avatar
    Scope Tracing: A new facility for tracing scope enter/exit · ca3c22c5
    George Joseph authored
    What's wrong with ast_debug?
    
      ast_debug is fine for general purpose debug output but it's not
      really geared for scope tracing since it doesn't present its
      output in a way that makes capturing and analyzing flow through
      Asterisk easy.
    
    How is scope tracing better?
    
      Scope tracing uses the same "cleanup" attribute that RAII_VAR
      uses to print messages to a separate "trace" log level.  Even
      better, the messages are indented and unindented based on a
      thread-local call depth counter.  When output to a separate log
      file, the output is uncluttered and easy to follow.
    
      Here's an example of the output. The leading timestamps and
      thread ids are removed and the output cut off at 68 columns for
      commit message restrictions but you get the idea.
    
    --> res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001
    	--> res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173
    		--> res_pjsip_session.c:3669 handle_incoming_response PJSIP/
    			--> chan_pjsip.c:3265 chan_pjsip_incoming_response_after
    				--> chan_pjsip.c:3194 chan_pjsip_incoming_response P
    					    chan_pjsip.c:3245 chan_pjsip_incoming_respon
    				<-- chan_pjsip.c:3194 chan_pjsip_incoming_response P
    			<-- chan_pjsip.c:3265 chan_pjsip_incoming_response_after
    		<-- res_pjsip_session.c:3669 handle_incoming_response PJSIP/
    	<-- res_pjsip_session.c:3661 handle_incoming_response PJSIP/1173
    <-- res_pjsip_session.c:3680 handle_incoming PJSIP/1173-00000001
    
      The messages with the "-->" or "<--" were produced by including
      the following at the top of each function:
    
      SCOPE_TRACE(1, "%s\n", ast_sip_session_get_name(session));
    
      Scope isn't limited to functions any more than RAII_VAR is.  You
      can also see entry and exit from "if", "for", "while", etc blocks.
    
      There is also an ast_trace() macro that doesn't track entry or
      exit but simply outputs a message to the trace log using the
      current indent level.  The deepest message in the sample
      (chan_pjsip.c:3245) was used to indicate which "case" in a
      "select" was executed.
    
    How do you use it?
    
      More documentation is available in logger.h but here's an overview:
    
      * Configure with --enable-dev-mode.  Like debug, scope tracing
        is #ifdef'd out if devmode isn't enabled.
    
      * Add a SCOPE_TRACE() call to the top of your function.
    
      * Set a logger channel in logger.conf to output the "trace" level.
    
      * Use the CLI (or cli.conf) to set a trace level similar to setting
        debug level... CLI> core set trace 2 res_pjsip.so
    
    Summary Of Changes:
    
      * Added LOG_TRACE logger level.  Actually it occupies the slot
        formerly occupied by the now defunct "event" level.
    
      * Added core asterisk option "trace" similar to debug.  Includes
    	ability to specify global trace level in asterisk.conf and CLI
    	commands to turn on/off and set levels.  Levels can be set
    	globally (probably not a good idea), or by module/source file.
    
      * Updated sample asterisk.conf and logger.conf.  Tracing is
        disabled by default in both.
    
      * Added __ast_trace() to logger.c which keeps track of the indent
        level using TLS. It's #ifdef'd out if devmode isn't enabled.
    
      * Added ast_trace() and SCOPE_TRACE() macros to logger.h.
        These are all #ifdef'd out if devmode isn't enabled.
    
    Why not use gcc's -finstrument-functions capability?
    
      gcc's facility doesn't allow access to local data and doesn't
      operate on non-function scopes.
    
    Known Issues:
    
      The only know issue is that we currently don't know the line
      number where the scope exited.  It's reported as the same place
      the scope was entered.  There's probably a way to get around it
      but it might involve looking at the stack and doing an 'addr2line'
      to get the line number.  Kind of like ast_backtrace() does.
      Not sure if it's worth it.
    
    Change-Id: Ic5ebb859883f9c10a08c5630802de33500cad027
    ca3c22c5