January 7, 2010 at 4:37 pm
Dear all,
I have a strange result from a trace and I don't know what to think of it.
I was asked to look into a commerce server application installed on sql2005 that behaves like a pig.
I don't know (and don't want to know) Commerce Server because last time I looked at it (ten years ago?), it was just a pig... that could not do anything properly and/or fast.
Never mind...
I ran a server side trace looking for anything taking 5 seconds or more on the production server.
The trace ran for one hour and I caught 175 instances of the same stored proc.
Fortunately, the DB was small so I took a copy of the last backup and restored it on my laptop.
There, I ran the stored proc while running a much "heavier" trace (via profiler).
I am not too sure if it is a Commerce Server standard but the stored proc is called dbo.ctlg_GetCategoryResults
It returns 175 rows in total from quite a small database.
The stored proc runs a INSERT / SELECT (too) complex query via some dynamic sql using a parametised query to populate a "pseudo" temporary table (named using @@SPID).
It then runs another Dynamic SQL to select the result.
What surprises me is that the trace claims there were 450,000 INSERT staements while I think it probably inserted at most 200 rows...
For just one execution lasting 6 seconds and returning 175 rows?
In My Trace, I selected
- events: Performance Statistics, RPC:Completed. SP:Completed, SP:Recompile, Exec Prepared SQL, SQL: Batch Completed
- columns: TextData, ApplicationName, CPU, Reads, Write, Duration, Database Name, and a couple more...
Why would Profiler lie to me?
After all these years? :crying:
Why so many entries in my trace?
Many Thanks
Eric
January 7, 2010 at 4:54 pm
Eric can you show us the proc text itself, and maybe post the execution plan of the proc when it runs? that would give us the critical diagnostic info, i think.
Lowell
January 8, 2010 at 3:27 am
Unfortunately, the proc is a little bit too complicated... but I have extracted the worst dynamic sql it generates
INSERT [MSCS_CatalogScratch].dbo.[CtlInv___CategorySearch___SortedResults__for_spid__58](#TmpCatalogoid#,rank,#TmpCatalogName#, FreeTextSearch_Rank,InventoryCondition,#Inv_SkuOid#)
Select A.#TmpCatalogoid#, B.rank, A.#TmpCatalogName#,NULL AS FreeTextSearch_Rank, P.InventoryCondition, P.SkuOid
FROM (
SELECT oid AS #TmpCatalogoid#, BaseCatalogName As #TmpCatalogName# FROM dbo.[CDC_BrowseCatalog_FR_fr-FR] WHERE (i_classtype=8)) AS A,
[MSCS_CatalogScratch].dbo.[CtlInv__CategorySearch___Results__for_spid__58] B,
(Select *
from (
Select BaseCatalogName, Oid, convert(uniqueidentifier, null) AS SkuOid, min(InventoryCondition) As InventoryCondition
FROM (Select CTLG.BaseCatalogName, CTLG.Oid
,case when INV.status is null then 3
when INV.status=0 then 3
when INV.status=2 then 0
when INV.OnHandQuantity>INV.StockOutThreshold THEN 0 ELSE 3
END InventoryCondition
FROM (
Select PTT.#TmpCatalogName# AS BaseCatalogName,PTT.#TmpCatalogoid# As oid,CTLG.ProductId
FROM [MSCS_CatalogScratch].dbo.[CtlInv__CategorySearch___Results__for_spid__58] PTT
,dbo.[CDC_BrowseCatalog_FR_LNG_NEUTRAL] CTLG
WHERE PTT.#TmpCatalogName# = CTLG.BaseCatalogName
AND PTT.#TmpCatalogoid# = CTLG.Oid
AND PTT.#Tmp_i_classtype# = 8 ) CTLG
inner join dbo.[CDC_InventoryCatalog_FR_InventorySkus] INV WITH (NOLOCK) ON CTLG.ProductId = INV.SkuId
AND INV.ProductCatalogName = N'CDC_BrowseCatalog_FR'
) INV
GROUP BY BaseCatalogName, Oid
) INV
WHERE InventoryCondition IN (0,1,2)) P
WHERE (A.#TmpCatalogoid# = B.#TmpCatalogoid# AND A.#TmpCatalogName# = B.#TmpCatalogName#)
AND (A.#TmpCatalogoid# = P.oid AND A.#TmpCatalogName# = P.BaseCatalogName)
OPTION (KEEPFIXED PLAN, loop join)
Hurray! I just discovered how to attach documents... The query plan should be attached
😉
January 8, 2010 at 3:40 am
Estimates differ a lot from actual row counts.
Are your statistics upto date? You have a few query hints to , i would recommend removing those at this stage, unless you know the specific reason why they are there.
-- Edit its the loop join hint that is really killing you , causing multiple scans of CDC_InventoryCatalog_FR_InventorySkus. Its probably scanning rather than seeking due to out of data stats. Does it even have a usable index ?
January 8, 2010 at 7:47 am
I was mostly intrigued by the fact that the trace had 450,000 entries for just one run, not really about the actual run/performance
I can't change much if any in that code since it is dynamic sql created by Commerce Server.
My question is more, why did the trace report so many actions while I don't think they actually happened?
Viewing 5 posts - 1 through 5 (of 5 total)
You must be logged in to reply to this topic. Login to reply