SCN Wiki upgrade to version 6.13 on Tuesday 19.11.2019 - beginning 07:30 am CET

During upgrade process new content will not be transported to new Wiki version

Registration

Dear SAP Community Member,
In order to fully benefit from what the SAP Community has to offer, please register at:
http://scn.sap.com
Thank you,
The SAP Community team.
Skip to end of metadata
Go to start of metadata

Introduction

We often are faced with process flows that take longer than we would expect to run. This workflow may be a simple one such as a logon to the BI Launchpad, or may be a more complex workflow like refreshing a Dashboard that uses multiple web services. In either case, the biggest challenge is identifying where in the workflow is taking the bulk of the time.

 

Even a simple End to End trace can be overwhelming and can consist of 100s of thousands of lines. These traces, when read line by line, are not exactly an interesting read for most but they can be very good at painting a picture of what is going on.

 

This document covers a workflow that I use quite often to parse the End to End traces to see if there are a few functions that I need to look at deeper that take the bulk of the time during a process flow I wish to optimize.

 

I will assume that you are already familiar with running end to end traces and will reference several other links that will go into more details on certain steps discussed in this document.

 

Requirements

To carry out the steps in this document, you will require the following:

  1. Download SAP Client Plugin tool used for End to End tracing to your client machine
  2. Download the GLF Log Viewer to your client machine
  3. You will need to have Excel installed on one of your machines

 

The very first thing we have to do is download and launch the SAP Client Plugin tool that we will use to create the End to End traces. If you have not used this tool before, I highly recommend you review the following articles before proceeding. Links to download the tool can be found in these articles as well as detailed instructions on how to use it. There is also a KBA that shows you where to download the GLF Log Viewer from.

 

KBA 1909467 - Where can I download the GLF Viewer for BI Platform 4.0 and BI Platform 4.1?

KBA 1861180 - Customer instructions and best practice for collecting a BI Platform 4.x end to end trace

SCN Blog Post - How to generate and consume an E2E trace with BI4.x (for non-SolMan landscapes)


 

High-level Overview of steps (for quick reference)

The below steps are truncated for quick reference. The section following this gives very detailed step by step instructions.

 

  1. Complete an End to End trace using the steps identified in:
    • 1861180 - Customer instructions and best practice for collecting a BI Platform 4.x end to end trace
      • Important notes on generating and collecting traces:
        • If at all possible, it is best to stop the SIA and Application Servers before doing an end to end trace. With these stopped, you can clear out the logging directories so that old log files will not clutter the directories.
        • Again, if possible, it is best to stop the SIA and Application Servers before collecting the trace logs as well. This ensures that all log files are completely written to. Some of the servers do not write real-time to the logs and will not contain all entries until a few hours after the traces were completed.
        • Ensure that you collect ALL traces, including the SBOPWebapp* (Application Server) traces and the BusinessTransaction.xml file. It is easiest just to copy and paste all of the logs into the directory where the BusinessTransaction.xml file is created
  2. Once the logs are collected, load them into the GLF Log Viewer application and filter them using the DSRRootContextID value that you pulled from the BusinessTransaction.xml
  3. Once the filtered logs are loaded, you can start analyzing them for performance issues. The easiest way to find the longest running function calls is to carry out the following steps:
    • Filter the logs with the filter: TEXT {Starts with} “END”
    • Use the File/Export (current filtered view) option to save the output to a file (Use CSV format)
    • Open the filtered log in Excel and add a column beside the Text column called "Timing"
    • Use this example formula to parse out the time Spent on each call:
      • =MID($C2,(FIND("SPENT [",$C2) + 7),(FIND("] FROM",$C2)) - (FIND("SPENT [",$C2)) - 7)
    • Sort the cells Z-A using the newly created Timing column.
  4. Once you have identified the longest running function calls, you can start deep dive analysis on the logs.


 

Detailed Walk-through of a sample (For newbies)

 

Considerations before starting

  • If you have the option to stop the SIA(s) and Application Server(s) before doing these traces, I highly recommend you do so and clear out the existing logs before doing this workflow. It gives us a nice clean set of logs after the traces
  • You will also want to make sure that you modify the bo_trace.ini file to ensure that keep_num and append settings are changed. This ensures that the logs are not truncated or appended when process IDs change due to restarts or crashes (More details in KBAs above)

 

Scenario: Viewing a Webi Report that takes longer than expected to run

The following walk through is just a sample workflow that I did on my test image. The document used is a simple Web Intelligence document that is based off of a small BEx query. This query uses an optional variable off of a Country Hierarchy to pull back some data. I've hard-coded the variable values to many countries and set the document to refresh on open. This document takes 50-60 seconds to open in total.

 

Generating the End to End (E2E) traces - My Way

  1. Download and extract the SAP Client Plugin tool using the instructions in the above mentioned KBA
  2. Launch the plugin-starter-gui.exe from the extraction directory 
    •  
  3. Ensure all Internet Explorers are closed before moving on to the next step.
  4. From the SAP Client Plugin, Launch Internet Explorer.
  5. Once Internet Explorer (IE) loads, name your Business Transaction Name and Step Name accordingly. Do not click the Start Transaction button until just before the workflow you wish to capture. The key to collecting a useful End to End trace is to only capture the workflows you are interested in.
  6. Since my workflow was just viewing a Webi report, I named my transaction ViewWebiReport and my step was called ViewRefreshOnOpen as that explains what I am doing (Viewing a report that has Refresh on Open turned on)
  7. I navigate to the folder where my report is located before pressing the Start Transaction button. Once I am ready to view the report, I click the Start Transaction button and then complete my action. In this case, I right-click and click on View for my report.
  8. I can tell my trace is working as expected if the dialog box shows "Recording..." at the top and I see that Requests and Responses are going up.
  9. As my workflow continues, I can see the numbers increase for Sent/Received Bytes, Requests and Responses. In the background, I can see that my report is refreshing.
  10. Once my workflow is completed, in this case that was when my report returned after about 45 seconds, we click the Stop Transaction button. For environments that do not have Solution Manager configured, you will see a message saying "Please upload BusinessTransaction.xml manually!" Just click ok.
  11. The next thing to do is find the directory that was created during the trace. It will be under the directory you ran the SAP Client Plugin from in a \log\ directory. It will use today's date, time and transaction name so it should be easy to find. Open that directory.
  12. Inside this directory, you will see a file called "BusinessTransaction.xml".
  13. This file contains a unique ID listed as "BusinessTransaction id=" that we will use later on to filter out just our workflow from the E2E trace. Open it in Internet Explorer to easily see this. NOTE: It's not easy to copy and paste that ID from Internet Explorer so you might want to open the file in notepad or another text editor to copy that "id=" line.
  14. We then need to start collecting the .glf log files that were created during our trace. The ones that are most often overlooked when collecting E2E trace logs are the SBOPWebapp*\Webapp*.glf log files. These are created by the components of BI that are deployed to your application server and are key to getting the whole picture. In my case, I needed to collect the BIlaunchpad logs from my C:\SBOPWebapp_BIlaunchpad*\ directory
    • NOTE: It is best to stop your SIA and Application Server before collecting the traces after an End to End trace. Some of the Java components tend to delay-write to the log files so if you collect the files right away without stopping the App Server and SIA, there is a slight chance that you will not get the entire trace workflow in the logs. Another option is to just wait a few hours before collecting the logs. This will generally allow for the processes to complete their writing to disk.
  15. I find it best to just copy and paste all of the log files you collect into the same directory as the BusinessTransaction.xml file. Once we have collected all the traces, we can just zip up that directory and it will contain all the pieces of the puzzle that we need.
  16. The next place to grab logs from would be the default /logging/ folder under the install directory. Copy all the *.glf log files from that directory and Paste them into the BusinessTransaction.xml directory as well.
  17. In multi-node deployments, you will have to do this on each of the servers that are a part of the BI Deployment. In most enterprise deployments, there are 2 or more servers utilized so ensure that you collect the traces from all servers. Don't worry, the log viewer along with the ID from the E2E trace will help us join the workflows later on.
  18. Once all the logs are collected, zip them up. These will be handy for your own internal analysis as well as for Support if you end up opening a message for this issue.

 

That's it for generating and collecting the traces. The next step will be finding where the bulk of our time is spent.

 

Filtering the traces using GLF Log Viewer

Once you have all of the log files collected, you can begin loading them into the GLF log viewer. To do so, you will need the unique ID that is found in the BusinessTransaction.xml file that we created with the E2E trace tool (SAP Client Plug-in).

 

  1. Open the BusinessTransaction.xml file and get the ID that follows the "BusinessTransaction id=" in the xml.
  2. Open GLF Log Viewer and go to File/Open.
  3. Select ALL of the GLF logs collected and click the "Filter and only read matching entries" option on the Open Files dialog. Choose DSRRootContextID for the Column, == for the operator and paste the BusinessTransaction ID into the text box. Image below for reference.
  4. Click Ok and you will see a status bar that shows as the GLF Viewer loads and filters the logs. This process will filter out any entries that do not have our transaction ID in them and will greatly reduce the amount of entries we have to look at.
  5. Optional: The next thing I like to do is click the View/Indent Text According to Scope option. This shows us a bit of a tree view of the function calls and will give you an idea of which functions are nested within other functions. Below is a screenshot of what the indentation looks like.
    • At this point, I could go into all sorts of detail on how to read this trace but for the purpose of this document, I want to first show you how to find the most relevant sections of the log to look at for performance evaluation.
  6. For each "CALL" that is made, we have a START INCOMING / OUTGOING CALL entry and an END INCOMING / OUTGOING CALL entry. These give us a high level overview of the function calls made between servers and services. The END calls are particularly interesting to us as they have a SPENT section that tell us how long that function took from start to end. This is very helpful for performance analysis.
  7. We can filter the logs so that they only show us these END entries which can tell us which functions may be the longest running ones within our workflow. To do this, we need to filter our logs using the following filter: Text starts with [Case sensitive] END. Picture below for reference.
  8. This will give us a log output of just the END calls which should all contain a SPENT [##.###] section.
  9. This filtered set of logs can still be thousands of lines long and unfortunately there is no way to sort them by this SPENT value in the current version. So, we need to export this to CSV to get simple text file we can parse externally. To do this, go to File/Export current (filtered) view. Choose Comma-Separated Values or Excel (*.csv) from the drop down and Save the file to your location of choice.
  10. Once we have the file saved off, we can open it in Excel to help us parse and sort it.
  11. The initial view in Excel should look something like the image below. Note that the columns may be in a different order on your view. The export order is dictated by the GLF viewer order so you can always rearrange the columns in the GLF viewer before exporting to help get a better order of columns. I usually use Time, Text, ProcessID, ThreadID, ActionID as my first few columns as these are the columns I use the most in my analysis.
  12. Next, we have to add a column in front of the Text column. We will add a formula to this new column that will parse out the value between the SPENT [] brackets. The formula I use is in the steps to follow.
  13. In my case, I added a column before the "Text" column and named it "TIMINGS". I then pasted the below formula into the $B2 row. Note that it uses the $C2 value in many places. The formula basically searches the Text string for the "SPENT [" section and the "] FROM" section and parses out the value in-between.
    • FORMULA: =MID($C2,(FIND("SPENT [",$C2) + 7),(FIND("] FROM",$C2)) - (FIND("SPENT [",$C2)) - 7)
  14. Once we test the formula once, we can copy and paste it to all the other rows in our new column. Excel is usually smart enough to adjust the $C2 portion of the formula to be the relative $C# row. You results should look something like this
  15. Once we have the timing information in it's own column, we can start sorting it to try and locate the longest running calls. To do this, Select ALL the cells and use the Sort option.
  16. Once the values are sorted, we should be able to see the longest running calls quite easily. I usually sort Z to A so the largest numbers come to the top of the list. You may see a Sort Warning message like the one below. I choose the option "Sort anything that looks like a number, as a number"
  17. The end result should look something like the one below. In my case, I can see that the bulk of the time was spent on the ProcessDPCommandsEx function call (45 seconds) and another 5 seconds was spent on the getSessionInfosEx call. This gives me my high-level starting point to do a detailed log analysis. Since we did an End to End trace, the logs should have everything I need to get to the root cause of why these two functions took as long as they did. The log review may show me areas that we can improve the performance on or may just explain why the calls take as long as they do but in either case, we will be able to explain why things are taking as long as they are.

 

Conclusion

The focus of this article was to find the long(er) running functions within an End to End trace. Once you know the longer running functions, you will have to dive into the details of the logs to try and determine why the calls take as long as they do.

Remember, traces are geared towards support and developers so don't feel you need to understand or analyze them yourself. It is perfectly fine to collect the traces and attach them to a support incident for assistance in reviewing them.

 

 

 


  • No labels