This is just a short note to point out that I finally uploaded under the downloadable files of TOP a new version of TVD$XTAT. To download it click here. Not only I introduced some new features, but I also fixed several bugs.
The detailed change log since Beta 10 is the following:
Last January, in the following tweet, I pointed out that the documentation vaguely mentions that a trace file may be split into several files.
Did you successfully tested the new MAX_DUMP_FILE_SIZE behavior? If yes, which version/OS?https://t.co/4F9f9wsT95 pic.twitter.com/X2Y7FNf1HG
— Christian Antognini (@ChrisAntognini) January 20, 2016
Today I started having a look to the Oracle Database Exadata Express Cloud Service announced last week at Oracle OpenWorld. Note that since the amount of resources provided (in summary, 1 OCPU, 20 or 50 GB of database storage) is very limited, in general, in my opinion that service will only be useful for functional tests. In fact, if it wasn’t because that is the very first 12.2 release (12.2.0.0.3 according to V$VERSION) available, I doubt I would care about it…
A first important thing to know is that the service gives access to a PDB via SQL*Net only (in addition to the web-based interfaces like APEX). In other words, the OS access is precluded.
The second edition of Cary Millsap‘s MASTERING ORACLE TRACE DATA (MOTD) is finally available. You can order it through amazon.com. I had the pleasure not only to review MOTD while Cary was working on it, but also to write a foreword that summarizes what I think about the book. So, if you are asking yourself whether you should buy MOTD, here is my opinion/foreword…
With the INMEMORY clause you can specify 4 sub-clauses:
Extended SQL trace (a.k.a. debugging event 10046 at a level higher than 1) is one of the key features provided by Oracle to troubleshoot applications using Oracle Database. For many years the available levels were always the same (4, 8 and 12). In fact, since I wrote my first paper about it in May 2000 and the release of 11g nothing changed.
With 11g, as I described in this post, new levels (16 and 32) were introduced.
This is just a short post to point out that the company I work for, Trivadis, is organizing 3 classes with Cary Millsap. The topic, as the title suggests, is Cary’s 1-day class entitled “Mastering Oracle Trace Data”.
The following dates and locations are planned:
For detailed information have a look to the flyer. Note that the early bird registration period, that entitles you a 15% discount, ends on August 1.
Recently I was involved in a project where I had to trace the database calls of an application based on Oracle Portal 10.1.4. The basic requirements were the following:
Given that Oracle Portal uses a pool of connections and that for each HTTP call it can use several database sessions, statically enable SQL trace for specific sessions was not an option.
The release 11.2.0.2 not only provides a lot of documented new features, but also provides undocumented ones. Today, I would like to spend few words about the undocumented changes introduced in the TKPROF output. In this area it is interesting to point out that after the introduction of wait events in Oracle9i, there were really few enhancement in the formatting of the output.
To show you what’s new in the output, I executed the same commands I already used in the post covering the 11.2.0.1 new features of TKPROF. I just removed the histogram on SH.SALES.CHANNEL_ID before running them (I did that because I was not interested in having different execution plans).
The relevant part of the output generated by TKPROF is the following:
SQL ID: 94mzsr37n3vz0 Plan Hash: 1550251865 SELECT * FROM sh.sales WHERE channel_id = :channel_id call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 5 0.00 0.00 0 0 0 0 Execute 5 0.00 0.00 0 0 0 0 Fetch 61263 3.58 3.65 756 69331 2 918843 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 61273 3.59 3.65 756 69331 2 918843 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 34 Rows Row Source Operation ------- --------------------------------------------------- 258025 PARTITION RANGE ALL PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=664296 us cost=536 size=6661619 card=229711) 258025 TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=465129 us cost=536 size=6661619 card=229711)
SQL ID: 94mzsr37n3vz0 Plan Hash: 1550251865 SELECT * FROM sh.sales WHERE channel_id = :channel_id call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 5 0.00 0.00 0 0 0 0 Execute 5 0.00 0.00 0 0 0 0 Fetch 61263 3.58 3.65 756 69331 2 918843 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 61273 3.59 3.65 756 69331 2 918843 Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 34 Number of plan statistics captured: 5 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 258025 183769 540328 PARTITION RANGE ALL PARTITION: 1 28 (cr=13866 pr=151 pw=0 time=492737 us cost=536 size=6661619 card=229711) 258025 183769 540328 TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=13866 pr=151 pw=0 time=396774 us cost=536 size=6661619 card=229711)
As you can see the differences (in order or appearance, not relevance) are the following :
The new/changed information is good. But, be careful, averages hide a lot of information. So, while the new output is more useful than the old one, it’s not perfect. In fact, if you really want to know what happened at runtime, you have to give a look to the raw trace file information. In this case the information associated to the execution plans are the following (notice how the number or returned rows, attribute “cnt”, and the number of logical reads in consistent mode, attribute “cr”, changes between executions):
STAT #182927356440 id=1 cnt=258025 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=664296 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=2 cnt=258025 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=18811 pr=756 pw=0 time=465129 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=1 cnt=540328 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=1146677 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=2 cnt=540328 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=37596 pr=0 pw=0 time=739039 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=1 cnt=118416 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=421391 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=2 cnt=118416 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=333077 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=1 cnt=0 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218050 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=2 cnt=0 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218013 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=1 cnt=2074 pid=0 pos=1 obj=0 op='PARTITION RANGE ALL PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=13271 us cost=536 size=6661619 card=229711)' STAT #182927356440 id=2 cnt=2074 pid=1 pos=1 obj=13821 op='TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=228613 us cost=536 size=6661619 card=229711)'
Another difference is related to the processing of trace files while aggregation is disabled (i.e. “aggregate=no”) and the SORT parameter is specified. The following two outputs, based on the same trace file as above, illustrate this (notice how several execution plans are displayed in the 11.2.0.1 output). Honestly, this could be seen as a bug fix.
SQL ID: 94mzsr37n3vz0 Plan Hash: 1550251865 SELECT * FROM sh.sales WHERE channel_id = :channel_id call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 3 0.00 0.00 0 0 0 0 Execute 3 0.00 0.00 0 0 0 0 Fetch 8037 1.01 1.02 0 12924 0 120490 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 8043 1.01 1.02 0 12924 0 120490 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 34 Rows Row Source Operation ------- --------------------------------------------------- 118416 PARTITION RANGE ALL PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=421391 us cost=536 size=6661619 card=229711) 118416 TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=9515 pr=0 pw=0 time=333077 us cost=536 size=6661619 card=229711) 0 PARTITION RANGE ALL PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218050 us cost=536 size=6661619 card=229711) 0 TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1635 pr=0 pw=0 time=218013 us cost=536 size=6661619 card=229711) 2074 PARTITION RANGE ALL PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=13271 us cost=536 size=6661619 card=229711) 2074 TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=1774 pr=0 pw=0 time=228613 us cost=536 size=6661619 card=229711)
SQL ID: 94mzsr37n3vz0 Plan Hash: 1550251865 SELECT * FROM sh.sales WHERE channel_id = :channel_id call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 3 0.00 0.00 0 0 0 0 Execute 3 0.00 0.00 0 0 0 0 Fetch 8037 1.01 1.02 0 12924 0 120490 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 8043 1.01 1.02 0 12924 0 120490 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 34 Number of plan statistics captured: 3 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 118416 40163 118416 PARTITION RANGE ALL PARTITION: 1 28 (cr=4308 pr=0 pw=0 time=217571 us cost=536 size=6661619 card=229711) 118416 40163 118416 TABLE ACCESS FULL SALES PARTITION: 1 28 (cr=4308 pr=0 pw=0 time=259901 us cost=536 size=6661619 card=229711)
The last thing I would like to point out, but without discussing the details, is that there are some changes in the trace files as well. The most obvious is the numbering of cursors…
Recent comments
3 years 5 weeks ago
3 years 17 weeks ago
3 years 21 weeks ago
3 years 22 weeks ago
3 years 27 weeks ago
3 years 48 weeks ago
4 years 16 weeks ago
4 years 46 weeks ago
5 years 30 weeks ago
5 years 31 weeks ago