Sunday, February 2, 2014

Dealing with very large trace files

Overview

In RedPrairie, we often have to analyze trace files.  The trace files are generally very helpful because nothing is missed when you trace everything - but that also implies that nothing is skipped.  This means that it is not a surprise to get a trace file that has several million lines.
Most new MOCA Clients have nice trace viewers but they all have a problem with extremely large trace files.  Also the analysis is quite difficult.

Solution.

One solution is to load the trace to the database.  With a proper schema that represents the trace the analysis can become manageable.  Following tables represent a possible schema:
    usr_temp_cmd_trace_analysis
    Column Specification Comments Example
    uc_trace_file String(500) Name of the trace file /blah/trace.log
    uc_cmd String(4000) Command Name USRint/list order lines available for wave planning
    uc_lvl String(100) Command Stack Level in trace 1
    uc_start_ts String(100) Start time stamp from trace 17:15:32,571
    uc_end_ts String(100) End time stamp from trace 17:15:34,059
    uc_elapsed_ms Float Elapsed time of this command execution 1488
    uc_start_line_num Float Starting Line Number in trace file 202
    uc_end_line_num Float Ending Line Number in trace file 121208
    uc_args String(4000) Pipe separated List of arguments and values
    |wh_id=xyz(STRING)
    usr_temp_sql_trace_analysis
    Column Specification Comments Example
    uc_trace_file String(400) Name of trace file /blah/trace.log
    uc_bound_sql String(4000) SQL Statement with bind variables
    select super_usr_flg 
    from les_usr_ath 
    where usr_id = :var0
    uc_unbound_sql String(4000) SQL Statement with bind variables replaced with values
    select super_usr_flg 
    from les_usr_ath 
    where usr_id = 'XXX'
    uc_rows_returned String(100) # rows returned 1
    uc_elapsed String(100) Elapsed Time in seconds 0.002135123
    uc_line_num Float Line Number in trace file 377
    uc_cmd String(4000) Command that called this SQL MCSbase/list users
    uc_lvl String(100) Command Stack Level In Trace 10
    uc_cmd_start_line_num Float Starting Line number of this trace file 352

Loading the trace to these tables

Simple MOCA command can be developed to read the trace file and load these tables.  The latest version of Oracular MOCA Client will include this functionality as well.  Since the trace files can be very large, you should use groovy to read the file - as opposed to using "read file".  Additionally you should commit the data as it is being loaded into these tables.

Typical Analysis

Once data is loaded into these tables analyzing huge trace files becomes quite manageable, for example:
  • Using usr_temp_cmd_trace_analysis, you can pin point which execution of a command took the longest, i.e. highest value of uc_elapsed_ms.
  • usr_temp_sql_trace_analysis.uc_bound_sql has bind variables so it can help in analyzing SQL statements that are executed very frequently.  You can group by this column and sum uc_elapsed and take count(*).  This way it becomes easy to find SQLs that are executed very often.
  • usr_temp_sql_trace_analysis.uc_bound_sql can be explained to see how the statement will be executed by the database.
  • By comparing the total time in usr_temp_sql_trace_analysis and usr_temp_cmd_trace_analysis, we can find out if the performance issue may be external to the database.  For example if usr_temp_cmd_trace_analysis shows 2 minutes but the total time in usr_temp_sql_trace_analysis  is 1 minute, we know that 50% of the overhead is outside the database.
  • If we see that a command is executed very frequently, according to usr_temp_cmd_trace_analysis, some caching techniques may be employed or the commands may be disabled.

We will add some of these features to future versions of Oracular MOCA client.

Conclusion

RedPrairie trace files can quickly reach millions of lines.  For example tracing of wave planning, pick release, allocation, etc. can often create huge trace files.  Analyzing these via typical tools can be very challenging.  By loading the data into a database table, we can pin point the problems very easily.  The script to load the trace into the database can be quite efficient.  I have loaded a 7 million line trace file in around 30 minutes into these two tables.  Once the data is loaded we can easily find the problem areas.

5 comments:

  1. This is a fantastic idea! Can you provide steps on creating the tables and loading the data (using groovy, I assume)?

    ReplyDelete
  2. FYI, Tried this in the latest Oracular MOCA client's "Save to DB" function. It says "function disabled".

    ReplyDelete
    Replies
    1. What was the exact menu option that we used? What is the version?

      Delete
  3. I really appreciate information shared above. It’s of great help. If someone want to learn Online (Virtual) instructor lead live training in RedPrairie, kindly contact us http://www.maxmunus.com/contact
    MaxMunus Offer World Class Virtual Instructor led training on RedPrairie. We have industry expert trainer. We provide Training Material and Software Support. MaxMunus has successfully conducted 100000+ trainings in India, USA, UK, Australlia, Switzerland, Qatar, Saudi Arabia, Bangladesh, Bahrain and UAE etc.
    For Demo Contact us:
    Name : Nitesh Kumar
    Email : nitesh@maxmunus.com
    Skype id: nitesh_maxmunus
    Contact No.-+91-8553912023
    Company Website –http://www.maxmunus.com

    ReplyDelete
  4. How to load trace into the database?

    ReplyDelete