Skip to Content

Little angels

I had received a call from a customer that their SAP system server was consuming Full CPU cores while normally the use was 5% on average. This was after an Oracle11G upgrade had taken place so it immediately pointed towards the switch from Oracle10G to Oracle11G.

I logged on once I got home. I had my kids with me which is the normal situation, my future wife drives them to grand-ma in the morning, and I pick them up in the evening. To my delight they were like little angels and I could logon without the need for superhero moves.

Searching for the root cause

The logs

The logs (SAP logs and Oracle logs) didn’t show anything special and when checking the statistics in the SAP systems only showed some trace of the elevated CPU use and the slowdown caused by it.

I did check the SAP system thoroughly for clues (system administrator transactions, logging, tracing, expensive SQL statements, AWR reporting for Oracle). Too bad Database Analysis for Diagnostics scenario is not yet available (it should be available in Solution Manager 7.1).

Residing to other sources

After those checks I started looking on sources such as SAP Service Marketplace, Oracle Metalink, SCN and Google (in that order). The first search I did I used the keywords “oracle CPU” in SAP Service Marketplace. This brings up SAP Note 712624 – High CPU consumption by Oracle. A SAP Note with thirty-one points on possible causes for high CPU consumption.

I couldn’t really pinpoint the cause though based on the instructions I could find on any of these sources. After some searching around on the net I couldn’t find anything that was really conclusive and could give the proper root cause.

Eventually I did come across very interesting information for this particular case through Google: http://www.oracledatabase12g.com/archives/resolving-high-cpu-usage-on-oracle-servers.html.

The page includes a case study of Oracle on resolving High CPU Usage on Oracle Servers (interesting content). Further down on the page you can also find SQL statements used to check CPU consumption.

QSlice

Further down on the webpage mentioned previously you can find instructions to use a Windows administrative tool QSlice. It can be used to check which part of ORACLE.EXE is consuming the CPU.

This is also possible using other tools such as the Oracle Administration Assistant for Windows can also provide Process Information of individual threads.

QSlice
Oracle EXE

picture 1.1

When you open QSlice you will have a similar overview as in picture 1.1. You can see here the process on the bottom takes the CPU (oracle.exe).

Oracle threads
Thread usage

picture 1.2

To check which part of oracle.exe is consuming that much CPU you can double click on oracle.exe in the second column to view the details.

The total CPU% on picture 1.2 is actually around 50%. The reason is because I performed a stop/start of SAP + Oracle earlier on the same day before business hours which freed of the CPU power.

Now when you look at the first column in picture 1.2 you will see the TID (Thread ID). The SQL statements mentioned on the webpage used this TID to try and figure out what the thread is actually doing.

In this case TID 13e0 and 1778 are consuming CPU power. The notation here of the TID is Hexadecimal, to be able to use it in SQL statements. First convert the TIDs to Decimal format. You can do this through SQL or using a simple calculator which you Google up in two seconds.

Hexadecimal to Decimal conversion:
13e0 equals 5088
1778 equals 6008

SQL 1

picture 1.3

You can see now we have identified the Oracle process ID (PID = 49) and the Windows thread id in decimal format (SPID = 5088).

SQL 2

picture 1.4

You can see now for the second thread ID in QSlice we have identified the Oracle process ID (PID = 50) and the Windows thread id in decimal format (SPID = 6008).

In the source mentioned earlier there are also SQL statements to find out which Oracle session is related to a certain process. However since there were no abnormalities in SAP (transaction DB02) I didn’t expect any return. I did perform the SQL statement to see which session is connected but I got a “no rows returned” as result.

Oradebug

Since I still didn’t really have enough information I wanted to go a step further and dump what Oracle was doing. You can find instructions to perform those kinds of actions on the same source mentioned in this blog.

Now you can create a trace of what these processes are doing:

ORADebug 1

picture 1.5

Enable the trace by setting the following event:

ORADebug 2

picture 1.6

Disable the trace again after a little bit of time with the following statement:

ORADebug 3

picture 1.7

This dumps a trace file to the location which is specified by parameter user_dump_dest. To check the location where the trace file is written you can show the parameter value:show parameter user_dump_dest;

I enabled the trace and let it run for some minutes. I went to check the content of the trace file; to my surprise it was empty. The only additional information I had found is the fact that it concerns shadow process since it’s visible when you perform the oradebug command in the ORACLE.EXE (SHAD).

An Oracle shadow process is typically created when a connection towards Oracle is made. SAP also uses the mechanism. I was also communicating with the IT department of my customer as good communication and status updates etc aid the cause of finding the proper solution.

Since the CPU usage was 0% upon startup and it went up to 25% after a while, stayed there and then bumper up to 50% and after some more time 75% and eventually 100% it seemed the issue was triggered by a periodic job.

To blog or not to?

I saw the serious discussion on the link blog earlier today so I had to build in an interval at this point. I love story telling and for me blogging works best for me, I cannot write this way if I would have to write a white-paper.

Troubleshooting is a form of art

picture 1.8

I love troubleshooting, yes it can bring additional work hours and yes it’s a challenge and people will be anxious but for me troubleshooting is creating art (hence my blog the art of troubleshooting). Since I wanted to give it some more momentum I decided to draw a small piece of art (see picture).

Around 9PM my future wife arrived at home and started to give comments on the crime scene that was left behind by the kids inside the house. I did let the little angels watch DVD movies, play around, eat and drink, colour in colouring books and probably also on colour on items they shouldn’t colour on.

I waved it off by saying “This is IT”. It sounded a lot like the one-liner from 300 “This is Sparta”. The only problem was mine didn’t have any impact.

Then I probably skipped half of the conversation and I answered without knowing what I answered but I was focused on the greater cause. Finding the root cause and solving the issue. Most likely I promised to clean up the mess so I could continue. Apparently I tend to talk and answer in my sleep also. Good thing my brain is always alert for trick questions.

This is IT

Alright I’m tilting towards too much non technical content so back to the problem. Where were we? Yes so I called the customers IT persons and discussed what I had seen so far. So now we were looking for a job or program that would trigger at certain timings but outside of SAP since there was no single trace that SAP itself (SAP ERP) was involved in any way. While I was talking on the phone I saw another CPU core being fully utilized in QSlice so I had an exact timing. With that timing and the traces of the other timings the customer was able to find out that it was a Cognos job that was triggered on that timing.

It makes sense once the puzzle is complete

Since we wanted to be sure, he launched a job manually and we saw the CPU bumping up another 25% so we had found the root cause of the issue. After checking it seemed the Oracle client used by Cognos was too old (or the Cognos software was already too old) and when the Oracle client connected to Oracel11G, on the Cognos side, it throws an error and closes down and on Oracle11G side the shadow process keeps using CPU.

This is great

By the time the test was done it was 11:15pm. The great thing about the whole story is how we (customer and me) teamed up. The mission was accomplished and the customer was very happy that the root cause was found. Since there were persons working on SAP at that timing I set an alarm to wake up at 4:45am again to stop/start SAP+Oracle to free up the resources (it had been running at 75% CPU while I was sleeping). A few twitters the next morning are traces of the excellent teamwork that was done.

System administration

I also want to point out that system administration contains lots of area’s (certainly not narrowed down to only SAP software).

I graduated as a developer and as a developer, having to use coding from can be a challenge. In the past I have spend time on building a modification for Unreal Tournament 2004 (PC game). To be able to create modifications, add content and so on, you first have to understand the coding that exists to be able to reuse parts and code new parts.

This is also very often the case as a system administrator, we have to gather the pieces of the puzzle and put them together. If a SAP application fails, the administrator is contacted and he has to find out what caused it. It’s possible it doesn’t have anything to do with a problem caused by the SAP software itself.

To report this post you need to login first.

5 Comments

You must be Logged on to comment or reply to a post.

  1. Anonymous
    Thanks for the blogs. I’ve learned extra by reading this blog. Would like to hear more from you.
    Thanks.

    Cheers,
    Nicholas Chang

    (0) 
    1. Tom Cenens Post author
      Hello Nicholas

      Thank you for the comment.

      I have some drafts blogs that I should finish up. It does take me some time to build these, since the editor doesn’t yet support Word paste I tend to write the blogs in html code myself to ensure proper formatting and spacing.

      Kind regards

      Tom

      (0) 
      1. Anonymous
        Hi Tom,

        Do you perform any 11g installation on Unix (11.2.0.2)? If yes, do you have any cookbook on this? I’ve gather all the related notes, and understand that patchset 11.2.0.2 are full installation of the oracle database software and is different compare to oracle 10g installation.

        I’ve downloaded ORACLE RDBMS 11.2.0.2 SOLARIS and as usual SAPINST will extract it to /oracle/stage dir.. what it have to do with the patchset here for the installation?

        Appreciate if you can shed some light on this.

        If you have any cookbook, appreciate if you can send it to ncks82@yahoo.com. Thanks!

        Cheers,
        Nicholas.

        (0) 
        1. Anonymous
          If i not mistaken, /oracle/stage/112_64/database/SAP
          extracted from RDBMS will need to replace by the installation files from patchset 11.2.0.4?

          Thanks,
          Nicholas Chang

          (0) 
          1. Tom Cenens Post author
            Hello Nicolas

            I havent yet installed a patch as the installation was on Windows 2008 and there is no patch available yet for that platform.

            I use the instructions that are delivered in the readme which you find on the same location as the patch on SAP service marketplace, those work fine.

            I would expect you need to run the installer once the patch is extracted (the location where it is extracted doesn’t matter normally) but as I mentioned before please check the readme.html accompanied by the patch.

            Kind regards

            Tom

            (0) 

Leave a Reply