Lab: High Response Times

1. List the pods for the example application deployment; for example:

   oc get pods
   

   Example output:

   NAME                          READY   STATUS    RESTARTS   AGE
   libertydiag-b98748954-mgj64   1/1     Running   0          97s
   

2. Open a shell into the pod by replacing $POD with a pod name from the previous command:

   oc rsh -t $POD
   

   For example:

   oc rsh -t libertydiag-b98748954-mgj64
   

3. Copy and paste the following command and press Enter. Liberty will dynamically update the requestTiming configuration in the server (assuming the feature is installed, which it usually is).

echo '<?xml version="1.0" encoding="UTF-8"?><server><featureManager><feature>requestTiming-1.0</feature></featureManager><requestTiming slowRequestThreshold="9s" hungRequestThreshold="300s" sampleRate="1" /></server>' > /config/configDropins/overrides/requestTiming.xml

1. In the Topology view of the Developer perspective, click on the libertydiag circle, then click the Resources tab in the drawer on the right, and then click on the one pod that's running:
   
2. Click on the Terminal tab to open a remote shell into the running container in the pod:
   
3. Copy and paste the following command and press Enter. Liberty will dynamically update the requestTiming configuration in the server (assuming the feature is installed, which it usually is).

echo '<?xml version="1.0" encoding="UTF-8"?><server><featureManager><feature>requestTiming-1.0</feature></featureManager><requestTiming slowRequestThreshold="9s" hungRequestThreshold="300s" sampleRate="1" /></server>' > /config/configDropins/overrides/requestTiming.xml

1. Request the following web page from your terminal to exercise long requests:

   1. macOS, Linux, or Windows with Cygwin:

      curl -k -s "https://$(oc get route libertydiag "--output=jsonpath={.spec.host}")/servlet/LoadRunner?url=http%3A%2F%2Flocalhost%3A9080%2Fservlet%2FSleep%3Fmean%3D5000%26stddev%3D4000&method=get&entity=&concurrentusers=5&totalrequests=100&user=&password="
      

   2. Windows with Command Prompt:

      1. Ensure you have curl for Windows installed

      2. List the application's URL:

         oc get route libertydiag "--output=jsonpath={.spec.host}{'\n'}"
         

      3. Execute the following command, replacing $HOST with the output of the previous command:

         curl -k -s "https://$HOST/servlet/LoadRunner?url=http%3A%2F%2Flocalhost%3A9080%2Fservlet%2FSleep%3Fmean%3D5000%26stddev%3D4000&method=get&entity=&concurrentusers=5&totalrequests=100&user=&password="
         

2. Request the following web page from your terminal to check on the status of the run:

   1. macOS, Linux, or Windows with Cygwin:

      curl -k -s "https://$(oc get route libertydiag "--output=jsonpath={.spec.host}")/loadrunner.jsp" | grep 'li>Run'
      

   2. Windows with Command Prompt:

      1. Ensure you have curl for Windows installed

      2. List the application's URL:

         oc get route libertydiag "--output=jsonpath={.spec.host}{'\n'}"
         

      3. Execute the following command, replacing $HOST with the output of the previous command:

         curl -k -s "https://$HOST/loadrunner.jsp" | findstr 'li>Run'
         

3. Keep executing the above command until you see that the max execution value exceeds 9000. This means at least one request took more than 9 seconds. (In the statistically rare chance that this doesn't happen, start again at step 1).

1. Click on the Load Runner link from the libertydiag application homepage:
   

2. In the Target URL, copy and paste the following:

   http://localhost:9080/servlet/Sleep?mean=5000&stddev=4000
   

3. Scroll to the bottom and click Start

4. You may refresh this page to check on the status of the run. Note that refreshing does not start a new run.
   
5. Keep refreshing until you see that the max execution value exceeds 9000. This means at least one request took more than 9 seconds. (In the statistically rare chance that this doesn't happen, Start the load again.)

1. List the pods for the example application deployment; for example:

   oc get pods
   

   Example output:

   NAME                          READY   STATUS    RESTARTS   AGE
   libertydiag-b98748954-mgj64   1/1     Running   0          97s
   

2. Open a shell into the pod by replacing $POD with a pod name from the previous command:

   oc rsh -t $POD
   

   For example:

   oc rsh -t libertydiag-b98748954-mgj64
   

3. Copy and paste the following command and press Enter:

   cat /logs/messages.log
   

4. Scroll up until you find the TRAS0112W warning message signifying that an HTTP request exceeded the requestTiming configured threshold. For example:

   [11/1/22 20:02:12:053 UTC] 00000074 com.ibm.ws.request.timing.manager.SlowRequestManager         W TRAS0112W: Request AAPj5+4YXW3_AAAAAAAAAB5 has been running on thread 00000071 for at least 9000.263ms. The following stack trace shows what this thread is currently running.
   
         at java.lang.Thread.sleepImpl(Native Method)
         at java.lang.Thread.sleep(Thread.java:977)
         at java.lang.Thread.sleep(Thread.java:960)
         at com.example.servlet.Sleep.doSleep(Sleep.java:79)
         at com.example.servlet.Sleep.doWork(Sleep.java:40)
         at com.example.util.BaseServlet.service(BaseServlet.java:104)
         at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:587)
         [...]
   
   The following table shows the events that have run during this request.
   
   Duration     Operation
   9001.583ms + websphere.servlet.service | libertydiag | com.example.servlet.Sleep?mean=5000&stddev=4000
   

5. The warning message notes how long the request had been running at the time of the warning (9000.263ms) followed by a stack trace of what the thread was doing. The stack trace is the main symptom that suggests where the slow-down may be. In this example, the application (com.example[...]) is calling Thread.sleep which is causing the delay. Below the stack trace, Liberty prints a table showing any events leading up to the time the threshold was exceeded. In this case, the only event is the HTTP request itself which shows the servlet and its parameters. If the application performed other work such as database queries, these would be shown along with their SQLs.

1. Open the Terminal for the application pod in the OpenShift web console as you did in Step 2 above.

2. Copy and paste the following command and press Enter:

   cat /logs/messages.log
   

3. Scroll up until you find the TRAS0112W warning message signifying that an HTTP request exceeded the requestTiming configured threshold. For example:

   [11/1/22 20:02:12:053 UTC] 00000074 com.ibm.ws.request.timing.manager.SlowRequestManager         W TRAS0112W: Request AAPj5+4YXW3_AAAAAAAAAB5 has been running on thread 00000071 for at least 9000.263ms. The following stack trace shows what this thread is currently running.
   
         at java.lang.Thread.sleepImpl(Native Method)
         at java.lang.Thread.sleep(Thread.java:977)
         at java.lang.Thread.sleep(Thread.java:960)
         at com.example.servlet.Sleep.doSleep(Sleep.java:79)
         at com.example.servlet.Sleep.doWork(Sleep.java:40)
         at com.example.util.BaseServlet.service(BaseServlet.java:104)
         at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:587)
         [...]
   
   The following table shows the events that have run during this request.
   
   Duration     Operation
   9001.583ms + websphere.servlet.service | libertydiag | com.example.servlet.Sleep?mean=5000&stddev=4000
   

4. The warning message notes how long the request had been running at the time of the warning (9000.263ms) followed by a stack trace of what the thread was doing. The stack trace is the main symptom that suggests where the slow-down may be. In this example, the application (com.example[...]) is calling Thread.sleep which is causing the delay. Below the stack trace, Liberty prints a table showing any events leading up to the time the threshold was exceeded. In this case, the only event is the HTTP request itself which shows the servlet and its parameters. If the application performed other work such as database queries, these would be shown along with their SQLs.

1. List the pods for the example application deployment; for example:

   oc get pods
   

   Example output:

   NAME                          READY   STATUS    RESTARTS   AGE
   libertydiag-ddf5f95b6-wj6dm   1/1     Running   0          97s
   

2. Download the Liberty messages.log by replacing $POD with a pod name from the previous command

   oc cp $POD:/logs/messages.log messages.log
   

   For example:

   oc cp libertydiag-ddf5f95b6-wj6dm:/logs/messages.log messages.log
   

Files other than native logs (equivalent to Liberty's console.log) cannot be downloaded through the browser. You must use the command line steps above. Alternatively, you may use the Terminal tab of the pod and cat the file in the browser.

1. Request the following web page from your terminal to exercise long requests:

   1. macOS, Linux, or Windows with Cygwin:

      curl -k -s "https://$(oc get route libertydiag "--output=jsonpath={.spec.host}")/servlet/LoadRunner?url=http%3A%2F%2Flocalhost%3A9080%2Fservlet%2FSleep%3Fmean%3D5000%26stddev%3D4000&method=get&entity=&concurrentusers=5&totalrequests=100&user=&password="
      

   2. Windows with Command Prompt:

      1. Ensure you have curl for Windows installed

      2. List the application's URL:

         oc get route libertydiag "--output=jsonpath={.spec.host}{'\n'}"
         

      3. Execute the following command, replacing $HOST with the output of the previous command:

         curl -k -s "https://$HOST/servlet/LoadRunner?url=http%3A%2F%2Flocalhost%3A9080%2Fservlet%2FSleep%3Fmean%3D5000%26stddev%3D4000&method=get&entity=&concurrentusers=5&totalrequests=100&user=&password="
         

2. Request the following web page from your terminal to check on the status of the run:

   1. macOS, Linux, or Windows with Cygwin:

      curl -k -s "https://$(oc get route libertydiag "--output=jsonpath={.spec.host}")/loadrunner.jsp" | grep 'li>Run'
      

   2. Windows with Command Prompt:

      1. Ensure you have curl for Windows installed

      2. List the application's URL:

         oc get route libertydiag "--output=jsonpath={.spec.host}{'\n'}"
         

      3. Execute the following command, replacing $HOST with the output of the previous command:

         curl -k -s "https://$HOST/loadrunner.jsp" | findstr 'li>Run'
         

1. Click on the Load Runner link from the libertydiag application homepage:
   

2. In the Target URL, copy and paste the following:

   http://localhost:9080/servlet/Sleep?mean=5000&stddev=25000
   

3. Scroll to the bottom and click Start

1. List the pods for the example application deployment; for example:

   oc get pods
   

   Example output:

   NAME                          READY   STATUS    RESTARTS   AGE
   libertydiag-b98748954-mgj64   1/1     Running   0          97s
   

2. Create a dump.yaml file, replacing $POD with the name of the pod from the previous command (e.g. libertydiag-b98748954-mgj64):

   apiVersion: liberty.websphere.ibm.com/v1
   kind: WebSphereLibertyDump
   metadata:
     name: libertydump1
     annotations:
       day2operation.openliberty.io/targetKinds: Pod
   spec:
     license:
       accept: true
     podName: $POD
     include:
       - thread
   

3. Apply the YAML:

   oc apply -f dump.yaml
   

1. Ensure the perspective is set to Developer in the top left:
   
2. Set your current namespace/project to what you were provided. For example:
   
3. In the Topology view of the Developer perspective, click on the libertydiag circle, then click the Resources tab in the drawer on the right, and then copy the name of the pod that's running:
   
4. Click Operator Backed on the +Add page:
   
5. Click WebSphereLibertyDump and then click Create
6. Expand License and check accept
7. Paste the pod name from the step above into the podName text box.
8. Expand include and since we only want a thread dump, click Remove include for the second, Value=heap section
9. Click Create

1. Use the wait command to wait for the dump to complete:

   oc wait wldump libertydump1 --for condition=completed --timeout=5m
   

   Example output:

   webspherelibertydump.liberty.websphere.ibm.com/libertydump1 condition met
   

2. List WebSphereLibertyDump custom resources to get the final dump path:

   oc get wldump
   

   Example output:

   NAME           STARTED   COMPLETED   DUMP FILE
   libertydump1   True      True        /serviceability/user15-namespace/libertydiag-b98748954-mgj64/2023-01-23_18:30:56.zip
   

1. Click on Search, click the Resources drop down, search for dump, check WebSphereLibertyDump, click on the resource name created earlier, and wait until there is a Completed=True line in the Conditions section at the bottom:
   
2. Click on the YAML tab and scroll down to find the dumpFile location:
   

1. List the pods for the example application deployment; for example:

   oc get pods
   

   Example output:

   NAME                          READY   STATUS    RESTARTS   AGE
   libertydiag-ddf5f95b6-wj6dm   1/1     Running   0          97s
   

2. Download the dump by replacing $POD with a pod name from above and $DUMP with the dump path from the previous step.

   oc cp $POD:$DUMP dump.zip
   

   For example:

   oc cp libertydiag-ddf5f95b6-wj6dm:/serviceability/user15-namespace/libertydiag-ddf5f95b6-wj6dm/2023-01-23_18:30:56.zip dump.zip
   

3. Expand the zip file and you should find lots of diagnostics including a javacore*.txt file in the root of the zip which will show thread stacks at the time of the dump. This should include simulated high response time threads; for example:

   3XMTHREADINFO      "Default Executor-thread-1421" J9VMThread:0x00000000002BA800, omrthread_t:0x00007F8000006D50, java/lang/Thread:0x00000000FF943260, state:CW, prio=5
   3XMJAVALTHREAD            (java/lang/Thread getId:0x5D2, isDaemon:true)
   3XMJAVALTHRCCL            com/ibm/ws/classloading/internal/ThreadContextClassLoader(0x00000000E2169578)
   3XMTHREADINFO1            (native thread ID:0x71C, native priority:0x5, native policy:UNKNOWN, vmstate:CW, vm thread flags:0x00000481)
   3XMTHREADINFO2            (native stack address range from:0x00007F80424C1000, to:0x00007F8042501000, size:0x40000)
   3XMCPUTIME               CPU usage total: 0.015525339 secs, current category="Application"
   3XMHEAPALLOC             Heap bytes allocated since last GC cycle=0 (0x0)
   3XMTHREADINFO3           Java callstack:
   4XESTACKTRACE                at java/lang/Thread.sleepImpl(Native Method)
   4XESTACKTRACE                at java/lang/Thread.sleep(Thread.java:977)
   4XESTACKTRACE                at java/lang/Thread.sleep(Thread.java:960)
   4XESTACKTRACE                at com/example/servlet/Sleep.doSleep(Sleep.java:79) [...]
   

Files other than native logs (equivalent to Liberty's console.log) cannot be downloaded through the browser. You must use the command line steps above.

1. Delete the WebSphereLibertyDump custom resource:

   oc delete wldump libertydump1
   

1. Click on Search, click the Resources drop down, search for dump, check WebSphereLibertyDump, click the vertical ellipses next to the custom resource created earlier, click Delete WebSphereLibertyDump, and click Delete.

1. Check if you have authority for all verbs on all resources:

   oc auth can-i '*' '*'
   

   Example output:

   yes
   

2. If the answer is no, then you do not have cluster-admin permissions.

1. Access your OpenShift web console at https://console-openshift-console.$CLUSTER/. Replace $CLUSTER with your OpenShift cluster domain.
2. Ensure the perspective is set to Administrator in the top left:
   
3. Expand User Management. If you don't see a Users option, then you do not have cluster-admin permissions. If you do see it, click on it, and then click on your user name:
   
4. Click on RoleBindings and check if any binding has a Role ref of cluster-admin. If there are none, then you do not have cluster-admin permissions.
   

1. Request the following web page from your terminal to exercise long requests:

   1. macOS, Linux, or Windows with Cygwin:

      curl -k -s "https://$(oc get route libertydiag "--output=jsonpath={.spec.host}")/servlet/LoadRunner?url=http%3A%2F%2Flocalhost%3A9080%2Fservlet%2FSleep%3Fmean%3D5000%26stddev%3D25000&method=get&entity=&concurrentusers=5&totalrequests=100&user=&password="
      

   2. Windows with Command Prompt:

      1. Ensure you have curl for Windows installed

      2. List the application's URL:

         oc get route libertydiag "--output=jsonpath={.spec.host}{'\n'}"
         

      3. Execute the following command, replacing $HOST with the output of the previous command:

         curl -k -s "https://$HOST/servlet/LoadRunner?url=http%3A%2F%2Flocalhost%3A9080%2Fservlet%2FSleep%3Fmean%3D5000%26stddev%3D25000&method=get&entity=&concurrentusers=5&totalrequests=100&user=&password="
         

2. Request the following web page from your terminal to check on the status of the run:

   1. macOS, Linux, or Windows with Cygwin:

      curl -k -s "https://$(oc get route libertydiag "--output=jsonpath={.spec.host}")/loadrunner.jsp" | grep 'li>Run'
      

   2. Windows with Command Prompt:

      1. Ensure you have curl for Windows installed

      2. List the application's URL:

         oc get route libertydiag "--output=jsonpath={.spec.host}{'\n'}"
         

      3. Execute the following command, replacing $HOST with the output of the previous command:

         curl -k -s "https://$HOST/loadrunner.jsp" | findstr 'li>Run'
         

1. Click on the Load Runner link from the libertydiag application homepage:
   

2. In the Target URL, copy and paste the following:

   http://localhost:9080/servlet/Sleep?mean=5000&stddev=25000
   

3. Scroll to the bottom and click Start

1. Download a helper script:
   1. macOS or Linux: containerdiag.sh
   2. Windows: containerdiag.bat
2. Open a Terminal or Command Prompt and change directory to where you downloaded the script

3. On macOS or Linux, make the script executable:

   chmod +x containerdiag.sh
   

4. On macOS, remove the download quarantine:

   xattr -d com.apple.quarantine containerdiag.sh
   

5. List the current deployments:

   oc get deployments
   

   Example output:

   NAME          READY   UP-TO-DATE   AVAILABLE   AGE
   libertydiag   1/1     1            1           13m
   

6. Execute the MustGather. Normally, the -c option specifying the directory of the javacores is not needed; however, this sample application overrides the default javacore directory using -Xdump. This is common in container deployments so that a directory may be used that's mounted on a permanent disk so that diagnostics are still available if a pod is killed.

   1. macOS or Linux:

      ./containerdiag.sh -d libertydiag libertyperf.sh -c "/opt/ibm/wlp/output/defaultServer/logs/diagnostics/javacore*"
      

   2. Windows:

      containerdiag.bat -d libertydiag libertyperf.sh -c "/opt/ibm/wlp/output/defaultServer/logs/diagnostics/javacore*"
      

7. When the MustGather is complete, you will see a repeating message of the form:

   run.sh: Files are ready for download. Download with the following command in another window:
   
     oc cp [...]
   

8. Open another Terminal or Command Prompt and copy & paste the oc cp line that you saw in the previous step. For example (your command will be different):

   $ oc cp worker4-debug:/tmp/containerdiag.SN9RbwVmfC.tar.gz containerdiag.SN9RbwVmfC.tar.gz --namespace=openshift-debug-node-g8dqbdfx5d
   tar: Removing leading `/' from member names
   

9. Go back to the previous Terminal or Command Prompt, type ok, and press Enter to complete the MustGather:

   After the download is complete, type OK and press ENTER: ok
   [2022-11-08 19:01:03.670923238 UTC] run.sh: Processing finished. Deleting /tmp/containerdiag.SN9RbwVmfC.tar.gz
   [2022-11-08 19:01:03.674236286 UTC] run.sh: finished.
   

10. Expand the containerdiag.*.tar.gz file that you downloaded.

The MustGather cannot be executed from the browser. You must use the command line steps above.

1. Go to https://www.ibm.com/support/pages/ibm-thread-and-monitor-dump-analyzer-java-tmda
2. Download the JAR file
3. Double click to launch TMDA
4. Click File } Open Thread Dumps
5. Go to where you expanded containerdiag.*.tar.gz in the previous step } pods } libertydiag } containers } libertydiag } Multi-select all javacore.txt files and click Open
6. Multi-select all the thread dumps and click the Compare Threads button
   
7. Expand the left pane of threads. The default sort is by average stack depth for a thread which tends to correlate with activity. Each row is a thread and each column is a thread dump.
   

8. Click on a cell to show a thread stack on the right. Explore the various stacks and look for patterns. You should notice two distinct patterns:

   1. Stacks in Thread.sleepImpl. These are the simulated long-running requests.

      at java/lang/Thread.sleepImpl(Native Method)
      at java/lang/Thread.sleep(Thread.java:977)
      at java/lang/Thread.sleep(Thread.java:960)
      at com/example/servlet/Sleep.doSleep(Sleep.java:79) [...]
      

   2. Stacks in SocketInputStream.socketRead0. These are the load runner users.

      at java/net/SocketInputStream.socketRead0(Native Method)
      [...]
      at com/example/loadrunner/SimulatedUser.call(SimulatedUser.java:113) [...]
      

9. With a sufficient number of thread dumps and a persistent pattern of stack tops, this may be used to hypothesize likely causes of slow HTTP requests.