Link to home
Start Free TrialLog in
Avatar of JonahGroup
JonahGroupFlag for Canada

asked on

Reading ASE Optimizer trace flag / switch output

Hello,

I would like to be able to better understand how to read ASE (v15.7) switch / trace flag output.  For example, when these options and flags are set (below), the optimizer grinds through many permutations of possible query plans and join orders, etc., and it dumps out a lot of trace information.
set option show_log_props normal
set option show_parallel normal
set option show_lio_costing normal
set option show_pio_costing normal
set option show_pll_costing normal
set option show_search_engine normal
set plan opttimeoutlimit 10
set parallel_degree 1
set statistics plancost on
set statistics io, time on
set showplan on
set switch on 3604, 317, 302

Open in new window

Sample output:
START NEW COSTING
( PopSort ( PopInsert ( PopSort ( PopNlJoin ( PopNlJoin ( PopNlJoin ( PopIndScan SCOTTX_CLCH_LKP SCOTT_CLCH_CHANGED_CLAIM CLCH ) ( PopRidJoin ( PopIndScan CMCX_CLCL_PRIMARY CMC_CLCL_CLAIM_H1 CLCL ) ) ) ( PopRidJoin ( PopIndScan CMCX_MEPE_PRIMARY CMC_MEPE_PRCS_ELIG_H1 MEPE ) ) ) ( PopRidJoin ( PopIndScan CMCX_PDPD_PRIMARY CMC_PDPD_PRODUCT_H1 PDPD ) ) ) ) ) ) cost: [C=0 A=0 1] tempdb:0 order: {1,6,17,18,23} part: Roundrobin-ins :{} Degree(s):[1] Has BmoS
ort 
START BUFFER CACHE COSTING
END BUFFER CACHE COSTING
START POP PIO COSTING
START: Parallel Costing of PopSort
	lio:6 pio:0 cpu:1
	Parallel cost: [C=0 A=3.025 1] 
	Calculating critical cost from child
	Listing 1 child vector(s)
		Child-Pop PopInsert TsRes{ 529232 529232 264098.9 0 }
		Child's critical cost: 0 Child's curr critical cost: 613688.5
	Cost Summary:
		TsRes{ 529232 529232 264111 0 }SsRes{ 0.001873639 }
		cost: [path: 613700.6 work: 198335.8 est: 812036.3 deg: 1]
END: Parallel Costing of PopSort
END POP PIO COSTING
END NEW COSTING

( PopSort ( PopInsert ( PopSort ( PopNlJoin ( PopNlJoin ( PopNlJoin ( PopIndScan SCOTTX_CLCH_LKP SCOTT_CLCH_CHANGED_CLAIM CLCH ) ( PopRidJoin ( PopIndScan CMCX_CLCL_PRIMARY CMC_CLCL_CLAIM_H1 CLCL ) ) ) ( PopRidJoin ( PopIndScan CMCX_MEPE_PRIMARY CMC_MEPE_PRCS_ELIG_H1 MEPE ) ) ) ( PopRidJoin ( PopIndScan CMCX_PDPD_PRIMARY CMC_PDPD_PRODUCT_H1 PDPD ) ) ) ) ) ) cost: [C=613700.6 A=198335.8 1] O(L6,P0,C1) tempdb:0.01904297 order: {1,6,17,18,23} part: Roundr
obin-ins :{} Degree(s):[1] Has BmoSort 
	... Pop enforcers:
	( PopSort ( PopInsert ( PopSort ( PopNlJoin ( PopNlJoin ( PopNlJoin ( PopIndScan SCOTTX_CLCH_LKP SCOTT_CLCH_CHANGED_CLAIM CLCH ) ( PopRidJoin ( PopIndScan CMCX_CLCL_PRIMARY CMC_CLCL_CLAIM_H1 CLCL ) ) ) ( PopRidJoin ( PopIndScan CMCX_MEPE_PRIMARY CMC_MEPE_PRCS_ELIG_H1 MEPE ) ) ) ( PopRidJoin ( PopIndScan CMCX_PDPD_PRIMARY CMC_PDPD_PRODUCT_H1 PDPD ) ) ) ) ) ) cost: [C=613700.6 A=198335.8 1] O(L6,P0,C1) tempdb:0.01904297 order: {1,6,17,18,23} part: Round
robin-ins :{} Degree(s):[1] Has BmoSort 
	
	... PopLet enforcers:
	... done eager enforcement.

Eqc competition ...
	initial old Pops:
	initial new Pops:
	( PopSort ( PopInsert ( PopSort ( PopNlJoin ( PopNlJoin ( PopNlJoin ( PopIndScan SCOTTX_CLCH_LKP SCOTT_CLCH_CHANGED_CLAIM CLCH ) ( PopRidJoin ( PopIndScan CMCX_CLCL_PRIMARY CMC_CLCL_CLAIM_H1 CLCL ) ) ) ( PopRidJoin ( PopIndScan CMCX_MEPE_PRIMARY CMC_MEPE_PRCS_ELIG_H1 MEPE ) ) ) ( PopRidJoin ( PopIndScan CMCX_PDPD_PRIMARY CMC_PDPD_PRODUCT_H1 PDPD ) ) ) ) ) ) cost: [C=613700.6 A=198335.8 1] O(L6,P0,C1) tempdb:0.01904297 order: {1,6,17,18,23} part: Round
robin-ins :{} Degree(s):[1] Has BmoSort 
	
	( PopInsert ( PopSort ( PopMergeJoin ( PopSort ( PopNlJoin ( PopNlJoin ( PopIndScan SCOTTX_CLCH_LKP SCOTT_CLCH_CHANGED_CLAIM CLCH ) ( PopRidJoin ( PopIndScan CMCX_CLCL_PRIMARY CMC_CLCL_CLAIM_H1 CLCL ) ) ) ( PopStoreInd ( PopRidJoin ( PopIndScan AS_OF_TO_DATES CMC_PDPD_PRODUCT_H1 PDPD ) ) ) ) ) ( PopRidJoin ( PopIndScan CMCX_MEPE_PRIMARY CMC_MEPE_PRCS_ELIG_H1 MEPE ) ) ) ) ) cost: [C=2.605495e+08 A=7.159485e+07 1] O(L1.002075,P1.002075,C10.02075) tempdb
:0.01708984 order: <1,6,18,17,23> part: Roundrobin-ins :{} Degree(s):[1] 
	
	( PopInsert ( PopSort ( PopNlJoin ( PopMergeJoin ( PopNlJoin ( PopIndScan SCOTTX_CLCH_LKP SCOTT_CLCH_CHANGED_CLAIM CLCH ) ( PopRidJoin ( PopIndScan CMCX_MEPE_PRIMARY CMC_MEPE_PRCS_ELIG_H1 MEPE ) ) ) ( PopRidJoin ( PopIndScan CMCX_CLCL_PRIMARY CMC_CLCL_CLAIM_H1 CLCL ) ) ) ( PopRidJoin ( PopIndScan CMCX_PDPD_PRIMARY CMC_PDPD_PRODUCT_H1 PDPD ) ) ) ) ) cost: [C=5.428407e+12 A=1.498255e+12 1] O(L1.002075,P1.002075,C10.02075) tempdb:0.01708984 order: <1,6,1
8,17,23> part: Roundrobin-ins :{} Degree(s):[1] 
	
	( PopInsert ( PopSort ( PopNlJoin ( PopNlJoin ( PopMergeJoin ( PopSort ( PopXchg ( PopTabScan CMC_CLCL_CLAIM_H1 CLCL ) ) ) ( PopIndScan SCOTTX_CLCH_LKP SCOTT_CLCH_CHANGED_CLAIM CLCH ) ) ( PopRidJoin ( PopIndScan CMCX_MEPE_PRIMARY CMC_MEPE_PRCS_ELIG_H1 MEPE ) ) ) ( PopRidJoin ( PopIndScan CMCX_PDPD_PRIMARY CMC_PDPD_PRODUCT_H1 PDPD ) ) ) ) ) cost: [C=1.641668e+08 A=6.27999e+07 1] O(L1.002075,P1.002075,C10.02075) tempdb:0.01708984 order: <1,6,18,17,23> p
art: Roundrobin-ins :{} Degree(s):[1] 

Open in new window

Are there any decent technical references or presentations for reading and understanding ASE optimizer trace output?
SOLUTION
Avatar of Joe Woodhouse
Joe Woodhouse

Link to home
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
Start Free Trial
Avatar of JonahGroup

ASKER

Hi Joe,

Thanks for the detailed response; I appreciate your assistance. You've provided some great Sybase help for me as far back as 2006; and not just by responding to my own questions, but many others.

I probably should not have cut & paste all the "set" commands I had been messing with, when my question was specifically about trace flag output, so I may have misled.

I have become reasonably good at reading and understanding query plans, lava trees, and sp_showoptstats output over the years. The original problem (now resolved) that led to my question, concerned the optimizer selecting a poor query plan. It turned out that the optimizer was just running out of time before coming across the better plan. By adjusting opttimeoutlimit, the issue was resolved. But also, by restricting the costing activities for parallelism (parallel_degree=1) instead of adjusting the timeout limit, the same outcome was obtained. This seems to have happened because the optimizer had less costing work to do by including parallelism strategies, and so it didn't reach the timeout limit, and found the better expected plan.

So my hypothesis is that it's just "bad luck" that the better plan was considered later than others, and was not found in time (still just a hypothesis). And this led me on a tangent of actually looking closely at all this trace output and wanting to understand it better, and how all the  optimizer's calculation pieces fit together.

These TechWave slides are (so far) the only real help I've come across about second-level optimizer diagnostics as you call them.

Sybase TechWave 2005: ASE116: ASE 15.0 QUERY TUNING
http://download.sybase.com/presentation/TW2005/ASE116.pdf

This presentation mentions and defines terms like: Lop, Pop, Optblock, Gt, Gc, Gti, Tc, Eqc.. But since I imagine the slides were part of an oral presentation, I know the presenter probably imparted some really great morsels of technical insight that just don't come across without the presenter's words. It would be great to get the audio for some of these TechWave conference lectures. I suppose I should start going to these conferences (just missed it for 2014).

I was hoping that somewhere out there, I might find a paper or textbook that explains all the second-level optimizer diagnostics. This would make a great textbook, and I'd happily pay $100 for it, if  someone would write it. BTW, it ought to include your broad description of 302/310/317  trace flags as a chapter intro; that was good!

Regards,
Scott.
ASKER CERTIFIED SOLUTION
Link to home
membership
This solution is only available to members.
To access this solution, you must be a member of Experts Exchange.
Start Free Trial
Thanks Joe. I'm in the process of digesting these techwave presentations, and experimenting with your suggestions, but it'll probably take a few weeks before I'm done.  I'll just close this now, and open another question if needed.  Thanks again!

Scott.