Oracle Trace Files - finally documented. Free eBook.

[NormTeamT]

Someone recently mentioned in a thread here, possibly John Dorlon, that Oracle Trace Files were not very well documented. I can’t find the thread now of course!

I’ve had piles of notes on the subject spread over many files for years, so I’ve gathered them all together and converted them into an eBook (pdf) that anyone can download and keep for free. Hopefully it will be of some use.

The book is on my Github repository, along with all the source code used to create it (in LaTeX format) so you are free to update it if you wish.

To obtain your free copy, with pretty pictures and a working index, goto:

github.com/…/OracleTraceFilesExplained.pdf

Then wait for the pdf to appear, then click the download button.

Enjoy.

[phyllis.helton_1150]

Thank you, Norm!

On Thu, Jul 20, 2017 at 6:22 PM, Norm [TeamT] bounce-NormTeamT@toadworld.com wrote:

Oracle Trace Files - finally documented. Free eBook.

Thread created by Norm [TeamT]
Someone recently mentioned in a thread here, possibly John Dorlon, that Oracle Trace Files were not very well documented. I can't find the thread now of course!

I've had piles of notes on the subject spread over many files for years, so I've gathered them all together and converted them into an eBook (pdf) that anyone can download and keep for free. Hopefully it will be of some use.

The book is on my Github repository, along with all the source code used to create it (in LaTeX format) so you are free to update it if you wish.

To obtain your free copy, with pretty pictures and a working index, goto:

github.com/.../OracleTraceFilesExplained.pdf

Then wait for the pdf to appear, then click the download button.

Enjoy.

To reply, please reply-all to this email.

Stop receiving emails on this subject.

Or Unsubscribe from Toad for Oracle Forum notifications altogether.

Toad for Oracle - Discussion Forum

Flag this post as spam/abuse.

--
Phyllis Helton

Data Magician

Security Gestapo
Digital Products & Strategies, Cru | Data Sciences & Analytics
Office 407-515-4452

phyllis.helton@cru.org

[rjesse]

I highly recommend the TraceMiner2 tool mentioned in your eBook, Norm. It’s a huge time-saver when sifting through million-line traces looking to see exactly which data was modified, especially if binds are used with a multi-byte characterset, because those bind values are presented in hex form in the trace.

Document saved to my library…

Thanks, Norm!
Rich

Disclaimer: That’s gold, Jerry! GOLD!

[NormTeamT]

Hmm, I seem to have managed to double post - apologies for that.

The eBook has been updated today, the latest version is in GitHub ready for download.

I fixed a few missing words, a section was somewhat absent, plus a few other bits and pieces have been added and the format slightly changes to reduce page spanning tables etc.

The date of creating is now formatted much better, on the copyright page, and shows the full date and time that the eBook was created, so you know if you have the latest version.

[NormTeamT]

Updated again. A few spelling mistakes have been corrected, but the data types table has also been updated. What Oracle say can occur and what I have got in numerous trace files differs!

[damir.vadas_250]

Hi Norm,

Thx in front (before reading) for your nice effort. Will definitely read it now.
Brg
Damir

[NormTeamT]

Afternoon All,

after a couple of days working in the depths of a particularly nasty trace file of 2 million plus lines, I have added a new section to my Trace Files Explained eBook, so it’s available for download as before from Github.

To obtain your free copy, with pretty pictures and a working index, goto:

https://github.com/NormanDunbar/OracleTraceFilesExplained/blob/master/OracleTraceFilesExplained.pdf

Then wait for the pdf to appear, then click the download button.

Updates include:

Various things to watch out for, child cursors, recursive SQL, reuse of cursor ids, executing the same statement under numerous different Cursor IDs and so on.

Enjoy.

Cheers,

Norm.

[NormTeamT]

Afternoon All,

updates like busses - nothing for ages, then two together!

After a brief conversation with John Dorlon, I’ve added some better explanations of what goes on when a cursor is closed but Oracle decided not to close it and simply caches it for later use. This results in an interesting situation whereby the cursor shows in the trace file as closed (with a type=1, 2 or 3) but is subsequently executed (with binds if appropriate) and without an intervening PARSING IN CURSOR or PARSE line. This is because the caching of a cursor does not close it, so it remains parsed etc. Oracle will do this if the database SESSION_CACHED_CURSORS is non-zero and the same statement has been parsed at least three times so far.

As ever, to obtain your free copy, stillwith pretty pictures and a working index, goto:
https://github.com/NormanDunbar/OracleTraceFilesExplained/blob/master/OracleTraceFilesExplained.pdf

Wait for the pdf to appear, then click the download button.

Enjoy.

[damir.vadas_250]

Hi Norm,

John is fully introduced with our talk on mine trace fiel?

If yes, then he can fix TFB a lot...

If not, please let me know so I can contact him and explain all...

Brg,**
________________________**

Damir Vadas
http://damir-vadas.blogspot.com

It does not matter what you have in your life, but who!

Razmislite o čuvanju okoliša prije nego odštampate ovaj e-mail
Please consider the environment before printing this email

On Tue, Nov 7, 2017 at 3:05 PM, Norm [TeamT] bounce-NormTeamT@toadworld.com wrote:

RE: Oracle Trace Files - finally documented. Free eBook.

Reply by Norm [TeamT]
Afternoon All,

updates like busses - nothing for ages, then two together!

After a brief conversation with John Dorlon, I've added some better explanations of what goes on when a cursor is closed but Oracle decided not to close it and simply caches it for later use. This results in an interesting situation whereby the cursor shows in the trace file as closed (with a type=1, 2 or 3) but is subsequently executed (with binds if appropriate) and without an intervening PARSING IN CURSOR or PARSE line. This is because the caching of a cursor does not close it, so it remains parsed etc. Oracle will do this if the database SESSION_CACHED_CURSORS is non-zero and the same statement has been parsed at least three times so far.

As ever, to obtain your free copy, stillwith pretty pictures and a working index, goto:
https://github.com/NormanDunbar/OracleTraceFilesExplained/blob/master/OracleTraceFilesExplained.pdf

Wait for the pdf to appear, then click the download button.

Enjoy.

To reply, please reply-all to this email.

Stop receiving emails on this subject.

Or Unsubscribe from Toad for Oracle Forum notifications altogether.

Toad for Oracle - Discussion Forum

Flag this post as spam/abuse.

[JohnDorlon]

Damir,

If you’ve found a bug, let me know the details. Norm and I did talk about your file.

-John

From: Damir Vadas [mailto:bounce-damirvadas_250@toadworld.com]

Sent: Tuesday, November 07, 2017 8:37 AM

To: toadoracle@toadworld.com

Subject: RE: [Toad for Oracle - Discussion Forum] Oracle Trace Files - finally documented. Free eBook.

RE: Oracle Trace Files - finally documented. Free eBook.

Reply by Damir Vadas

Hi Norm,

John is fully introduced with our talk on mine trace fiel?

If yes, then he can fix TFB a lot…

If not, please let me know so I can contact him and explain all…

Brg,**
________________________**

Damir Vadas

http://damir-vadas.blogspot.com

I****t does not matter what you have in your life, but who!

Razmislite o čuvanju okoliša prije nego odštampate ovaj e-mail

Please consider the environment before printing this email

To reply, please reply-all to this email.

Stop receiving emails on this subject.

Or
Unsubscribe from Toad for Oracle Forum notifications altogether.

Toad for Oracle - Discussion Forum

Flag
this post as spam/abuse.

[damir.vadas_250]

Hi john

You said that you are busy so I was waiting for you to come.
On link:
https://drive.google.com/open?id=0B8R6MVlBMkSpOHFzVTFwa053R0k

you can find all files needed for analyze.

1. trace_data.zip-trace file

2. MOBCST1_ora_28891_anylyze.xlsx- Toad Trace Browser (later TTB) representation of that trace file

3, 4) MOBCST1_ora_28891_nosort.lst and MOBCST1_ora_28891_sort.lst-two oracle tkprof analyzed files

5. AWR Rpt - MOBCST1 Snap 261759 thru 261780.html- AWR data from the whole time of traced session

6. trca_e11951.zip-analyze data done with trace analyzer

I do not know when you talk with Norm, what did he tell you.

Please let me know not to repeat.

Shortly.

Here is the statement from the trace file, starting at line 366652.

The cursor# for this statement is 11529215045668893824.

PARSING IN CURSOR #11529215045668893824 len=2843 dep=0 uid=9 oct=2 lid=9 tim=26375808573640 hv=1064773190 ad='c0000006a0e20208' sqlid='0um91dczrf9k6'

insert into CHARGE (BAN,ENT_SEQ_NO,ACTV_SEQ_NO,SYS_CREATION_DATE,SYS_UPDATE_DATE,OPERATOR_ID,APPLICATION_ID,DL_SERVICE_CODE,DL_UPDATE_STAMP,ACTV_CODE,ACTV_REASON_CODE,ACTV_DATE,ACTV_AMT,ACTV_BILL_SEQ_NO,CHG_CREATION_DATE,FEATURE_CODE,FTR_REVENUE_CODE,BALANCE_IMPACT_CODE,CREDIT_LEVEL,SOURCE_APPL_CODE,PRIOD_CVRG_ST_DATE,PRIOD_CVRG_ND_DATE,EFFECTIVE_DATE,INV_SEQ_NO,SUBSCRIBER_NO,SOC,SOC_DATE,SERVICE_FTR_SEQ_NO,SERVICE_TYPE,NO_OF_INSTALL_FROM,TOTAL_NO_OF_INSTALL,TAX_CODE,TAX_PERCENT_RATE,TAX_EFFECTIVE_DATE,MONTHLY_RATE,DISCOUNT_PCT,QUANTITY,LAST_RG_RC_DATE,BILL_COMMENT,AU_ISSUE_CODE,ACTION_DIRECTION_CD,CONV_RUN_NO,CHANNEL_SEIZURE_DT,MESSAGE_SWITCH_ID,MEMO_ID,CYCLE_MONTH_ST_DATE,LYT_QLF_RT_PRICE,ADJUSTED_AMT,PREV_ADJUSTED_AMT,DSPT_ADJ_AMT,DSPT_NON_ADJ_AMT,BEN,CHARGE_HIST_IND,AU_EFF_DATE,CHG_PRORATION_FACTOR,TAX_AMT,BL_IGNORE_IND,ASGN_TO_BILL_APPL_CD,SOC_VER_NO,SOC_SEQ_NO,PERIOD_CODE,PROVIDER_ID,BL_SERVICE_GROUP,FREE_MINS_USED,FREE_CALLS_USED,PRODUCT_TYPE,EU_ACTV_AMT,EU_MONTHLY_RATE,EU_ADJUSTED_AMT,EU_PREV_ADJUSTED,EU_DSPT_ADJ_AMT,EU_DSPT_NON_ADJ_AMT,EU_TAX_AMT,AU_BREAKDOWN_DATE,CALLS_DURATION,NUMBER_OF_CALLS,X_SUBSCRIBER_NR,DOCUMENT_NUMBER,PRICE_PLAN_CODE,CALL_GROUP,SENDER,FILE_SEQ_NO,INV_TYPE,SP_ENT_SEQ_NO,BILL_ADD_COMMENTS,APN,DISP_UOM_CODE,QUANTITY_TYPE,RC_CRDT_AMT,EU_RC_CRDT_AMT,CHAR_ADDITIONAL_INFO,CHG_APPLY_POINTS,FREE_TEXT_SOC,FREE_TEXT_FEATURE_CD,EU_VALID_AMT,UNUSED_DISC_AMT,UNUSED_DISC_EU_AMT,ORIG_DISCOUNT_AMT,ORIG_DISCOUNT_EU_AMT,BILL_DISPLAY_IND,IM_ROLLED_PRD_1,IM_ROLLED_PRD_2,CALL_DUR_REAL,CALL_DUR_ROUNDED,MSISDN,FM_TYPE,TURNOVER_IND) values (:b0,:b1,:b2,SYSDATE,null ,:b3:b4,:b5:b6,:b7:b8,:b9:b10,:b11:b12,:b13:b14,TO_DATE(:b15:b16,'YYYYMMDD'),:b17,:b18,TO_DATE(:b19:b20,'YYYYMMDD'),:b21:b22,:b23:b24,:b25,:b26:b27,:b28:b29,TO_DATE(:b30:b31,'YYYYMMDD'),TO_DATE(:b32:b33,'YYYYMMDD'),TO_DATE(:b34:b35,'YYYYMMDD'),:b36:b37,:b38:b39,:b40:b41,TO_DATE(:b42:b43,'YYYYMMDD'),:b44:b45,:b46:b47,:b48:b49,:b50:b51,:b52:b53,:b54:b55,TO_DATE(:b56:b57,'YYYYMMDD'),:b58:b59,:b60:b61,:b62:b63,TO_DATE(:b64:b65,'YYYYMMDD'),:b66:b67,:b68:b69,:b70:b71,:b72:b73,TO_DATE(:b74:b75,'YYYYMMDDHH24MISS'),:b76:b77,:b78:b79,TO_DATE(:b80:b81,'YYYYMMDD'),:b82:b83,:b84:b85,:b86:b87,:b88:b89,:b90:b91,:b92,:b93,TO_DATE(:b94:b95,'YYYYMMDD'),:b96:b97,:b98:b99,:b100:b101,:b102:b103,:b104:b105,:b106:b107,:b108:b109,:b110:b111,:b112:b113,:b114:b115,:b116:b117,:b118:b119,:b120:b121,:b122:b123,:b124:b125,:b126:b127,:b128:b129,:b130:b131,:b132:b133,TO_DATE(:b134:b135,'YYYYMMDD'),:b136:b137,:b138:b139,:b140:b141,:b142:b143,:b144:b145,:b146:b147,:b148:b149,:b150:b151,:b152:b153,:b154:b155,:b156:b157,:b158:b159,:b160:b161,:b162:b163,:b164:b165,:b166:b167,:b168:b169,:b170:b171,:b172:b173,:b174:b175,:b176:b177,:b178:b179,:b180:b181,:b182:b183,:b184:b185,:b186:b187,:b188:b189,:b190:b191,:b192:b193,:b194:b195,:b196:b197,:b198:b199,:b200:b201)

END OF STMT

PARSE #11529215045668893824:c=0,e=1076,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=26375808573637

The trace file contains 15 EXEC lines for that cursor id. They start with: EXEC #11529215045668893824

So it seems to me that the statement was executed 15 times.

But in tkprof there is entry for that sql_id:

SQL ID: 0um91dczrf9k6 Plan Hash: 0

insert into CHARGE (BAN,ENT_SEQ_NO,ACTV_SEQ_NO,SYS_CREATION_DATE,

SYS_UPDATE_DATE,OPERATOR_ID,APPLICATION_ID,DL_SERVICE_CODE,DL_UPDATE_STAMP,

ACTV_CODE,ACTV_REASON_CODE,ACTV_DATE,ACTV_AMT,ACTV_BILL_SEQ_NO,

CHG_CREATION_DATE,FEATURE_CODE,FTR_REVENUE_CODE,BALANCE_IMPACT_CODE,

CREDIT_LEVEL,SOURCE_APPL_CODE,PRIOD_CVRG_ST_DATE,PRIOD_CVRG_ND_DATE,

EFFECTIVE_DATE,INV_SEQ_NO,SUBSCRIBER_NO,SOC,SOC_DATE,SERVICE_FTR_SEQ_NO,

SERVICE_TYPE,NO_OF_INSTALL_FROM,TOTAL_NO_OF_INSTALL,TAX_CODE,

TAX_PERCENT_RATE,TAX_EFFECTIVE_DATE,MONTHLY_RATE,DISCOUNT_PCT,QUANTITY,

LAST_RG_RC_DATE,BILL_COMMENT,AU_ISSUE_CODE,ACTION_DIRECTION_CD,CONV_RUN_NO,

CHANNEL_SEIZURE_DT,MESSAGE_SWITCH_ID,MEMO_ID,CYCLE_MONTH_ST_DATE,

LYT_QLF_RT_PRICE,ADJUSTED_AMT,PREV_ADJUSTED_AMT,DSPT_ADJ_AMT,

DSPT_NON_ADJ_AMT,BEN,CHARGE_HIST_IND,AU_EFF_DATE,CHG_PRORATION_FACTOR,

TAX_AMT,BL_IGNORE_IND,ASGN_TO_BILL_APPL_CD,SOC_VER_NO,SOC_SEQ_NO,

PERIOD_CODE,PROVIDER_ID,BL_SERVICE_GROUP,FREE_MINS_USED,FREE_CALLS_USED,

PRODUCT_TYPE,EU_ACTV_AMT,EU_MONTHLY_RATE,EU_ADJUSTED_AMT,EU_PREV_ADJUSTED,

EU_DSPT_ADJ_AMT,EU_DSPT_NON_ADJ_AMT,EU_TAX_AMT,AU_BREAKDOWN_DATE,

CALLS_DURATION,NUMBER_OF_CALLS,X_SUBSCRIBER_NR,DOCUMENT_NUMBER,

PRICE_PLAN_CODE,CALL_GROUP,SENDER,FILE_SEQ_NO,INV_TYPE,SP_ENT_SEQ_NO,

BILL_ADD_COMMENTS,APN,DISP_UOM_CODE,QUANTITY_TYPE,RC_CRDT_AMT,

EU_RC_CRDT_AMT,CHAR_ADDITIONAL_INFO,CHG_APPLY_POINTS,FREE_TEXT_SOC,

FREE_TEXT_FEATURE_CD,EU_VALID_AMT,UNUSED_DISC_AMT,UNUSED_DISC_EU_AMT,

ORIG_DISCOUNT_AMT,ORIG_DISCOUNT_EU_AMT,BILL_DISPLAY_IND,IM_ROLLED_PRD_1,

IM_ROLLED_PRD_2,CALL_DUR_REAL,CALL_DUR_ROUNDED,MSISDN,FM_TYPE,TURNOVER_IND)

values

(:b0,:b1,:b2,SYSDATE,null ,:b3:b4,:b5:b6,:b7:b8,:b9:b10,:b11:b12,:b13:b14,

TO_DATE(:b15:b16,'YYYYMMDD'),:b17,:b18,TO_DATE(:b19:b20,'YYYYMMDD'),

:b21:b22,:b23:b24,:b25,:b26:b27,:b28:b29,TO_DATE(:b30:b31,'YYYYMMDD'),

TO_DATE(:b32:b33,'YYYYMMDD'),TO_DATE(:b34:b35,'YYYYMMDD'),:b36:b37,:b38:b39,

:b40:b41,TO_DATE(:b42:b43,'YYYYMMDD'),:b44:b45,:b46:b47,:b48:b49,:b50:b51,

:b52:b53,:b54:b55,TO_DATE(:b56:b57,'YYYYMMDD'),:b58:b59,:b60:b61,:b62:b63,

TO_DATE(:b64:b65,'YYYYMMDD'),:b66:b67,:b68:b69,:b70:b71,:b72:b73,

TO_DATE(:b74:b75,'YYYYMMDDHH24MISS'),:b76:b77,:b78:b79,TO_DATE(:b80:b81,

'YYYYMMDD'),:b82:b83,:b84:b85,:b86:b87,:b88:b89,:b90:b91,:b92,:b93,

TO_DATE(:b94:b95,'YYYYMMDD'),:b96:b97,:b98:b99,:b100:b101,:b102:b103,

:b104:b105,:b106:b107,:b108:b109,:b110:b111,:b112:b113,:b114:b115,

:b116:b117,:b118:b119,:b120:b121,:b122:b123,:b124:b125,:b126:b127,

:b128:b129,:b130:b131,:b132:b133,TO_DATE(:b134:b135,'YYYYMMDD'),:b136:b137,

:b138:b139,:b140:b141,:b142:b143,:b144:b145,:b146:b147,:b148:b149,

:b150:b151,:b152:b153,:b154:b155,:b156:b157,:b158:b159,:b160:b161,

:b162:b163,:b164:b165,:b166:b167,:b168:b169,:b170:b171,:b172:b173,

:b174:b175,:b176:b177,:b178:b179,:b180:b181,:b182:b183,:b184:b185,

:b186:b187,:b188:b189,:b190:b191,:b192:b193,:b194:b195,:b196:b197,

:b198:b199,:b200:b201)

call count cpu elapsed disk query current rows

---

Parse 22 0.00 0.00 0 0 0 0

Execute 165 25.08 654.00 252 68 2728 165

Fetch 0 0.00 0.00 0 0 0 0

---

total 187 25.08 654.00 252 68 2728 165

which shows that sql has been 165 times executed.

Also, what is even worse, TTB timings for that query is completely different than one in tkprof

Regardless the fact that even 165 execution of one row in table should not be too long, timings are pretty different.

Please look in line 1110 of excel file and you will see that really this statement is lasting so long

Tim is in microseconds, so line, of trace file, there is:

Line 36656: PARSE #11529215045668893824:c=0,e=1076,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=26375808573637

And

Line 284530: EXEC #11529215045668893824:c=83870000,e=2048188431,p=1233,cr=45536,cu=18,mis=1,r=1,dep=0,og=1,plh=0,tim=26377856794348

Those numbers return (26377856794348-26375808573637)/1000000=2048.188431s, as it is in mine numbers in Excel, what is only for this one run, and this is far far more than entry in tkrpof.

And if you summarize all elapsed data, you do not get the whole number of seconds, not even closer.

There are other numbers that differ really far too much, so let us focus on this example, what might explain all other misunderstandings

Just checked all cursors for sql_id = 0um91dczrf9k6, and there are, since 11g (didn’t know until now) that in same trace file may have differend cursor ID.

So for each occurance of cursor ID, in notepad++ put this as a search patern:

EXEC #11529215045668893824|EXEC #11529215045668870656|EXEC #11529215045666891304|EXEC #11529215045667083928|EXEC #11529215045668547312|EXEC #11529215045668871704|EXEC #11529215045668644096|EXEC #11529215045667067984|EXEC #11529215045668593504|EXEC #11529215045667346424 |EXEC #11529215045668867760 |EXEC #11529215045668668496 |EXEC #11529215045666957888 |EXEC #11529215045668605048 |EXEC #11529215045667033848 |EXEC #11529215045669292664 |EXEC #11529215045667036552 |EXEC #11529215045668660424 |EXEC #11529215045669317056 |EXEC #11529215045667071512 |EXEC #11529215045668872752 |EXEC #11529215045667362488

I got 76 hits:

   Line 284530: EXEC #11529215045668893824:c=83870000,e=2048188431,p=1233,cr=45536,cu=18,mis=1,r=1,dep=0,og=1,plh=0,tim=26377856794348

   Line 285024: EXEC #11529215045668893824:c=140000,e=2624163,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377859621006

   Line 285728: EXEC #11529215045668893824:c=140000,e=2413470,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377863581255

   Line 286280: EXEC #11529215045668893824:c=130000,e=2679444,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377866733332

   Line 286770: EXEC #11529215045668893824:c=140000,e=2838723,p=5,cr=1,cu=25,mis=0,r=1,dep=0,og=1,plh=0,tim=26377869715977

   Line 287267: EXEC #11529215045668893824:c=110000,e=2453272,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377872385530

   Line 288894: EXEC #11529215045668893824:c=170000,e=7101492,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377886769904

   Line 291349: EXEC #11529215045668893824:c=140000,e=2837662,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377903704000

   Line 291836: EXEC #11529215045668893824:c=150000,e=3036948,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377906841364

   Line 292531: EXEC #11529215045668893824:c=160000,e=5915306,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26377914644794

   Line 293026: EXEC #11529215045668893824:c=180000,e=7555395,p=0,cr=0,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26377922346563

   Line 325494: EXEC #11529215045668893824:c=130000,e=2499590,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26378150557251

   Line 356231: EXEC #11529215045668893824:c=130000,e=2498295,p=0,cr=1,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26378387367191

   Line 470267: EXEC #11529215045668893824:c=160000,e=5862413,p=4,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26379321865385

   Line 470757: EXEC #11529215045668893824:c=160000,e=5777847,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26379327744777

   Line 490549: EXEC #11529215045668870656:c=140000,e=2577010,p=5,cr=1,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26379492020981

   Line 491041: EXEC #11529215045668870656:c=140000,e=2531761,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26379494722075

   Line 505653: EXEC #11529215045668870656:c=140000,e=3717849,p=0,cr=1,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26379607747752

   Line 513186: EXEC #11529215045668870656:c=150000,e=4590798,p=4,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26379660080063

   Line 513671: EXEC #11529215045668870656:c=140000,e=3273142,p=0,cr=0,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26379663481872

   Line 560089: EXEC #11529215045666891304:c=140000,e=2703383,p=0,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26380009496981

   Line 587886: EXEC #11529215045666891304:c=150000,e=4013971,p=0,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26380261653216

   Line 596900: EXEC #11529215045666891304:c=160000,e=6143677,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26380349879659

   Line 662787: EXEC #11529215045667083928:c=160000,e=3641569,p=9,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26380987327947

   Line 663282: EXEC #11529215045667083928:c=150000,e=3129418,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26380990744147

   Line 663891: EXEC #11529215045667083928:c=150000,e=3123825,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26380994885559

   Line 664376: EXEC #11529215045667083928:c=150000,e=3286579,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26380998279863

   Line 664876: EXEC #11529215045667083928:c=160000,e=6835333,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381005350087

   Line 665359: EXEC #11529215045667083928:c=140000,e=2675836,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381008186965

   Line 701005: EXEC #11529215045668547312:c=140000,e=2996220,p=0,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381311668846

   Line 705954: EXEC #11529215045668547312:c=130000,e=3092864,p=4,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381347125520

   Line 706447: EXEC #11529215045668547312:c=130000,e=2688499,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381350016758

   Line 707693: EXEC #11529215045668547312:c=180000,e=7128606,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381366278283

   Line 708181: EXEC #11529215045668547312:c=150000,e=5263576,p=0,cr=0,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26381371665935

   Line 708869: EXEC #11529215045668547312:c=160000,e=3063050,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381376135916

   Line 709355: EXEC #11529215045668547312:c=150000,e=3451240,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381379757758

   Line 716346: EXEC #11529215045668547312:c=130000,e=2716060,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381438296861

   Line 717651: EXEC #11529215045668547312:c=130000,e=2735528,p=0,cr=1,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26381446123939

   Line 719953: EXEC #11529215045668547312:c=150000,e=3231761,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381460227765

   Line 720649: EXEC #11529215045668547312:c=150000,e=2836497,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381464519648

   Line 721343: EXEC #11529215045668547312:c=140000,e=3211680,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381469267135

   Line 722037: EXEC #11529215045668547312:c=140000,e=2602188,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381473131430

   Line 739346: EXEC #11529215045668871704:c=150000,e=2778997,p=4,cr=1,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26381616382093

   Line 739838: EXEC #11529215045668871704:c=140000,e=2515720,p=0,cr=1,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26381619043704

   Line 741298: EXEC #11529215045668871704:c=150000,e=2398796,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381629130133

   Line 741787: EXEC #11529215045668871704:c=150000,e=4361446,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381633602727

   Line 742474: EXEC #11529215045668871704:c=120000,e=2462594,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381637295264

   Line 742959: EXEC #11529215045668871704:c=140000,e=2367459,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381639754340

   Line 767183: EXEC #11529215045668871704:c=150000,e=2713976,p=9,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381816442508

   Line 767668: EXEC #11529215045668871704:c=150000,e=2867717,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381819405109

   Line 778744: EXEC #11529215045668871704:c=150000,e=3215262,p=2,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381928956254

   Line 779229: EXEC #11529215045668871704:c=150000,e=2925708,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26381932001683

   Line 804027: EXEC #11529215045668870656:c=30000,e=574654,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2830013948,tim=26382127844581

   Line 828239: EXEC #11529215045668870656:c=20000,e=448328,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2830013948,tim=26382316913418

   Line 836515: EXEC #11529215045668870656:c=20000,e=394279,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2830013948,tim=26382377214045

   Line 844125: EXEC #11529215045668644096:c=180000,e=7299236,p=4,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26382492920546

   Line 844650: EXEC #11529215045668644096:c=200000,e=17264815,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26382510553379

   Line 878875: EXEC #11529215045667067984:c=150000,e=3122296,p=4,cr=3,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26382769985060

   Line 879370: EXEC #11529215045667067984:c=160000,e=3615038,p=0,cr=1,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26382773753750

   Line 897559: EXEC #11529215045667067984:c=160000,e=2769571,p=8,cr=1,cu=25,mis=0,r=1,dep=0,og=1,plh=0,tim=26382908781972

   Line 898045: EXEC #11529215045667067984:c=170000,e=2836070,p=0,cr=0,cu=18,mis=0,r=1,dep=0,og=1,plh=0,tim=26382911719434

   Line 923106: EXEC #11529215045668593504:c=140000,e=3106473,p=4,cr=1,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383131866852

   Line 923600: EXEC #11529215045668593504:c=150000,e=3088096,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383135097267

   Line 924399: EXEC #11529215045668593504:c=150000,e=4912031,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383142333999

   Line 925068: EXEC #11529215045668593504:c=150000,e=3218170,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383147003513

   Line 926362: EXEC #11529215045668593504:c=140000,e=2655841,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383154654143

   Line 926847: EXEC #11529215045668593504:c=140000,e=2756460,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383157512135

   Line 927542: EXEC #11529215045668593504:c=170000,e=6379999,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383165067197

   Line 928029: EXEC #11529215045668593504:c=140000,e=3857232,p=0,cr=0,cu=16,mis=0,r=1,dep=0,og=1,plh=0,tim=26383169018510

   Line 1362897: EXEC #11529215045668871704:c=130000,e=2663633,p=1,cr=4,cu=22,mis=0,r=3,dep=0,og=1,plh=0,tim=26386856652084

   Line 1377979: EXEC #11529215045668871704:c=150000,e=3080961,p=1,cr=3,cu=25,mis=0,r=20,dep=0,og=1,plh=0,tim=26386994123044

   Line 1378908: EXEC #11529215045668871704:c=180000,e=6884905,p=0,cr=0,cu=19,mis=0,r=4,dep=0,og=1,plh=0,tim=26387003995537

   Line 1392917: EXEC #11529215045668871704:c=140000,e=3317123,p=5,cr=5,cu=23,mis=0,r=20,dep=0,og=1,plh=0,tim=26387111694074

   Line 1402354: EXEC #11529215045668871704:c=140000,e=2397525,p=5,cr=1,cu=19,mis=0,r=3,dep=0,og=1,plh=0,tim=26387175221684

   Line 1410372: EXEC #11529215045668871704:c=150000,e=3038876,p=8,cr=2,cu=19,mis=0,r=15,dep=0,og=1,plh=0,tim=26387226871116

   Line 1423760: EXEC #11529215045668871704:c=270000,e=23341546,p=8,cr=1,cu=19,mis=0,r=12,dep=0,og=1,plh=0,tim=26387390911672

And again this is far from 165 from tkprof results…

Working with Norm, we got that 165 is correct number of execution times but timings is not even clear in tkprof (do not show recursive calls) and in trace analzer it is little closer ...

And the best of all TTB do not have any of those occurances at all, what I find also as big missunderstanding of whole case.

Last but not least, when AWR do not show any blocking sessions, how come one inser tlast so long#

Hope you will find this interested and help me finding the cause of the mine wrong assumptions.

Brg,**
________________________**

Damir Vadas
http://damir-vadas.blogspot.com

It does not matter what you have in your life, but who!

Razmislite o čuvanju okoliša prije nego odštampate ovaj e-mail
Please consider the environment before printing this email

On Tue, Nov 7, 2017 at 4:24 PM, John Dorlon bounce-jdorlon@toadworld.com wrote:

RE: Oracle Trace Files - finally documented. Free eBook.

Reply by John Dorlon
Damir,

If you’ve found a bug, let me know the details. Norm and I did talk about your file.

-John

To reply, please reply-all to this email.

Stop receiving emails on this subject.

Or Unsubscribe from Toad for Oracle Forum notifications altogether.

Toad for Oracle - Discussion Forum

Flag this post as spam/abuse.

[JohnDorlon]

I’ll reply to you privately so we don’t hijack Norm’s thread.

[NormTeamT]

Evening All,

I’ve updated the Trace Files eBook again - and it’s still free!

The changes this time are to do with the PARSING IN CURSOR lines, and better explain the UID and LID parameters which refer to login ID and User ID. I have been testing with a proxy user account (logging in to Toad as user norman[dunbar]) and checking out what gets generated in trace files under this configuration. In a nutshell, both UID and LID get set to the proxy user, ‘dunbar’ in this case and not the login user ‘norman’. Strange that we have two parameters but both are the same. At least, for now. Maybe Oracle 18 will differ? This was tested on 12c (12.1).

As ever, to obtain your free copy, still with pretty pictures and a working index, goto:
https://github.com/NormanDunbar/OracleTraceFilesExplained/blob/master/OracleTraceFilesExplained.pdf

Wait for the pdf to appear, then click the download button.

Enjoy.

[damir.vadas_250]

Thx Norm.

[NormTeamT]

AfternoonAll,

I’ve updated the Trace Files eBook yet again - and it’s still free!

The changes this time are to do with:

• PARSE ERROR lines, to better explain the UID and LID parameters which refer to login ID and User ID.
• The appendix about Oracle Data Types has been updated with even more details of additional data types, plus a few more details about where there are inconsistencies between DBA_TAB_COLS, V$SQL_BIND_CAPTURE and what you actually see in trace files.
  As ever, to obtain your free copy, still with pretty pictures and a working index, goto:

github.com/…/OracleTraceFilesExplained.pdf

Wait a few seconds for the pdf to start to appear, then click the download button. YOu don;t have to wait for the entire file to display before clicking the button.

Enjoy.

[JohnDorlon]

Thanks Norm!

[mst_11133]

Nice & Thanks

2018-05-25 16:01 GMT+02:00 John Dorlon bounce-jdorlon@toadworld.com:

RE: Oracle Trace Files - finally documented. Free eBook.

Reply by John Dorlon
Thanks Norm!

To reply, please reply-all to this email.

Stop receiving emails on this subject.

Or Unsubscribe from Toad for Oracle Forum notifications altogether.

Toad for Oracle - Discussion Forum

Flag this post as spam/abuse.

--
Mette Stephansen

Miracle Expert ServicesMiracle A/S
Borupvang 2C, 2750 Ballerup

53 74 72 26

[damir.vadas_250]

Thx Norm a lot.

[NormTeamT]

Sorry folks, another update to the book.

https://github.com/NormanDunbar/OracleTraceFilesExplained/blob/master/OracleTraceFilesExplained.pdf is where to go to get your free copy. Just wait for the page to start loading, then click the download button, there’s no need to wait for the file to appear on screen.

Latest changes are:

• Corrected details for UNMAP. These were incorrect and related to SORT UNMAP instead. Which was missing.
• Added a section on SORT UNMAP.
• Added a small section on TIM values.
• Noted that any SQL with a password in it will be obfuscated in PARSE ERROR lines.
• Noted that ERROR lines only relate to EXEC or FETCH operations.
  Enjoy.

[NormTeamT]

If I may be permitted to "blow my own trumpet" again.....

I have uploaded an updated version of the Oracle Trace Files Explained eBook to https://github.com/NormanDunbar/OracleTraceFilesExplained/releases/latest where you can download the latest PDF file, and/or, the source code that I used to build it. (It's LaTeX!)

The updates are:

• To bring the document up to Oracle 12c standards as there have been a few changes in 12c trace files, especially with multi-tenant databases;
• Hopefully, I've made the section on child cursors a little clearer;
• Many spelling erors (!) corrected.

Oh yes, the index is back! It had gone missing for some reason.

Help yourselves and enjoy.

Cheers,
Norm. [TeamT]