Oracle Trace is one of my favorite tools when working with performance. It’s not my only tool, but it’s a tool which have given me great success when working on performance related issues. In this small article I’ll try to explain why? I’ll start by telling a small story.
I’m a cyclist. I’m just an amateur, but some years ago I sometimes participated in local cycling races. As a part of my training I cycled between my home and work, which was approximately 30 km (a little less than 20 miles) one way. After some years away from cycling (and a little to0 much work and unhealthy overtime food), I gained some weight (about 40 pounds!). So I brushed the dust off my bike, and started riding to work again.
Some days later, when I was parking my bike outside my work, a colleague came cycling and parked on the side of me. We got talking, and it turned out that his home was pretty close to mine. I got a little curious and asked how much time he spent riding to work. He said that he usually cycled very slow, and only did very easy training when riding to and from work. Usually spending about 1 hour and 30 minutes each way. I was very happy to hear this, and asked if I could join him one day. I spent about 20 minutes less, but thought it would be nice with some company. I would have no trouble riding a little slower. A couple of days later we met with our bikes in an agreed intersection, and started on the ride towards work. We were cycling side by side, talking about work and life in general. After a while we started to climb a longer hill. Not very steep, but enough to get the heartbeat going a little faster. Halfway up the hill, I had trouble keeping the conversation going. My colleague seemed completely untouched by the climb. At first I tried to act as nothing, struggling to keep the pace up. But riding on 95 % of maximum pulse can not last forever. Finally I had to let go of my pride, and I asked if we could slow down a bit. He said “Of course!”, and he also asked if I wanted to stay on his tail. The rest of the ride I spent behind his back wheel, only asking him to slow down once in a while. Finally – when arriving work – I noticed that I had only spent 1 hour on my way to work. This was 10 minutes faster than I usually ride, and 30 minutes faster than he said that he spent. So I asked him why this was the case. His answer was: “When I ride by myself, I always ride an alternative route getting some extra distance and training”. So when I was riding 30 km in 1 hour and 10 minutes. My colleague was riding 45 km in 1 hour and 30 minutes! I forgot one of the very important facts when working with performance, timings do not tell you the whole story!
Performance is about response time and throughput. Both response time and throughput is about time and some amount of work (a task to be completed; possibly involving several subtasks). This underlines the importance of time, but time in itselves contains very little information. If I told you that yesterday I was cycling for 1 hour. It would be really hard to judge the effort in my cycling. But if i told you that my weight is 90 kilo, and that I cycled 35 km in 1 hour with a total of 1500 elevation meters. That gives an average speed of 35 km/h with a lot of climbs. You could actually question if I was telling the truth. We need to know the amount of work that is behind the timings. When speaking about application performance, the amount of work is defined by the code path. What code is being run between the user push the button on the screen and the confirmation about the task being finished pops up on the screen? This involves all the layers in our IT stack, for instance browsers or thick clients, proxies, load balancers, application servers, network (WAN, LAN, SAN etc), databases and storage devices (as disks). The total time spent completing all the different sub tasks sums up into the total response time. When working with performance we need to find where time is spent. When working with Oracle database, one of these places is Oracle trace.
When an application talks to a database, it does so through a database connection (inside the database the connection is represented by a database session). When a running application has access to a Oracle connection (or session), it can complete tasks towards the database by submitting SQL commands. Each SQL command is completed by the database client API by submitting OPI calls as PARSE, BIND, EXECUTE, FETCH, COMMIT, ROLLBACK, etc towards the database. A PARSE might trigger new and recursive SQLs to be fired. A FETCH will possible trigger some Oracle blocks to be read, maybe both blocks from indexes and tables. These blocks might not be in memory, and might trigger IO calls towards the storage layer. Oracle lets you start a trace on a connection (or session). When trace is started (or enabled) every completed OPI call is recorded with some statistics about the work done. How much CPU time was spent? How much time in total was used to complete the call? How many blocks was read completing the task? How many rows was fetched? Etc. All these statistics are written to a trace file on the Oracle database server. Another thing which is recorded in the trace file is the wait calls. For instance – IO calls towards the storage layers. Using all this information we can create a time profile which shows where the time is spent. When you know where time is spent, you can really start your work with improving performance. Many developers are surprised when they get the facts on the table. What they thought was a slow running database, might be a chatty application. When an application fires thousands of small queries towards a database, the response time could end up consisting mainly of network latency. The database might be idle for the most of the time, just waiting for more work to be done.
Post a Comment