Igor Kromin |   Consultant. Coder. Blogger. Tinkerer. Gamer.

While diagnosing an issue with high CPU usage on WebLogic I had to work out which threads were at fault. This was a relatively straight forward exercise but required a couple of tools and a bit of decimal to hexadecimal conversion. The server had 2-cores and WebLogic seemed to be using 100% of CPU time on one of the cores at all times.

In JVisualVM that looked something like this...
wlshighcpu4.png


Since JVisualVM takes the number of cores into account, the JVM was hovering around the 50% of the overall CPU time for the machine. Using the top command gave a different picture of the same issue. In top, the java process was being reported to use around the 100% of CPU time (which it was on that core)...

The PID of the process was what I needed to get out of top and in this case it was 29329.
 top
$ top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29329 oracle 20 0 10.3g 5.5g 34m S 98.4 70.3 6:14.49 java
...


Just having the PID for the JVM was not enough though. Pressing the shift-h key combination in top switched to thread display mode which revealed more about what was consuming all of that CPU. In my case I had 3 threads taking up considerable amount of CPU time...
 top
shift-h
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29523 oracle 20 0 10.3g 5.7g 34m S 56.6 72.6 0:01.71 java
29430 oracle 20 0 10.3g 5.7g 34m R 49.3 72.6 2:02.40 java
29356 oracle 20 0 10.3g 5.7g 34m R 49.0 72.6 2:16.29 java
...


Even though there were 3 threads, looking closely at these results showed that the thread with the PID of 29523 had only used 1.71s of CPU time so was not likely the culprit. The other two were both on over 2mins of CPU time (the server was not up for that long) so were likely the culprits here.

Now I had enough information about the JVM and the threads it was time to use jstack to get a thread dump. This required the JVM PID to be passed in and I sent the output to a temporary file like so...
 jstack
$ jstack 29329 > /tmp/jstack.txt


Now it was time to do some decimal to hexadecimal conversion. Since the stack trace lists thread IDs in hex and top reported them in decimal, I used this site to convert the two thread PIDs I was interested into hex. In my case the results were like this...
 Binary to Hex
29430 -> 0x72f6
29356 -> 0x72ac




Now it was a matter of looking through the thread dump file and finding the threads using their IDs (by looking for nid=<PID> in the dump). I got two stack traces from that...
 jstack.txt - 0x72f6
"[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=10 tid=0x00007fd420017000 nid=0x72f6 in Object.wait() [0x00007fd411b9b000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:503)
at weblogic.common.CompletionRequest.getResult(CompletionRequest.java:109)
- locked <0x00000006c646e170> (a weblogic.common.CompletionRequest)
at weblogic.diagnostics.archive.wlstore.PersistentStoreDataArchive.readRecord(PersistentStoreDataArchive.java:695)
- locked <0x000000060c948708> (a weblogic.diagnostics.archive.wlstore.HarvestedPersistentStoreDataArchive)
at weblogic.diagnostics.archive.wlstore.PersistentStoreDataArchive.readRecord(PersistentStoreDataArchive.java:668)
at weblogic.diagnostics.archive.wlstore.PersistentStoreDataArchive.deleteDataRecords(PersistentStoreDataArchive.java:1285)
- locked <0x000000060c948708> (a weblogic.diagnostics.archive.wlstore.HarvestedPersistentStoreDataArchive)
at weblogic.diagnostics.archive.wlstore.PersistentStoreDataArchive.retireOldestRecords(PersistentStoreDataArchive.java:1211)
at weblogic.diagnostics.archive.DataRetirementByQuotaTaskImpl.performDataRetirement(DataRetirementByQuotaTaskImpl.java:92)
at weblogic.diagnostics.archive.DataRetirementByQuotaTaskImpl.run(DataRetirementByQuotaTaskImpl.java:49)
at weblogic.diagnostics.archive.DataRetirementTaskImpl.run(DataRetirementTaskImpl.java:261)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:553)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:312)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:264)

 jstack.txt - 0x72ac
"Thread-7" prio=10 tid=0x00007fd414068000 nid=0x72ac runnable [0x00007fd454325000]
java.lang.Thread.State: RUNNABLE
at weblogic.store.io.file.direct.DirectIONative.unmapFile(Native Method)
at weblogic.store.io.file.direct.FileMapping.unmapView(FileMapping.java:192)
at weblogic.store.io.file.direct.FileMapping.mapView(FileMapping.java:162)
at weblogic.store.io.file.direct.FileMapping.remapViewInit(FileMapping.java:140)
at weblogic.store.io.file.direct.FileMapping.getMappedBuffer(FileMapping.java:210)
at weblogic.store.io.file.StoreFile.mappedRead(StoreFile.java:508)
at weblogic.store.io.file.Heap.read(Heap.java:989)
at weblogic.store.io.file.FileStoreIO.readInternal(FileStoreIO.java:305)
at weblogic.store.io.file.FileStoreIO.read(FileStoreIO.java:281)
at weblogic.store.internal.ReadRequest.run(ReadRequest.java:34)
at weblogic.store.internal.StoreRequest.doTheIO(StoreRequest.java:89)
at weblogic.store.internal.PersistentStoreImpl.synchronousFlush(PersistentStoreImpl.java:1086)
at weblogic.store.internal.PersistentStoreImpl.run(PersistentStoreImpl.java:1070)
at java.lang.Thread.run(Thread.java:745)


From here I could go on with my debugging, but from both the stack traces it was clear to me that something was wrong with the persistent file store. A little bit of the mystery was solved!

-i

Have comments or feedback on what I wrote? Please share them below! Found this useful? Consider sending me a small tip.
comments powered by Disqus
Other posts you may like...
Hi! You can search my blog here ⤵
Or browse the recent top tags...

Recent Blog Posts

How to fix Google Cloud SDK dev server error - No module named ipaddr

Adorable but totally metal - Metal Earth 3D Guardians of the Galaxy Groot model kit

Riverside Expressway Cam shut down permanently

Inserting Google DFP ads with Backbone, Underscore and jQuery

How to resolve the domain is already mapped to a project error in Google App Engine

A quick look at the Nyko Super MiniBoss wireless controllers for the SNES mini

Loading and displaying a collection from bootstrapped data in Backbone.js

Add this handy function to your Bash profile file to display the compiled JDK version for a .class file

How does PCBWay stack up as a low budget PCB fab

Resolving the Cannot reference X before supertype constructor is called compiler error in Java

Recent Galleries

BMB-012 Nanoblock T-Rex Skeleton Model assembly

Tiny Arcade revision 6 kit assembly and decal application

Atari Lynx repair - Part 5 - McWill LED screen mod installation

Atari Lynx repair - Part 4 - screen cover replacement

Atari Lynx repair - Part 2 - re-capping the motherboard

Atari Lynx repair - Part 3 - broken speaker replacement

Atari Lynx repair - Part 1 - introduction and case disassembly

Building a custom Atari Lynx game box storage shelf unit in a day

Protecting old Atari Lynx game boxes with snug fit plastic sleeves

Monument Valley 2 is released and does not disappoint

Blogs and Friends

Matt Moores Blog
Georgi's FlatPress Guide
Perplexing Permutations
The Security Sleuth
Ilia Rogatchevski
Travelling Fairy

Blog Activity

Blog Activity