Запрос занимает очень много времени в клиентском приложении, но быстро выполняется в SQL Server Management Studio.

Я разрабатываю приложение, которое хранит изображения и связанные с ними метаданные. У меня возникают проблемы при выполнении определенного запроса с использованием NHibernate. Запрос занимает чрезмерно много времени (на моей машине около 31 секунды), хотя тот же запрос занимает всего долю секунды при выполнении в SQL Server Management Studio.

Я сократил и дополнил проблему небольшим тестовым приложением:

Объекты:

Тег, состоящий из идентификатора (строка, само значение тега)

public class Tag
{
    public virtual string Id { get; set; }
}

Изображение, состоящее из идентификатора (int), имени (строка) и тегов (многие ко многим, набор экземпляров Tag)

public class Image
{
    private Iesi.Collections.Generic.ISet<Tag> tags = new HashedSet<Tag>();

    public virtual int Id { get; set; }

    public virtual string Name { get; set; }

    public virtual IEnumerable<Tag> Tags
    {
        get { return tags; }
    }

    public virtual void AddTag(Tag tag)
    {
        tags.Add(tag);
    }
}

Я использую «сопоставление по коду» со следующими сопоставлениями:

public class TagMapping : ClassMapping<Tag>
{
    public TagMapping()
    {
        Id(x => x.Id, map => map.Generator(Generators.Assigned));
    }
}

public class ImageMapping : ClassMapping<Image>
{
    public ImageMapping()
    {
        Id(x => x.Id, map => map.Generator(Generators.Native));
        Property(x => x.Name);
        Set(x => x.Tags, 
            map => map.Access(Accessor.Field),
            map => map.ManyToMany(m2m => { }));
    }
}

Конфигурация NHibernate/базы данных выглядит так:

  <hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
    <session-factory>
      <property name="dialect">NHibernate.Dialect.MsSql2008Dialect</property>
      <property name="connection.connection_string_name">PrimaryDatabase</property>
        <property name="format_sql">true</property>
    </session-factory>
  </hibernate-configuration>
  <connectionStrings>
    <add name="PrimaryDatabase" providerName="System.Data.SqlClient" connectionString="Data Source=.\SQLEXPRESS;Initial Catalog=PerfTest;Integrated Security=True" />
  </connectionStrings>

Я хочу выполнить следующий запрос: дайте мне все изображения, имя которых содержит определенную строку или где любой тег содержит определенную строку. Чтобы найти последний, я использую подзапрос, который дает мне идентификаторы всех изображений с соответствующими тегами. Таким образом, в итоге критерии поиска таковы: изображение имеет имя, содержащее определенную строку, или его идентификатор является одним из тех, которые возвращаются подзапросом.

Вот код, который выполняет запрос:

var term = "abc";
var mode = MatchMode.Anywhere;

var imagesWithMatchingTag = QueryOver.Of<Image>()
    .JoinQueryOver<Tag>(x => x.Tags)
    .WhereRestrictionOn(x => x.Id).IsLike(term, mode)
    .Select(x => x.Id);

var qry = session.QueryOver<Image>()
    .Where( Restrictions.On<Image>(x => x.Name).IsLike(term, mode) ||
            Subqueries.WhereProperty<Image>(x => x.Id).In(imagesWithMatchingTag))
    .List();

Тестовая база данных (СУБД: SQL Server 2008 Express R2), к которой я запускаю этот запрос, была создана специально для этого теста и больше ничего не содержит. Я заполнил его случайными данными: 10 000 изображений (таблица Image), 4 000 тегов (таблица Tag) и примерно 200 000 ассоциаций между изображениями и тегами (таблица Tags< /em>), т.е. каждое изображение имеет около 20 связанных тегов. База данных

SQL NHibernate утверждает, что использует:

SELECT
    this_.Id as Id1_0_,
    this_.Name as Name1_0_
FROM
    Image this_
WHERE
    (
        this_.Name like @p0
        or this_.Id in (
            SELECT
                this_0_.Id as y0_
            FROM
                Image this_0_
            inner join
                Tags tags3_
                    on this_0_.Id=tags3_.image_key
            inner join
                Tag tag1_
                    on tags3_.elt=tag1_.Id
            WHERE
                tag1_.Id like @p1
        )
    );
@p0 = '%abc%' [Type: String (4000)], @p1 = '%abc%' [Type: String (4000)]

Это выглядит разумно, учитывая запрос, который я создаю.

Если я запускаю этот запрос с помощью NHibernate, запрос занимает около 30+ секунд (NHibernate.AdoNet.AbstractBatcher - ExecuteReader took 32964 ms) и возвращает 98 объектов.

Однако, если я выполняю эквивалентный запрос непосредственно в студии управления сервером Sql:

DECLARE @p0 nvarchar(4000)
DECLARE @p1 nvarchar(4000)

SET @p0 = '%abc%'
SET @p1 = '%abc%'    

SELECT
    this_.Id as Id1_0_,
    this_.Name as Name1_0_
FROM
    Image this_
WHERE
    (
        this_.Name like @p0
        or this_.Id in (
            SELECT
                this_0_.Id as y0_
            FROM
                Image this_0_
            inner join
                Tags tags3_
                    on this_0_.Id=tags3_.image_key
            inner join
                Tag tag1_
                    on tags3_.elt=tag1_.Id
            WHERE
                tag1_.Id like @p1
        )
    );

Запрос занимает гораздо меньше одной секунды (и также возвращает 98 результатов).

Дальнейшие эксперименты:

Если я ищу только по названию или только по тегам, т.е.:

var qry = session.QueryOver<Image>()
    .Where( Subqueries.WhereProperty<Image>(x => x.Id).In(imagesWithMatchingTag))
    .List();

or

var qry = session.QueryOver<Image>()
    .Where(Restrictions.On<Image>(x => x.Name).IsLike(term, mode))
    .List();

запросы быстрые.

Если я не использую подобное, а точное совпадение в своем подзапросе:

var imagesWithMatchingTag = QueryOver.Of<Image>()
    .JoinQueryOver<Tag>(x => x.Tags)
    .Where(x => x.Id == term)
    .Select(x => x.Id);

запрос тоже быстрый.

Изменение режима соответствия имени на Exact ничего не меняет.

Когда я отлаживаю программу и приостанавливаю выполнение запроса, верхняя часть стека управляемых вызовов выглядит так:

[Managed to Native Transition]   
System.Data.dll!SNINativeMethodWrapper.SNIReadSync(System.Runtime.InteropServices.SafeHandle pConn, ref System.IntPtr packet, int timeout) + 0x53 bytes  
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.ReadSni(System.Data.Common.DbAsyncResult asyncResult, System.Data.SqlClient.TdsParserStateObject stateObj) + 0xa3 bytes   
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket() + 0x24 bytes  
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.ReadBuffer() + 0x1f bytes     
System.Data.dll!System.Data.SqlClient.TdsParserStateObject.ReadByte() + 0x46 bytes   
System.Data.dll!System.Data.SqlClient.TdsParser.Run(System.Data.SqlClient.RunBehavior runBehavior, System.Data.SqlClient.SqlCommand cmdHandler, System.Data.SqlClient.SqlDataReader dataStream, System.Data.SqlClient.BulkCopySimpleResultSet bulkCopyHandler, System.Data.SqlClient.TdsParserStateObject stateObj) + 0x67 bytes     
System.Data.dll!System.Data.SqlClient.SqlDataReader.ConsumeMetaData() + 0x22 bytes   
System.Data.dll!System.Data.SqlClient.SqlDataReader.MetaData.get() + 0x57 bytes  
System.Data.dll!System.Data.SqlClient.SqlCommand.FinishExecuteReader(System.Data.SqlClient.SqlDataReader ds, System.Data.SqlClient.RunBehavior runBehavior, string resetOptionsString) + 0xe1 bytes  
...

Итак, мои вопросы:

  • Почему запрос намного длиннее при выполнении NHibernate, хотя используемый SQL тот же?
  • Как избавиться от разницы? Есть ли настройка, которая может вызвать такое поведение?

Я знаю, что запрос в целом не самая эффективная вещь в мире, но что меня здесь поражает, так это разница между использованием NHibernate и ручным запросом. Здесь определенно происходит что-то странное.

Извините за длинное сообщение, но я хотел включить как можно больше о проблеме. Заранее большое спасибо за вашу помощь!

Обновление 1: я протестировал приложение с помощью NHProf без особых преимуществ: NHProf показывает, что выполняемый SQL

SELECT this_.Id   as Id1_0_,
       this_.Name as Name1_0_
FROM   Image this_
WHERE  (this_.Name like '%abc%' /* @p0 */
         or this_.Id in (SELECT this_0_.Id as y0_
                         FROM   Image this_0_
                                inner join Tags tags3_
                                  on this_0_.Id = tags3_.image_key
                                inner join Tag tag1_
                                  on tags3_.elt = tag1_.Id
                         WHERE  tag1_.Id like '%abc%' /* @p1 */))

Это именно то, что я публиковал ранее (потому что это то, что NHibernate записал в свой журнал в первую очередь).

Вот скриншот NHProf Скриншот NHProf

Предупреждения понятны, но не объясняют поведение.

Обновление 2 @surfen предложил сначала извлечь результаты подзапроса из БД и вставить их обратно в основной запрос:

var imagesWithMatchingTag = QueryOver.Of<Image>()
    .JoinQueryOver<Tag>(x => x.Tags)
    .WhereRestrictionOn(x => x.Id).IsLike(term, mode)
    .Select(x => x.Id);

var ids = imagesWithMatchingTag.GetExecutableQueryOver(session).List<int>().ToArray();

var qry = session.QueryOver<Image>()
    .Where(
            Restrictions.On<Image>(x => x.Name).IsLike(term, mode) ||
            Restrictions.On<Image>(x => x.Id).IsIn(ids))
    .List();

Хотя это действительно делает основной запрос снова быстрым, я бы предпочел не использовать этот подход, поскольку он не соответствует предполагаемому использованию в реальном приложении. Интересно, что это намного быстрее, хотя. Я ожидаю, что подход подзапроса будет таким же быстрым, учитывая, что он не зависит от внешнего запроса.

Обновление 3 Похоже, это не связано с NHibernate. Если я запускаю запрос, используя обычные объекты ADO.NET, я получаю такое же поведение:

var cmdText = @"SELECT this_.Id   as Id1_0_,
                        this_.Name as Name1_0_
                FROM   Image this_
                WHERE  (this_.Name like  @p0 
                            or this_.Id in 
                        (SELECT this_0_.Id as y0_
                        FROM   Image this_0_
                            inner join Tags tags3_
                                on this_0_.Id = tags3_.image_key
                            inner join Tag tag1_
                                on tags3_.elt = tag1_.Id
                        WHERE  tag1_.Id like  @p1 ));";

using (var con = new SqlConnection(ConfigurationManager.ConnectionStrings["PrimaryDatabase"].ConnectionString))
{
    con.Open();
    using (var txn = con.BeginTransaction())
    {
        using (var cmd = new SqlCommand(cmdText, con, txn))
        {
            cmd.CommandTimeout = 120;
            cmd.Parameters.AddWithValue("p0", "%abc%");
            cmd.Parameters.AddWithValue("p1", "%abc%");

            using (var reader = cmd.ExecuteReader())
            {
                while (reader.Read())
                {
                    Console.WriteLine("Match");
                }
            }

        }
        txn.Commit();
    }
}

Обновление 4

Планы запросов (нажмите, чтобы увеличить):

Медленный запрос Медленный план

Быстрый запрос Быстрый план

Там определенно есть разница в плане.

Обновление 5

Поскольку действительно кажется, что Sql Server обрабатывает подзапрос как коррелированный, я попробовал что-то другое: я переместил критерий, связанный с именем, в подзапрос сам по себе:

var term = "abc";
var mode = MatchMode.Anywhere;

var imagesWithMatchingTag = QueryOver.Of<Image>()
    .JoinQueryOver<Tag>(x => x.Tags)
    .WhereRestrictionOn(x => x.Id).IsLike(term, mode)
    .Select(x => x.Id);

var imagesWithMatchingName = QueryOver.Of<Image>()
    .WhereRestrictionOn(x => x.Name).IsLike(term, mode)
    .Select(x => x.Id);

var qry = session.QueryOver<Image>()
    .Where(
      Subqueries.WhereProperty<Image>(x => x.Id).In(imagesWithMatchingName) ||        
      Subqueries.WhereProperty<Image>(x => x.Id).In(imagesWithMatchingTag) 
    ).List();

Сгенерированный SQL:

SELECT
    this_.Id as Id1_0_,
    this_.Name as Name1_0_
FROM
    Image this_
WHERE
    (
        this_.Id in (
            SELECT
                this_0_.Id as y0_
            FROM
                Image this_0_
            inner join
                Tags tags3_
                    on this_0_.Id=tags3_.image_key
            inner join
                Tag tag1_
                    on tags3_.elt=tag1_.Id
            WHERE
                tag1_.Id like @p0
        )
        or this_.Id in (
            SELECT
                this_0_.Id as y0_
            FROM
                Image this_0_
            WHERE
                this_0_.Name like @p1
        )
    );
@p0 = '%abc%' [Type: String (4000)], @p1 = '%abc%' [Type: String (4000)]

Это, кажется, нарушает корреляцию, и в результате запрос снова становится «быстрым» («быстрым», как в «приемлемом на данный момент»). Время запроса сократилось с 30+ секунд до ~170 мс. Все еще не легкий запрос, но, по крайней мере, позволит мне продолжить отсюда. Я знаю, что "like '%foo%'" никогда не будет супербыстрым. В худшем случае я все еще могу перейти на специализированный поисковый сервер (Lucene, solr) или на настоящий полнотекстовый поиск.

Обновление 6. Мне удалось переписать запрос, чтобы вообще НЕ использовать подзапросы:

var qry = session.QueryOver(() => img)
    .Left.JoinQueryOver(x => x.Tags, () => tag)
    .Where(
        Restrictions.Like(Projections.Property(() => img.Name), term, mode) ||
        Restrictions.Like(Projections.Property(() => tag.Id), term, mode))
    .TransformUsing(Transformers.DistinctRootEntity)
    .List();

SQL:

SELECT
    this_.Id as Id1_1_,
    this_.Name as Name1_1_,
    tags3_.image_key as image1_3_,
    tag1_.Id as elt3_,
    tag1_.Id as Id0_0_
FROM
    Image this_
left outer join
    Tags tags3_
        on this_.Id=tags3_.image_key
left outer join
    Tag tag1_
        on tags3_.elt=tag1_.Id
WHERE
    (
        this_.Name like @p0
        or tag1_.Id like @p1
    );
@p0 = '%abc%' [Type: String (4000)], @p1 = '%abc%' [Type: String (4000)]

Однако теперь запрос работает немного хуже, чем версия с подзапросами. Я буду исследовать это дальше.


person Andre Loker    schedule 30.03.2012    source источник
comment
Возможный дубликат: dba.stackexchange.com/q/9167/724   -  person Rowland Shaw    schedule 30.03.2012
comment
@RowlandShaw не является дубликатом, поскольку проблема может быть на стороне C #, что также делает ее недоступной для dba.   -  person mmmmmm    schedule 30.03.2012
comment
@AndreLoker - вы запустили профилировщик, чтобы увидеть, где берется время   -  person mmmmmm    schedule 30.03.2012
comment
Вы проверили запрос с помощью SQL Profiler? Там вы должны увидеть фактический запрос и иметь возможность в значительной степени вырезать и вставить его в SQL Manager для сравнения. Я не уверен, откуда вы берете заявления NHibernate об использовании, поэтому не уверен, что это абсолютная правда :)   -  person Joachim Isaksson    schedule 30.03.2012
comment
Установите NHPRof и посмотрите на фактический генерируемый запрос, сообщение, которое здесь. та   -  person Rippo    schedule 30.03.2012
comment
Я согласен с @Joachim - никогда не знаешь, какой SQL решит использовать инструмент ORM (и для начала они обычно генерируют довольно ужасный SQL).   -  person N West    schedule 30.03.2012
comment
То же самое с профилировщиком SQL, но также сравните настройки соединения на случай, если в соединении NHibernate есть что-то странное. Я не понимаю, почему еще запуск идентичного SQL может пойти не так :-/   -  person Rup    schedule 30.03.2012
comment
Я проверил NNHProf без особого понимания, см. обновление 1 в моем вопросе. У меня нет под рукой SQL Profiler.   -  person Andre Loker    schedule 30.03.2012
comment
Его нет в стандартной установке клиентских инструментов, которую вы установили для получения Management Studio? Я так и думал, но вполне мог ошибаться!   -  person Rup    schedule 30.03.2012
comment
Боюсь, не в экспресс-версии.   -  person Andre Loker    schedule 30.03.2012
comment
Похоже, проблема не связана с NH (см. последнее обновление), поэтому я удалил тег NHibernate.   -  person Andre Loker    schedule 30.03.2012
comment
Пожалуйста, опубликуйте планы выполнения как для медленной, так и для быстрой версии.   -  person Martin Smith    schedule 30.03.2012
comment
Это могут быть какие-то флаги оптимизации, которые устанавливает (или должен установить) NH, поэтому, ИМХО, тег NH по-прежнему применим.   -  person surfen    schedule 30.03.2012
comment
Как лучше всего опубликовать исполнительный план? Снимок экрана? XML? Таблица SHOWPLAN?   -  person Andre Loker    schedule 30.03.2012
comment
NHPRof также может показать план запроса   -  person Rippo    schedule 30.03.2012
comment
Я добавил планы запросов. План медленной версии исходит от NHProf, план быстрой версии исходит от Management Studio.   -  person Andre Loker    schedule 30.03.2012
comment
Кстати, тем временем я создал предложенный отсутствующий индекс, но это не повлияло на медленный запрос.   -  person Andre Loker    schedule 30.03.2012
comment
Я добавил новые планы запросов, оба из Management Studio (я нашел способ зафиксировать план, который использует приложение). Поддерево, связанное с сопоставлением тегов, действительно отличается. Вопрос в том, как я могу повлиять на план запроса внутри своего приложения?   -  person Andre Loker    schedule 30.03.2012
comment
Вы проверили это ayende.com/blog/2322/ orm-and-when-query-plans-go-bad и этот codewrecks.com/blog/index.php/2011/07/23/ ? Не уверен, что это поможет вам.   -  person Rippo    schedule 31.03.2012
comment
@Rippo, это звучит очень интересно, может быть, я смогу использовать это в этом случае. Большое спасибо!   -  person Andre Loker    schedule 31.03.2012


Ответы (1)


Могу поспорить, что второй запрос медленный:

var qry = session.QueryOver<Image>()
.Where( Restrictions.On<Image>(x => x.Name).IsLike(term, mode) ||
        Subqueries.WhereProperty<Image>(x => x.Id).In(imagesWithMatchingTag))
.List();

Вы предоставили SQL только для первого запроса. Что насчет второго? Вы тестировали его в SQL Management Studio? Используйте SQL Server Profiler, как предлагает @JoachimIsaksson, чтобы узнать, какие именно запросы NHibernate выполняет на стороне сервера.

Похоже, вы загружаете в память 97 image объектов. Насколько велика каждая из них?

ИЗМЕНИТЬ

Другая ставка заключается в том, что ваш первый запрос выполняет внутренний запрос для второго запроса. Попробуйте выполнить .List() в первом запросе, чтобы загрузить теги в память.

ИЗМЕНИТЬ 2

Судя по планам запроса, ваш запрос действительно вызывается как коррелированный подзапрос. Вы упомянули, что эти запросы выполняются быстро:

var qry = session.QueryOver<Image>()
.Where( Subqueries.WhereProperty<Image>(x => x.Id).In(imagesWithMatchingTag))
.List();

or

var qry = session.QueryOver<Image>()
.Where(Restrictions.On<Image>(x => x.Name).IsLike(term, mode))
.List();

Просто ОБЪЕДИНИТЕ их, и вы должны получить тот же результат, что и при запуске их обоих по отдельности. Также убедитесь, что все столбцы соединения имеют индексы.

В этом и есть загвоздка с IS IN (запрос) — вы не можете быть уверены, как база данных его выполняет (если только вы каким-то образом не заставите его использовать определенный план). Может быть, вы могли бы как-то изменить .In() на JoinQueryOver()?

person surfen    schedule 30.03.2012
comment
Есть только один запрос. imagesWithMatchingTag — это подзапрос. SQL, который я разместил, - это все, что выполняется. Если вы посмотрите на мой вопрос, то увидите, что объекты Image довольно малы: два примитивных поля и один набор хэшей, содержащий не более 20 записей. - person Andre Loker; 30.03.2012
comment
Я понимаю. Смотрите мои правки. Попробуйте выполнить .List() в первом запросе, чтобы увидеть, поможет ли это. - person surfen; 30.03.2012
comment
Разве это не вытянет первый запрос из SQL и вместо этого заставит его передавать список идентификаторов в код и из него? Не будет ли это хуже? - person Rup; 30.03.2012
comment
Нет, если в настоящее время он работает как коррелированный подзапрос. Я должен был добавить, что это мое предположение. - person surfen; 30.03.2012
comment
@surfen Сначала извлечение идентификаторов из базы данных действительно ускоряет выполнение запроса. Это не совсем подходящее решение для реального применения. Я не хочу вводить в запрос сотни параметров. Если я посмотрю на SQL, который генерирует NHibernate, подзапрос не будет коррелирован. - person Andre Loker; 30.03.2012
comment
Моя первоочередная задача — не улучшить дизайн запроса, а объяснить (и устранить) разницу между скоростью выполнения при запуске через NHibernate и Management Studio. - person Andre Loker; 30.03.2012
comment
@AndreLoker Предоставьте план выполнения запроса для запроса NHibernate в своем вопросе. Это покажет, какая часть запроса занимает так много времени. Если бы у вас был SQL Server Profiler, можно было бы сравнить эти планы выполнения запросов. - person surfen; 30.03.2012
comment
Согласно дизайну, проще поддерживать более простые запросы, чем один сложный. И, как показывает этот пример, один сложный запрос не всегда лучше, чем несколько небольших запросов. Если вы действительно не хотите выполнять 2 запроса, вы можете выполнить всю эту логику на стороне сервера, используя хранимые процедуры. - person surfen; 30.03.2012
comment
Спасибо уже за ваш ответ. Я не могу создать объединение (на стороне сервера) в NHibernate. Проблема в том, что запрос, который я показал, сам по себе является частью более крупного запроса, используемого для получения изображений в соответствии с критериями фильтрации. Более крупный запрос также требует проверки прав доступа и выполнения пейджинга. Так что в идеале на данный момент мне нужен один запрос, который я могу вставить (как сам подзапрос) в свой более крупный запрос. Но вот интересный вывод: если я перемещу часть запроса, которая сравнивает имя с самим подзапросом (см. обновленный вопрос), запрос снова будет быстрым. Я обновлю свой вопрос с более подробной информацией. - person Andre Loker; 30.03.2012
comment
Я рад, что смог помочь. Я на самом деле не эксперт в NHibernate, поэтому я полагаю, что, возможно, кто-то другой предложит лучший подход. Надеюсь, вы найдете удовлетворительное решение. - person surfen; 30.03.2012
comment
@surfen Я приму этот ответ. Хотя я еще не понимаю, почему SQL Server рассматривает мой исходный запрос как коррелированный, вы ответили, и комментарии заставили меня попробовать альтернативные запросы. Спасибо за вашу помощь. - person Andre Loker; 04.04.2012