[[profiler]]

== Profiler

*org.jpos.util.Profiler* is a very simple and easy to use user-space Profiler.
It leverages the Logger subsystem to provide accurate information about processing times. 


These are Profiler's public methods: 

[source,java]
----

    public void reset();
    public void checkPoint (String detail);
    public long getElapsed();
    public long getParcial();
  
----

See link:http://www.jpos.org/doc/javadoc/org/jpos/util/Profiler.html[ javadocs ] for details. 

Profiler implements Loggeable, so you can easily add a Profiler Object to a LogEvent 
to produce convenient profiling information. 

.Profiler
====
[source,java]
----

    Profiler prof = new Profiler();
    LogEvent evt = new LogEvent (this, "any-transaction", prof);

    // initialize message
    ISOMsg m = new ISOMsg ();
    m.setMTI ("1200");
    ...
    ...
    prof.checkPoint ("initialization");

    // send message to remote host
    ...
    ...
    ISORequest req = new ISORequest (m);
    mux.queue (req);
    ISOMsg response = req.getResponse (60000);
    prof.checkPoint ("authorization");

    // capture data in local database
    ...
    ...
    prof.checkPoint ("capture");
    ...
    ...
    Logger.log (evt);
  
----

====

[TIP]
====
The "end" checkPoint is automatically computed at output time (that's when
Logger calls its log listeners).

====

The profiler output looks like this:

----
      prepare: org.jpos.jcard.PrepareContext [0.2/0.2]      <1>
      prepare: org.jpos.jcard.CheckVersion [0.1/0.3]        <2>
      prepare: org.jpos.transaction.Open [1.0/1.3]
      prepare: org.jpos.jcard.Switch [0.1/1.5]
      prepare: org.jpos.jcard.NotSupported [0.1/1.7]
      prepare: org.jpos.jcard.PrepareResponse [11.2/13.0]
      prepare: org.jpos.transaction.Close [0.2/13.2]
      prepare: org.jpos.jcard.SendResponse [0.0/13.3]
      prepare: org.jpos.jcard.ProtectDebugInfo [0.1/13.4]
      prepare: org.jpos.transaction.Debug [0.0/13.5]
       commit: org.jpos.transaction.Close [1.8/15.4]
       commit: org.jpos.jcard.SendResponse [2.2/17.6]
       commit: org.jpos.jcard.ProtectDebugInfo [0.3/17.9]
       commit: org.jpos.transaction.Debug [3.9/21.9]        <3>
      end [1.9/23.9]                                        <4>
----

<1> Partial 0.2 milliseconds, total so far, 0.2 milliseconds.
<2> CheckVersion took 0.1 milliseconds, so the total so far is 0.3 milliseconds.
<3> Total so far, 21.9ms.
<4> 1.9ms is the time between the last checkPoint and the log time.

