Friday, February 24, 2012

Execution time of outer join versus inner

I've got two "heavy" queries here below, that I think should give the same
result.
I expected the first to be slower, and Query Analyzer agrees with me in the
estimated cost in the execution plans it generates for the two queries, but
in reality it's quite the opposite - now I'd like to know why ;)
What they do is join a large table onto itself, with a subquery on the same
table in the join conditions.
The table has 988,123 rows, LogIndex is primary key, CardNo is indexed.
The difference is in the method of the join: INNER versus LEFT OUTER.
Query 1:
- estimated by Query Analyzer: cost 12015, rows: 312617
- reality: finishes in 19 seconds, returns 3148 rows
SELECT {some fields}
FROM CardLog t1 LEFT OUTER JOIN CardLog t2
ON t1.CardNo = t2.CardNo
AND ABS(t1.Credit - t2.Credit) <> t2.Amount
AND t2.LogIndex = (SELECT MIN(t3.LogIndex)
FROM CardLog T3
WHERE t3.cardno = t1.cardno
AND t3.logindex > t1.logindex)
WHERE (t2.[Action] IN (2, 3, 4, 5))
ORDER BY t2.LogIndex
Query 2:
- estimated by Query Analyzer: cost 245, rows: 1325
- reality: doesn't finish in 17 minutes (that's the longest I let it run)
SELECT {some fields...}
FROM CardLog t1 INNER JOIN CardLog t2
ON t1.CardNo = t2.CardNo
AND ABS(t1.Credit - t2.Credit) <> t2.Amount
AND t2.LogIndex = (SELECT MIN(t3.LogIndex)
FROM CardLog T3
WHERE t3.cardno = t1.cardno
AND t3.logindex > t1.logindex)
WHERE (t2.[Action] IN (2, 3, 4, 5))
ORDER BY t2.LogIndexHi
Have you looked at the actual execution plans to see what is happening?
You may want to also make sure that the statistics are up-to-date.
You may also want to look at adding t2.logindex > t1.logindex to your join
criteria and seeing if that makes a difference and also possibly seeing if a
composite index helps. You may want to check that moving to the where clause
does not have any effect ABS(t1.Credit - t2.Credit) <> t2.Amount
John
"Lucvdv" <replace_name@.null.net> wrote in message
news:9c6rh1dgk3332ot7amhig4bromis937a4g@.
4ax.com...
> I've got two "heavy" queries here below, that I think should give the same
> result.
> I expected the first to be slower, and Query Analyzer agrees with me in
> the
> estimated cost in the execution plans it generates for the two queries,
> but
> in reality it's quite the opposite - now I'd like to know why ;)
> What they do is join a large table onto itself, with a subquery on the
> same
> table in the join conditions.
> The table has 988,123 rows, LogIndex is primary key, CardNo is indexed.
> The difference is in the method of the join: INNER versus LEFT OUTER.
> Query 1:
> - estimated by Query Analyzer: cost 12015, rows: 312617
> - reality: finishes in 19 seconds, returns 3148 rows
> SELECT {some fields}
> FROM CardLog t1 LEFT OUTER JOIN CardLog t2
> ON t1.CardNo = t2.CardNo
> AND ABS(t1.Credit - t2.Credit) <> t2.Amount
> AND t2.LogIndex = (SELECT MIN(t3.LogIndex)
> FROM CardLog T3
> WHERE t3.cardno = t1.cardno
> AND t3.logindex > t1.logindex)
> WHERE (t2.[Action] IN (2, 3, 4, 5))
> ORDER BY t2.LogIndex
> Query 2:
> - estimated by Query Analyzer: cost 245, rows: 1325
> - reality: doesn't finish in 17 minutes (that's the longest I let it run)
> SELECT {some fields...}
> FROM CardLog t1 INNER JOIN CardLog t2
> ON t1.CardNo = t2.CardNo
> AND ABS(t1.Credit - t2.Credit) <> t2.Amount
> AND t2.LogIndex = (SELECT MIN(t3.LogIndex)
> FROM CardLog T3
> WHERE t3.cardno = t1.cardno
> AND t3.logindex > t1.logindex)
> WHERE (t2.[Action] IN (2, 3, 4, 5))
> ORDER BY t2.LogIndex|||Try to separate the subquery using a temporary table, like this:
CREATE TABLE #CardLogSequence (
LogIndex int PRIMARY KEY,
NextLogIndex int NOT NULL UNIQUE
)
INSERT INTO #CardLogSequence
SELECT LogIndex, NextLogIndex
FROM (
SELECT t1.LogIndex, (
SELECT MIN(t3.LogIndex)
FROM CardLog t3
WHERE t3.CardNo = t1.CardNo
AND t3.LogIndex > t1.LogIndex
) as NextLogIndex
FROM CardLog t1
) X WHERE NextLogIndex IS NOT NULL
SELECT {some columns...}
FROM #CardLogSequence s
INNER JOIN CardLog t1 ON t1.LogIndex=s.LogIndex
INNER JOIN CardLog t2 ON t2.LogIndex=s.NextLogIndex
WHERE ABS(t1.Credit - t2.Credit) <> t2.Amount
AND t2.Action IN (2,3,4,5)
ORDER BY t2.LogIndex
DROP TABLE #CardLogSequence
(the above code is untested, because you didn't provide DDL as CREATE
TABLE statements)
What times are you getting with the above queries ?
Razvan|||On 7 Sep 2005 02:22:01 -0700, "Razvan Socol" <rsocol@.gmail.com> wrote:

> Try to separate the subquery using a temporary table, like this:
<snip>
> What times are you getting with the above queries ?
1 minute 45 seconds on the first run, 32 seconds if I restart it
immediately.
The LEFT version without a subquery still finishes in 17 seconds.
I had expected some difference when running the query a second time
(everything cached in RAM), but not that much.|||On Wed, 7 Sep 2005 10:10:00 +0100, "John Bell" <jbellnewsposts@.hotmail.com>
wrote:

> Hi
> Have you looked at the actual execution plans to see what is happening?
Yes, and even there it looks like the LEFT version should be slower
(looking at what it's doing and how many times).

> You may want to check that moving to the where clause
> does not have any effect ABS(t1.Credit - t2.Credit) <> t2.Amount
I had put it there initially, but that was in Enterprise Manager, and it
moved it into the join criteria by itself when I started the query.
Now I checked it both ways in QA, and the execution plans it generates are
identical.|||Execute sp_updatestats to make sure the statistics are up-to-date.
Which of the two statements in my previous post is taking more time
(the insert or the final select) ?
Please post the execution plan, obtained using SET SHOWPLAN_TEXT. The
graphical execution plan produced by Query Analyzer would be easier to
understand (and contains more information, like the number of rows
affected by each step), but make sure it's a small file (preferably,
PNG) if you post it as an attachment.
Razvan|||On 7 Sep 2005 22:10:37 -0700, "Razvan Socol" <rsocol@.gmail.com> wrote:

> Execute sp_updatestats to make sure the statistics are up-to-date.
Done.

> Which of the two statements in my previous post is taking more time
> (the insert or the final select) ?
The insert takes nearly all. In a few runs:
Insert: 28-31 sec
Total: 35-37 sec
That's after changing to a fixed table instead of a temporary (see below,
at execution plan).

> Please post the execution plan, obtained using SET SHOWPLAN_TEXT. The
> graphical execution plan produced by Query Analyzer would be easier to
> understand (and contains more information, like the number of rows
> affected by each step), but make sure it's a small file (preferably,
> PNG) if you post it as an attachment.
Thanks for the help so far.
But don't waste too much time on it unless you're interested yourself, it's
not as if my job depends on it.
I'll mix some results from the graph into the text version.
The | at the left margin are just there to tell my newsreader not to wrap
those lines, if you have one where you can turn wrapping off it might be
better readable that way.
1) LEFT join:
| |--Parallelism(Gather Streams, ORDER BY:([t2].[LogIndex] ASC))
Estimated row count: 312,617
Estimated subtree cost: 12,041
| |--Sort(ORDER BY:([t2].[LogIndex] ASC))
| |--Filter(WHERE:((([t2].[Action]=5 OR [t2].[Action]=4) OR [t2].[Action]=3) OR [t2].[Action]=2)
)
| |--Nested Loops(Left Outer Join, OUTER REFERENCES:([t1].[Credit], [t1].[LogIndex],
[t1].[CardNo]))
Estimated row count: 988,123
Estimated row size: 110
Estimated CPU cost: 2.07
Estimated number of executes: 1
Estimated cost: 2.065804
Estimated subtree cost: 11989
| |--Clustered Index Scan(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[PK__C
ardLog__1A14E395] AS [t1]))`
Est row count: 988,123
Est row size: 53
Est I/O cost: 4.15
Est CPU cost: 0.453
Est # executes: 1.0
Est subtree cost: 4.69
| |--Nested Loops(Inner Join, OUTER REFERENCES:([Expr1
003]))
Est row count: 1
Est row size: 66
Est CPU cost: 0.00004
Est # executes: 988,123
Est cost: 5.30
Est subtree cost: 11982
| |--Stream Aggregate(DEFINE:([Expr1003]=MIN([T3].[LogIndex
])))
| | |--Top(1)
| | |--Index S(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[IxCardLogCard] AS [T3]), SEEK:([T3].[CardNo]=[t1].[
CardNo] AND [T3].[LogIndex] > [t1].[LogIndex]) ORDERED FORWARD)
Est row count: 1
Est row size: 33
Est # executes: 988,123
Est cost: 5789
| |--Clustered Index S(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[PK__CardLog__1A14E395] AS [t2]), SEEK:([t2].[LogIn
dex]=[Expr1003]), WHERE:([t1].[CardNo]=[t2].[CardNo] AND abs([t1].[Credit]-[t2].[Credit])<>[t2].[Amount]) ORDERED
FOR
Est row count: 1
Est row size: 61
Est # executes: 988,123
Est cost: 6188
2) INNER join, my version:
| |--Parallelism(Gather Streams, ORDER BY:([t2].[LogIndex] ASC))
Estimated row count: 1325
Estimated subtree cost: 245
| |--Sort(ORDER BY:([t2].[LogIndex] ASC))
| |--Filter(WHERE:([Expr1003]=[t2].[LogIndex]))
| |--Nested Loops(Inner Join, OUTER REFERENCES:([t1].[LogIndex], [t1].[CardNo
]))
Est row count: 1,337,987
Est row size: 62
Est CPU cost: 2.80
Est # executes: 1
Est cost: 2.80
Est subtree cost: 244
| |--Parallelism(Repartition Streams, PARTITION COLUMNS:([t1].[LogIndex]
, [t1].[CardNo]))
Est row count: 1,337,987
Est row size: 58
Est CPU cost: 12.1
Est # executes: 1
Est cost: 12.0
Est subtree cost: 119
| | |--Hash Match(Inner Join, HASH:([t2].[CardNo])=([t1].[CardNo]), RESIDUAL:(abs([t1].[Cre
dit]-[t2].[Credit])<>[t2].[Amount]))
Est CPU cost: 90.6
Est cost: 90.6
Est subtree cost: 107
| | |--Parallelism(Repartition Streams, PARTITION COLU
MNS:([t2].[CardNo]))
| | | |--Clustered Index Scan(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[PK__CardLog__1A14E395]
AS [t2]), WHERE:((([t2].[Action]=5 OR [t2].[Action]=4) OR [t2].[Action]=3) OR [t2].[Action]=2))
Est row count: 312,617
Est row size: 61
Est CPU cost: 0.543
Est I/O cost: 4.15
Est cost: 4.69
| | |--Parallelism(Repartition Streams, PARTITION COLU
MNS:([t1].[CardNo]))
| | |--Clustered Index Scan(OBJECT:([WM-Eu-Var].[dbo].[
CardLog].[PK__CardLog__1A14E395] AS [t1]))
Est row count: 988,123
Est row size: 53
Est I/O cost: 4.15
Est CPU cost: 0.543
Est cost: 4.69
| |--Hash Match(Cache, HASH:([t1].[LogIndex], [t1].[CardNo]), RESIDUAL:([t1].[LogIndex]=[t1].[LogIndex] AND
[t1].[CardNo]=[t1].[CardNo]))
Est row count: 1
Est row size: 11
Est CPU cost: 7.73
Est # executes: 1,339,789
Est cost: 13.8
Est subtree cost: 122
| |--Stream Aggregate(DEFINE:([Expr1003]=MIN([T3].[LogIndex
])))
| |--Top(1)
| |--Index S(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[IxCardLogCard] AS [T3]), SEEK:([T3].[CardNo]=[t1].[
CardNo] AND [T3].[LogIndex] > [t1].[LogIndex]) ORDERED FORWARD)
Est row count: 1
Est row size: 33
Est I/O cost: 0.00632
Est CPU cost: 0.000360
Est # executes: 18529
Est cost: 109
(3) Temporary table
I couldn't get it to work with a temporary table, it gave "Invalid object
name" when trying to get an execution plan.
I worked around that by creating it as a normal table, and TRUNCATEing it
before the SELECT INTO.
Creating (filling) the table: estimated cost 5873.
| |--Index Insert(OBJECT:([WM-Eu-Var].[dbo].[CLSEQ].[UQ__CLSEQ__47FBA9D6]), SET:([LogIndex1009]=[CLSEQ].[LogIndex], [NextLog
Index1008]=[CLSEQ].[NextLogIndex], [IdxBmk1007]=[Bmk1006]))
Est Cost: 6.29, subtree: 5873
| |--Sort(ORDER BY:([CLSEQ].[NextLogIndex] ASC))
Est Cost: 66.15, subtree: 5867
| |--Clustered Index Insert(OBJECT:([WM-Eu-Var].[dbo].[CLSEQ].[PK__CLSEQ__4707859D]), SET:([CLSEQ].[NextLogIndex]=[Expr1002]
, [CLSEQ].[LogIndex]=[t1].[LogIndex]))
Est cost: 1.00, subtree: 5801
| |--Top(ROWCOUNT est 0)
| |--Parallelism(Gather Streams, ORDER BY:([t1].[LogIndex] ASC))
Est cost: 3.58, subtree: 5800
| |--Filter(WHERE:([Expr1002]<>NULL))
Est cost: 0.23, subtree: 5796
| |--Compute Scalar(DEFINE:([Expr1002]=[Expr
1002]))
| |--Nested Loops(Inner Join, OUTER REFERENCES:([t1].[Log
Index], [t1].[CardNo]))
Est cost: 2.07, subtree: 5796
| |--Clustered Index Scan(OBJECT:([WM-Eu-Var].[d
bo].[CardLog].[PK__CardLog__1A14E395] AS [t1]), ORDERED FORWARD)
Est cost: 4.69
| |--Stream Aggregate(DEFINE:([Expr1002]=MIN
([t3].[LogIndex])))
Est cost: 0.0986, subtree: 5789
| |--Top(1)
| |--Index S(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[IxCardLogCard] AS [t3]), SEEK:([t3].
[CardNo]=[t1].[CardNo] AND [t3].[LogIndex] > [t1].[LogIndex]) ORDERED FORWARD)
Est cost: 5789
Final select query: estimated cost 0.0634
| |--Nested Loops(Inner Join, OUTER REFERENCES:([s].[LogIndex], [t2].[Amount], [t2].[Credit]))
| |--Nested Loops(Inner Join, OUTER REFERENCES:([s].[NextLogIndex]))
| | |--Index Scan(OBJECT:([WM-Eu-Var].[dbo].[CLSEQ].[UQ__CLSEQ__47FBA9D6] AS [s])
, ORDERED FORWARD)
| | |--Clustered Index S(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[PK__CardLog__1A14E395] AS [t2]), SEEK:([t2].[LogIndex]=[s].[NextLogIndex])
, WHERE:((([t2].[Action]=5 OR [t2].[Action]=4) OR [t2].[Action]=3) OR [t2].[Action]=2) ORDERED FORWARD)
| |--Clustered Index S(OBJECT:([WM-Eu-Var].[dbo].[CardLog].[PK__CardLog__1A14E395] AS [t1]), SEEK:([t1].[LogIndex]=[s].[LogInde
x]), WHERE:(abs([t1].[Credit]-[t2].[Credit])<>[t2].[Amount]) ORDERED FORWARD)|||1. Create a unique index on (CardNo, LogIndex), run sp_updatestats
again and re-try all three queries (I believe your IxCardLogCard index
on these columns, but it is not unique);
2. Also try this query:
INSERT INTO #CardLogSequence
SELECT t1.LogIndex, MIN(t3.LogIndex)
FROM CardLog t1 INNER JOIN CardLog t3
ON t3.CardNo = t1.CardNo
AND t3.LogIndex > t1.LogIndex
GROUP BY t1.LogIndex
3. The actual execution plan produced by Query Analyzer is much more
useful than the estimated query plan (use Ctrl+K instead of Ctrl+L),
because when a query performs poorly it's probable that this is due to
wrong estimations of row counts (so we need the actual row counts)
4. Is is true that the condition "t2.Action IN (2,3,4,5)" greatly
restricts the number of rows (i.e. the number of rows that satisfy this
condition is much lower than the total number of rows) ? If so, you
should try moving this condition to the first query (i.e: add "AND
t3.Action IN (2,3,4,5)")
Razvan|||On 8 Sep 2005 22:28:45 -0700, "Razvan Socol" <rsocol@.gmail.com> wrote:

> 1. Create a unique index on (CardNo, LogIndex), run sp_updatestats
> again and re-try all three queries (I believe your IxCardLogCard index
> on these columns, but it is not unique);
That's correct, the index on CardNo can not be unique.
I created the unique index and updated the stats with "sample all rows".
Execution times remain the same (I aborted the INNER join after 6 minutes).
The original LEFT join actually went up to 19 seconds (from 17).
I also tried a (non-unique) index on CardNo/Action/Amount/Credit, it
doesn't change anything either.
That could be because all of the table's fields are in the query (at least
in the SELECT clause), scanning the table shouldn't be much harder than
scanning a 4-column index.

> 2. Also try this query:
> INSERT INTO #CardLogSequence
> SELECT t1.LogIndex, MIN(t3.LogIndex)
> FROM CardLog t1 INNER JOIN CardLog t3
> ON t3.CardNo = t1.CardNo
> AND t3.LogIndex > t1.LogIndex
> GROUP BY t1.LogIndex
It seems to go the same way as my own INNER join version.
I aborted it after 3 minutes and some seconds.
I think I know why it performs so badly though, see below.

> 3. The actual execution plan produced by Query Analyzer is much more
> useful than the estimated query plan (use Ctrl+K instead of Ctrl+L),
> because when a query performs poorly it's probable that this is due to
> wrong estimations of row counts (so we need the actual row counts)
I'm being called away into a meeting, I'll look into this later.

> 4. Is is true that the condition "t2.Action IN (2,3,4,5)" greatly
> restricts the number of rows (i.e. the number of rows that satisfy this
> condition is much lower than the total number of rows) ? If so, you
> should try moving this condition to the first query (i.e: add "AND
> t3.Action IN (2,3,4,5)")
No. It filters out less than half of the results.
Most of it is done by the ABS() condition.
Looking at the queries, this part of the join:
SELECT count(*)
FROM CardLog t1 INNER JOIN CardLog t3
ON t3.CardNo = t1.CardNo
would return a *huge* number of rows (this query actually caused an
arithmetic overflow).
When I add the next line, it also seems to run forever:
SELECT count(*)
FROM CardLog t1 INNER JOIN CardLog t3
ON t3.CardNo = t1.CardNo
AND t3.LogIndex > t1.LogIndex
Could the problem be the high frequency of some CardNo values blowing up
intermediate results?
There are 1715 total, but some occur a lot more than others.
The top 5 occur more than 13,000 times each; the halfway point is 255
times, and about 1/3 occur less than 100 times.
BTW, just in case it wasn't clear from my first post: I _expected_ long
execution times, and 17 or 19 seconds is better than I hoped for.
I was only wondering why changing "LEFT" into "INNER" made such an enormous
difference.|||Hi
Why do you need to use ABS in
ABS(t1.Credit - t2.Credit) <> t2.Amount
Try t1.Credit <> t2.Amount + t2.Credit
and index Amount an Credit
John
"Lucvdv" <replace_name@.null.net> wrote in message
news:ud5uh1hm95lm2p3fso23jaqpm4o4q9l81p@.
4ax.com...
> On Wed, 7 Sep 2005 10:10:00 +0100, "John Bell"
> <jbellnewsposts@.hotmail.com>
> wrote:
>
> Yes, and even there it looks like the LEFT version should be slower
> (looking at what it's doing and how many times).
>
> I had put it there initially, but that was in Enterprise Manager, and it
> moved it into the join criteria by itself when I started the query.
> Now I checked it both ways in QA, and the execution plans it generates are
> identical.

No comments:

Post a Comment