Parsing Oracle Traces with "Parse Trace OWI" tool
Tags: database, performance, oracle, tutorial
Published: 2021-01-09 13:01:04

One of the best things about the Oracle Community is the amount of people willing to share cool information and tools they develop on their own.
I guess we could say "Sharing is caring" :)

One of the people you should start following (but I'm sure you already do..) is [Kamil Stawiarski](https://twitter.com/ora600pl).
He recently created and shared an amazing tool to do Trace Parsing and find interesting performance stats from them, specially when you need to work with massive amount of traces.

The tool is called [Parse Trace OWI](https://github.com/ora600pl/tracefile_parsers/tree/master/parse_trace_owi) and you can find how it works in his recent post [WHAT TO DO WITH 5GB OF TRACE FILES?](https://blog.ora-600.pl/2021/01/08/what-to-do-with-5gb-of-trace-files/)

I dont currently have that amount of traces, but I thought could just spin up one small DB 12.2 and enable tracing during [Swingbench](http://dominicgiles.com/swingbench.html) Schema/Data creation.


First, lets start Installing [Parse Trace OWI](https://github.com/ora600pl/tracefile_parsers/tree/master/parse_trace_owi) in our DB server.

I have to install Go and git first, of course.
For GO, just followed this [guide](https://linuxize.com/post/how-to-install-go-on-centos-7/) (but changing to most recent version)

```bash
[root@rac1-node1 ~]# yum install git -y
Loaded plugins: langpacks, ulninfo
ol7_UEKR5                                                                                                                  | 2.5 kB  00:00:00
ol7_latest                                                                                                                 | 2.7 kB  00:00:00
(1/5): ol7_UEKR5/x86_64/updateinfo                                                                                         |  50 kB  00:00:00

[....]

Installed:
  git.x86_64 0:1.8.3.1-23.el7_8

Dependency Installed:
  perl-Error.noarch 1:0.17020-2.el7                                       perl-Git.noarch 0:1.8.3.1-23.el7_8

Complete!
[root@rac1-node1 ~]#



[root@rac1-node1 ~]# wget https://golang.org/dl/go1.15.6.linux-amd64.tar.gz
--2021-01-09 11:09:20--  https://golang.org/dl/go1.15.6.linux-amd64.tar.gz
Resolving golang.org (golang.org)... 172.217.169.81, 2a00:1450:4009:819::2011
Connecting to golang.org (golang.org)|172.217.169.81|:443... connected.
HTTP request sent, awaiting response... 302 Found
Location: https://dl.google.com/go/go1.15.6.linux-amd64.tar.gz [following]
--2021-01-09 11:09:21--  https://dl.google.com/go/go1.15.6.linux-amd64.tar.gz
Resolving dl.google.com (dl.google.com)... 216.58.204.78, 2a00:1450:4009:814::200e
Connecting to dl.google.com (dl.google.com)|216.58.204.78|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 120951514 (115M) [application/octet-stream]
Saving to: ‘go1.15.6.linux-amd64.tar.gz.1’

100%[========================================================================================================>] 120,951,514 7.21MB/s   in 17s

2021-01-09 11:09:38 (6.92 MB/s) - ‘go1.15.6.linux-amd64.tar.gz.1’ saved [120951514/120951514]

[root@rac1-node1 ~]# sudo tar -C /usr/local -xzf go1.15.6.linux-amd64.tar.gz
[root@rac1-node1 ~]# su - oracle
[oracle@rac1-node1 ~]$ vi .bash_profile
[oracle@rac1-node1 ~]$ grep -i path .bash_profile
PATH=$PATH:$HOME/.local/bin:$HOME/bin:/usr/local/go/bin
PATH=/home/oracle/scripts/:$PATH
export PATH
[oracle@rac1-node1 ~]$
[oracle@rac1-node1 ~]$ source .bash_profile
[oracle@rac1-node1 ~]$
```
Clone [tracefile_parsers](https://github.com/ora600pl/tracefile_parsers) and build [Parse Trace OWI](https://github.com/ora600pl/tracefile_parsers/tree/master/parse_trace_owi)

```bash
[oracle@rac1-node1 ~]$ git clone https://github.com/ora600pl/tracefile_parsers
Cloning into 'tracefile_parsers'...
remote: Enumerating objects: 65, done.
remote: Counting objects: 100% (65/65), done.
remote: Compressing objects: 100% (47/47), done.
remote: Total 80 (delta 31), reused 50 (delta 17), pack-reused 15
Unpacking objects: 100% (80/80), done.
[oracle@rac1-node1 ~]$
[oracle@rac1-node1 ~]$ export GOPATH=$PWD/tracefile_parsers/parse_trace_owi
[oracle@rac1-node1 ~]$ export PATH=$GOPATH:$PATH
[oracle@rac1-node1 ~]$ go build $GOPATH/parse_trace_owi.go
[oracle@rac1-node1 ~]$ ./parse_trace_owi
  -cpuprofile string
        write cpu profile to file
  -d string
        debug (default "false")
  -event string
        Display SQLids for specified event
  -p int
        parallel degree (default 1)
  -s string
        where to search for trace files
  -sqlid string
        Display wait events for sqlid
  -tf string
        time from (default "2020-01-01 00:00:00.100")
  -top int
        Only TOP n elements
  -tt string
        time to (default "2020-01-02 00:00:00.100")
[oracle@rac1-node1 ~]$
```

I enabled Tracing at DB level, so we make sure we get some nice traces during the [Swingbench](http://dominicgiles.com/swingbench.html) Schema/Data creation.
```bash
db1221 - SQL>ALTER SYSTEM SET EVENTS '10046 trace name context forever, level 12';

System altered.

db1221 - SQL>
```

And now, to generate some activity


![SwingBench](https://dev-to-uploads.s3.amazonaws.com/i/erucg9g7gfwr4mpxc7xz.png)


Let's analyse the traces (for the time it took, to analyse *everythong* :stuck_out_tongue_winking_eye:, you can see I have less DB activity than Kamil shows in his post)

TOP 10 of wait events:
```bash
[oracle@rac1-node1 ~]$ ./parse_trace_owi -s /u01/app/oracle/diag/rdbms/db122/db1221/trace/ -p 4 -tf="2021-01-09 11:35:00.000" -tt="2021-01-09 12:00:00.000" -top=10
                                                  WAIT EVENT            ELA(ms)                 COUNT           AVG(ms)                 STDDEV(ms)              CLASS

                                   'flashback log file sync'            1931.695000             315             6.132365                10.302641               User I/O
                                     'gc current block busy'            3424.641000             393             8.714099                20.340445               Cluster
                                     'enq: IV -  contention'            3988.528000             1224            3.258601                3.142054                UNKNOWN
                                           'buffer busy waits'            4084.563000             963             4.241498                24.400184               Concurrency
                            'flashback buf free by RVWR'            4273.345000             74              57.747905               48.967046               Configuration
                                                    'log file sync'            4287.429000             445             9.634672                8.247748                Commit
                                    'gc buffer busy acquire'            5154.863000             876             5.884547                16.949100               Cluster
                                    'gc buffer busy release'            5338.218000             244             21.877943               33.154836               Cluster
                                   'db file sequential read'            13500.061000            4117            3.279102                5.146506                User I/O
                                   'cursor: pin S wait on X'            21360.750000            404             52.873144               26.144244               Concurrency
Everythong took: 6.117350 ms
[oracle@rac1-node1 ~]$
```

TOP 10 SQL IDs waiting for 'cursor: pin S wait on X':
```bash
[oracle@rac1-node1 ~]$ ./parse_trace_owi -s /u01/app/oracle/diag/rdbms/db122/db1221/trace/ -p 4 -tf="2021-01-09 11:35:00.000" -tt="2021-01-09 12:00:00.000" -top=10 -event="'cursor: pin S wait on X'"
SQLs for event 'cursor: pin S wait on X'
'ftwavddscfwvh'         879.913000
'1d5382uc80v5s'         880.938000
'fyfbf4hhzj9k1'         886.067000
'128d10u73m6gs'         932.065000
'783fyg6rpujtf'         1000.191000
'g2xjf3yf4u9ux'         1017.430000
'81ajfu4j9cscv'         1120.566000
'dcspxv91pk3u7'         1241.761000
'3dgxux71h1rz5'         1258.127000
'889hf7ysfx1xn'         2152.660000
It was 24.590164 percent out of all SQLs - 30 out of 122
Everythong took: 4.941850 ms
[oracle@rac1-node1 ~]$
```

Checking 889hf7ysfx1xn Wait Events:
```bash
[oracle@rac1-node1 ~]$ ./parse_trace_owi -s /u01/app/oracle/diag/rdbms/db122/db1221/trace/ -p 4 -tf="2021-01-09 11:35:00.000" -tt="2021-01-09 12:00:00.000"  -sqlid="'889hf7ysfx1xn'"                     
Wait events for this SQLid
                                                  WAIT EVENT            ELA(ms)                 COUNT           AVG(ms)                 STDDEV(ms)CLASS

                                           'row cache mutex'            0.013000                1               0.013000                0.000000 Concurrency
                                         'buffer busy waits'            0.238000                1               0.238000                0.000000 Concurrency
                                        'resmgr:cpu quantum'            0.258000                1               0.258000                0.000000 Scheduler
                                   'gc cr multi block grant'            1.022000                1               1.022000                0.000000 Cluster
                                    'db file scattered read'            1.474000                1               1.474000                0.000000 User I/O
                                   'gc cr multi block mixed'            2.105000                2               1.052500                0.119500 Cluster
                            'gc current multi block request'            2.486000                3               0.828667                0.032190 Cluster
                                    'gc current block 2-way'            2.725000                5               0.545000                0.160181 Cluster
                                         'gc cr grant 2-way'            4.824000                10              0.482400                0.221645 Cluster
                                      'enq: HW - contention'            5.339000                3               1.779667                0.890092 Configuration
                                         'gc cr block 2-way'            6.785000                10              0.678500                0.260766 Cluster
                                     'gc current grant busy'            8.399000                12              0.699917                0.304603 Cluster
                                   'flashback log file sync'            51.713000               10              5.171300                3.643539 User I/O
                                            'row cache lock'            60.679000               24              2.528292                2.389836 Concurrency
                                    'gc current grant 2-way'            85.554000               137             0.624482                0.873164 Cluster
                                    'library cache: mutex X'            99.164000               26              3.814000                4.629967 Concurrency
                                   'library cache load lock'            104.678000              12              8.723167                2.432378 Concurrency
                                     'enq: IV -  contention'            200.024000              56              3.571857                3.124875 UNKNOWN
                                             'log file sync'            431.547000              16              26.971688               17.164262Commit
                                   'db file sequential read'            888.397000              179             4.963112                6.251202 User I/O
                                   'cursor: pin S wait on X'            2152.660000             15              143.510667              12.079331Concurrency
Everythong took: 6.146940 ms
[oracle@rac1-node1 ~]$
```

What an amazing tool, no need for Diagnostic Pack to get some really cool stats.

I'm sure this will be only improve, so make sure you subscribe to [Parse Trace OWI](https://github.com/ora600pl/tracefile_parsers/tree/master/parse_trace_owi) and [Kamil's blog](https://blog.ora-600.pl)