Этот баннер — требование Роскомнадзора для исполнения 152 ФЗ.
«На сайте осуществляется обработка файлов cookie, необходимых для работы сайта, а также для анализа использования сайта и улучшения предоставляемых сервисов с использованием метрической программы Яндекс.Метрика. Продолжая использовать сайт, вы даёте согласие с использованием данных технологий».
Политика конфиденциальности
|
|
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Hello World! На SQL-сервере опубликован SSIS-пакет. В определенный момент время его выполнения увеличилось на порядок. Выяснил, что зависает Data Flow Task. У него такая структура: 1. Источник - OLE DB SOURCE, Date Access mode - SQL Command, Сам скрипт - процедура с тремя параметрами, которая возвращает набор записей. Код: sql 1. 2. 2. Derived Column Transformation - добавляет несколько полей с константами. 3. Назначение - OLE DB DESTINATION, Sql-таблица Данная ситуация эпизодическая. Запуская Job руками на сервере может и не повториться. Из проекта VS аналогично, может зависнуть, а может и быстро выполниться. Пробовал разобраться с помощью профайлера. Из его лога видно, что в определенный момент все транзакции прекращаются. Рестарт сервера не помог. Подскажите, в каком направлении двигаться, чтобы определить из-за чего появляются зависания. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.03.2019, 16:16 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, Если без экзотики, то причина может быть либо в процедуре (SSIS не при чем), либо в задержке при логировании SSIS (смотрите активность в БД SSISDB или как там она у вас называется). ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.03.2019, 16:38 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, кто же знает, может у вас журнал или база расширяются. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.03.2019, 16:49 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Запуск процедуры из Managerment Studuo отрабатывает без задержек. Вот логи SSISDB Код: sql 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. operation_id message_time message_type message_source_type message package_name event_name message_source_name subcomponent_name package_path95166 2019-03-17 01:32:36.5983684 +03:00 10 40 UT Sales:Validation has started. Sale.dtsx OnPreValidate UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:32:36.5993685 +03:00 70 40 UT Sales:Information: Validation phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:32:58.1955279 +03:00 20 40 UT Sales:Validation is complete. Sale.dtsx OnPostValidate UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:00.4267510 +03:00 10 40 UT Sales:Validation has started. Sale.dtsx OnPreValidate UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:00.4277511 +03:00 70 40 UT Sales:Information: Validation phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:23.9110992 +03:00 20 40 UT Sales:Validation is complete. Sale.dtsx OnPostValidate UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:25.3312412 +03:00 30 40 UT Sales:Start 1:33:25 AM. Sale.dtsx OnPreExecute UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:25.3312412 +03:00 10 40 UT Sales:Validation has started. Sale.dtsx OnPreValidate UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:25.3342415 +03:00 70 40 UT Sales:Information: Validation phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:47.2844363 +03:00 20 40 UT Sales:Validation is complete. Sale.dtsx OnPostValidate UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:47.2884367 +03:00 70 40 UT Sales:Information: Prepare for Execute phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 01:33:47.2964375 +03:00 70 40 UT Sales:Information: Pre-Execute phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 09:30:59.2061931 +03:00 70 40 UT Sales:Information: Execute phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 09:31:02.3971931 +03:00 70 40 UT Sales:Information: Post Execute phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 09:31:02.4061931 +03:00 70 40 UT Sales:Information: "Staging Table" wrote 80277 rows. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 09:31:02.4091931 +03:00 70 40 UT Sales:Information: Cleanup phase is beginning. Sale.dtsx OnInformation UT Sales SSIS.Pipeline \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 09:31:02.4121931 +03:00 40 40 UT Sales:Finished 9:31:02 AM Elapsed time: 07:57:37.087. Sale.dtsx OnPostExecute UT Sales NULL \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 09:31:02.3911931 +03:00 70 60 UT Sales:Information: The final commit for the data insertion in "Staging Table" has started. Sale.dtsx OnInformation UT Sales Staging Table [28] \Package\EXTRACT\SOURCES\UT\UT Sales95166 2019-03-17 09:31:02.3941931 +03:00 70 60 UT Sales:Information: The final commit for the data insertion in "Staging Table" has ended. Sale.dtsx OnInformation UT Sales Staging Table [28] \Package\EXTRACT\SOURCES\UT\UT Sales ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.03.2019, 17:17 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2Из его лога видно, что в определенный момент все транзакции прекращаются.Да, интересно, Pre-Execute занял 8 часов. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.03.2019, 17:50 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, возможно, на стороне источника была заблокирована проверка метаданных, возвращаемых вашей процедурой. Мониторьте сервера ETL и источников во время выполнения. Лукапов вроде бы у вас нет (начитка данных для их наполнения происходит в этой же фазе). ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.03.2019, 18:02 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, Лог работы пакета наводит на определенные мысли... Из опыта - когда долго происходит валидация и PreExecution, рекомендации следующие (может сработать одна из них или несколько, зависит от конкретной ситуации): Проверить, что у Data Flow и Connection Manager установлено свойство DelayValidation=true . У Data Flow - свойство ValidateExternalMetadata=false . В хранимке - установлено SET ANSI_NULLS ON В SELECT запросе, возвращающем результат - добавить параметр OPTION (FAST 10000) . Он указывает оптимизатору запросов, чтобы план запроса оптимизировался на быстрый вывод 10000 записей. Проверить хранимку на предмет parameter sniffing . BTW, зачем вы запускаете хранимку с командой SET FMTONLY OFF; ? У вас там SQL 2008 в качестве СУБД? Начиная с SQL2012, есть гораздо более изящный и менее глючный способ. Например, для двух столбцов: Код: sql 1. 2. 3. 4. 5. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.03.2019, 10:16 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Подскажите, а как узнать план SQL-процедуры, запущенной из SSIS-пакета? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.03.2019, 14:19 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, запустить, отловить запрос профайлером, посмотреть план ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.03.2019, 14:24 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2Подскажите, а как узнать план SQL-процедуры, запущенной из SSIS-пакета?Узнать можно, но ведь уже сказали, что план никак не связан с долгим выполнением. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.03.2019, 14:24 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
alexeyvg...Узнать можно, но ведь уже сказали, что план никак не связан с долгим выполнением. Хм, не согласен. ИМХО, Pre-Execute - это фаза начала запроса Data Source, на нее же приходится заполнение кешей Lookup. В случае автора - запуск хранимки. Execute - это когда Data Source начал получать данные. Чем можно объяснить такую задержку между запуском хранимки и началом возврата данных, если не оптимальными планами выполнения? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 24.03.2019, 18:52 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Ferdipuxalexeyvg...Узнать можно, но ведь уже сказали, что план никак не связан с долгим выполнением. Хм, не согласен. ИМХО, Pre-Execute - это фаза начала запроса Data Source, на нее же приходится заполнение кешей Lookup. В случае автора - запуск хранимки. Execute - это когда Data Source начал получать данные.Разве? По моему, Pre-Execute - это фаза получения метаданных источника, то есть получение списка полей с типами и прочим. https://docs.microsoft.com/en-us/sql/integration-services/extending-packages-custom-objects/data-flow/run-time-methods-of-a-data-flow-component?view=sql-server-2017 В частности, там есть пример реализации Pre-Execute; видно, что делается только получение метаданных: Код: vbnet 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 24.03.2019, 22:33 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
alexeyvgРазве? По моему, Pre-Execute - это фаза получения метаданных источника, то есть получение списка полей с типами и прочим. https://docs.microsoft.com/en-us/sql/integration-services/extending-packages-custom-objects/data-flow/run-time-methods-of-a-data-flow-component?view=sql-server-2017 В частности, там есть пример реализации Pre-Execute; видно, что делается только получение метаданных: Не только. Pre-Execute вызывается после AcquireConnections , поэтому производится непосредственная валидация получаемых полей (это когда DelayValidation=true ). Но в документации приведен пример использования Pre-Execute - заполнение справочника имен полей и lineage IDs, с объяснением, почему именно на этом шаге - ранее BufferManager не доступен. В ситуации, подобной автору, проводил исследования с профайлером - после старта Pre-Execute выдаются запросы на получение данных кешей (если это полные кеши) и данных в Data Source. Про кеши - можете убедиться сами без профайлера - на этапе Pre-Execute в логе исполнения пакета сообщается о получении количества записей в кеши, их процессинге и размещении в память. Запрос к источнику данных идет после подготовки кешей, но тоже на шаге Pre-Excute. У автора нет lookup, поэтому и кешей нет. Значит, задержка объясняется только паузой между запросом и началом получения данных. ИМХО, самое простое объяснение факту разного времени выполнения хранимой процедуры -- неоптимальные планы исполнения, хотя могут быть и другие причины. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 08:22 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
В моем случае, скорее всего дело в плане запроса. Во-первых, у данной процедуры три плана: Код: sql 1. 2. 3. 4. 5. cacheobjtype objtype plan_handle textCompiled Plan Proc 0x05000A00D909737940E163FC090000000000000000000000 CREATE PROCEDURE [etl].[sp_Get_Sale] ...Compiled Plan Proc 0x05000A00D909737940E15E310A0000000000000000000000 CREATE PROCEDURE [etl].[sp_Get_Sale] ...Compiled Plan Prepared 0x06000A003AC0EC2040A17D080A0000000000000000000000 (@P1 datetime2(0);@P2 datetime2(0);@P3 smallint)EXEC [etl].[sp_Get_Sale] @P1; @P2; @P3 Также, чтобы разобраться с механизмом логирования SSISDB, я создал вспомогательную таблицу, в которую делаются вставки, если выполнилась определенная часть кода. Вот, что получилось на 24.03.2019 DT_Log Par12019-03-24 01:24:51.067 CREATE TABLE #SALE2019-03-24 01:24:51.070 Список всех регистраторов2019-03-24 01:24:52.470 /*1. РТУ*/2019-03-24 01:24:55.323 /*2. Реализации товаров отложенной отгрузки */2019-03-24 01:24:55.520 /*3. Возвраты*/2019-03-24 01:24:57.593 /*4. Корректировки*/2019-03-24 01:24:59.623 UPDATE -- Дата и номер заказа2019-03-24 01:25:01.050 UPDATE --1. Ищем себестоимость2019-03-24 11:00:41.100 UPDATE --2. Ищем первую себестоимость2019-03-24 11:00:46.833 UPDATE -- Себестоимость на дату реализации2019-03-24 11:00:48.753 UPDATE -- Конвертация валюты2019-03-24 11:00:50.997 TRUNCATE TABLE2019-03-24 11:00:51.003 INSERT INTO А ниже логи из SSISDB message_time message2019-03-24 01:24:47.7374354 +03:00 UT Sales:Validation has started.2019-03-24 01:24:47.7384340 +03:00 UT Sales:Information: Validation phase is beginning.2019-03-24 01:24:47.7604032 +03:00 UT Sales:Validation is complete.2019-03-24 01:24:49.9383498 +03:00 UT Sales:Validation has started.2019-03-24 01:24:49.9383498 +03:00 UT Sales:Information: Validation phase is beginning.2019-03-24 01:24:50.1290824 +03:00 UT Sales:Validation is complete.2019-03-24 11:00:53.5708178 +03:00 UT Sales:Start; 11:00:53 AM.2019-03-24 11:00:53.5718178 +03:00 UT Sales:Validation has started.2019-03-24 11:00:53.5738178 +03:00 UT Sales:Information: Validation phase is beginning.2019-03-24 11:00:53.7738178 +03:00 UT Sales:Validation is complete.2019-03-24 11:00:53.7778178 +03:00 UT Sales:Information: Prepare for Execute phase is beginning.2019-03-24 11:00:53.7888178 +03:00 UT Sales:Information: Pre-Execute phase is beginning.2019-03-24 11:00:53.9798178 +03:00 UT Sales:Information: Execute phase is beginning.2019-03-24 11:00:56.9438178 +03:00 UT Sales:Information: The final commit for the data insertion in "Staging Table" has started.2019-03-24 11:00:56.9468178 +03:00 UT Sales:Information: The final commit for the data insertion in "Staging Table" has ended.2019-03-24 11:00:56.9498178 +03:00 UT Sales:Information: Post Execute phase is beginning.2019-03-24 11:00:56.9568178 +03:00 UT Sales:Information: "Staging Table" wrote 80117 rows.2019-03-24 11:00:56.9598178 +03:00 UT Sales:Information: Cleanup phase is beginning.2019-03-24 11:00:56.9628178 +03:00 UT Sales:Finished; 11:00:56 AM; Elapsed time: 00:00:03.386. То есть, лог SSIS-пакета сообщил о старте исполнения хранимой процедуры, но на самом деле она почти выполнилась. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 13:54 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Также у меня был запущен профайлер. Из его логов видно, что сканирование кластерных индексов ничего не вернуло: StartTime: 2019-03-24 01:25:01 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 14:14 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
А в StartTime: 2019-03-24 01:25:01 стартует тот же самый запрос, но скан тех же индексов дает огромное количество записей. Хотя [dbo].[_InfoRg9112] содержит 470786, а [dbo].[_InfoRg9882] - 1389724 записей. Что это может значить и как мне поступить? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 14:15 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
В после выше StartTime: 2019-03-24 11:00:41.100 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 14:16 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, выложили бы план в виде .sqlplan а так чисто из картинки: у вас на таблице _InfoRg9112 нет нормального индекса удовлетворяющего вашему запросу. у вас идет соединение NL вашей темповой таблицы и скан некластерного индекса, чем больше строк будет в вашей #SALE тем медленней будет выборка. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 14:53 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2Также у меня был запущен профайлер. Из его логов видно, что сканирование кластерных индексов ничего не вернуло: StartTime: 2019-03-24 01:25:01 В этот момент времени было перехвачено событие Showplan XML, поэтому у всех операторов Actual Number of Row = 0 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 15:30 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
felix_ffYagrus2, выложили бы план в виде .sqlplan а так чисто из картинки: у вас на таблице _InfoRg9112 нет нормального индекса удовлетворяющего вашему запросу. у вас идет соединение NL вашей темповой таблицы и скан некластерного индекса, чем больше строк будет в вашей #SALE тем медленней будет выборка. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 15:35 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
felix_ff, Запустил, процедуру и ManagermentStudio. Время ее работы порядка 1 мин. Во вложении план, того же участка кода. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 15:39 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, кусок что ли плана выдрали? нет информации о set_options и самой инструкции t-sql. но планы у вас как раз таки различаются для ssms используется hash-соединение вместо NL. сравните настройки сессии с которыми запускаете в ssms и в вашем SSIS пакете, может ARITHABORT или QUOTED_IDENTIFIER отличаются. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 16:33 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
felix_ffкусок что ли плана выдрали? Нет, просто выбрал Extract Event Data ... для EventClass - "Showplan XML Statistics Profile" felix_ffнет информации о set_options и самой инструкции t-sql. Как профайлером отловить set_options? Код: sql 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. 20. 21. 22. 23. 24. 25. 26. 27. 28. 29. 30. 31. 32. 33. 34. felix_ffно планы у вас как раз таки различаются для ssms используется hash-соединение вместо NL. Это да, но мне кажется что первопричина - громадное значение Actual Number of Row felix_ffсравните настройки сессии с которыми запускаете в ssms и в вашем SSIS пакете, может ARITHABORT или QUOTED_IDENTIFIER отличаются. Как в пакете посмотреть эти настройки? Не нашел таких опций в ConnectionManager-е. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 17:29 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, actual number of rows у вас большой из-за NL: оно равно кол-во выполнений * кол-ко строк возвращенных оператором за один проход. Так что это вас не должно смущать, а должно смущать что выбирается для соединения именно NL. у вас извлеченное событие профилировки это кусок общего плана процедуры или батча. вам нужно взять его query_plan_hash и выполнить запрос: Код: sql 1. 2. 3. 4. оно вам даст общий план для всей процедуры если оно находится в кэше. там нужно посмотреть параметры времени компиляции для инструкции они там в xml представленны в виде узла StatementSetOptions скорее всего в кеше у вас будет два разных плана для двух запуской из SSMS и SSIS. можете планы получить так: Код: sql 1. 2. 3. 4. 5. 6. 7. для чистоты душевной можете проделать эксперимент: (желательно не на бою а на тестовом стенде) Код: sql 1. очистить процедурный кэш от планов вашей хранимки. запустить на исполнение SSIS, потом из SSMS и посмотреть сколько будет планов. касательно параметров SET они предопределены для каждого провайдера заранее, если явно не переопределяются настройками сервера/сессии. на msdn где то была таблица. как вариант для определения выставленных настроек можете запихнуть в процедуру что то типа логирования, что бы понять в какой настройке различия. вам надо выйти на то что бы для запуска из SSIS хранимка запускалась с планом на hash-join для больших объемов а не NL Код: sql 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 18:43 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, Попробуйте делать принудительное обновление статистик. Такое может происходить, когда вбрасывается новый ключ, с которым связано небольшое кол-во записей, а потом количество зависимых записей многократно возрастает. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 19:31 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
a_voronin, Это как раз проявляется в том случае, когда происходит nested loop, хотя уже напрашивается HASH JOIN. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 25.03.2019, 19:33 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
felix_ff, После очистки кеша, я запустил процедуру из SSMS. Вот что получилось: Код: sql 1. 2. 3. 4. name object_id principal_id schema_id parent_object_id type type_desc create_date modify_date is_ms_shipped is_published is_schema_publishedsp_Get_Sale 2037582297 NULL 5 0 P SQL_STORED_PROCEDURE 2018-04-27 16:26:37.643 2019-03-26 11:30:40.250 0 0 0 Код: sql 1. 2. 3. database_id object_id type type_desc sql_handle plan_handle cached_time last_execution_time execution_count total_worker_time last_worker_time min_worker_time max_worker_time total_physical_reads last_physical_reads min_physical_reads max_physical_reads total_logical_writes last_logical_writes min_logical_writes max_logical_writes total_logical_reads last_logical_reads min_logical_reads max_logical_reads total_elapsed_time last_elapsed_time min_elapsed_time max_elapsed_time10 2037582297 P SQL_STORED_PROCEDURE 0x03000A00D9097379CBB2BD001CAA00000100000000000000 0x05000A00D90973794081933E0E0000000000000000000000 2019-03-26 11:31:48.977 2019-03-26 11:31:48.987 1 30181726 30181726 30181726 30181726 94552 94552 94552 94552 11411 11411 11411 11411 5845485 5845485 5845485 5845485 30997773 30997773 30997773 30997773 Код: sql 1. 2. 3. bucketid refcounts usecounts size_in_bytes memory_object_address cacheobjtype objtype plan_handle pool_id34866 2 1 2547712 0x0000000E3E938060 Compiled Plan Proc 0x05000A00D90973794081933E0E0000000000000000000000 1 Код: sql 1. 2. attribute value is_cache_keyset_options 4345 1objectid 2037582297 1dbid 10 1dbid_execute 10 1user_id 5 1language_id 0 1date_format 1 1date_first 7 1compat_level 100 1status 0 1required_cursor_options 0 1acceptable_cursor_options 0 1merge_action_type 0 1is_replication_specific 0 1optional_spid 0 1optional_clr_trigger_dbid 0 1optional_clr_trigger_objid 0 1inuse_exec_context 0 0free_exec_context 1 0hits_exec_context 0 0misses_exec_context 1 0removed_exec_context 0 0inuse_cursors 0 0free_cursors 0 0hits_cursors 0 0misses_cursors 0 0removed_cursors 0 0sql_handle NULL 0 А запрос Код: sql 1. 2. 3. 4. возвратил cacheobjtype objtype plan_handleCompiled Plan Proc 0x05000A00D90973794081933E0E0000000000000000000000 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 14:50 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
А после запуска из SSIS. На момент сбора статистик он еще выполнялся Код: sql 1. 2. 3. 4. cacheobjtype objtype plan_handle textCompiled Plan Proc 0x05000A00D90973794081933E0E0000000000000000000000 CREATE PROCEDURE [etl].[sp_Get_Sale] ...Compiled Plan Prepared 0x06000A003AC0EC2040A125FF040000000000000000000000(@P1 datetime2(0);@P2 datetime2(0);@P3 smallint);EXEC [etl].[sp_Get_Sale] @P1; @P2; @P3 Код: sql 1. 2. 3. 4. name object_id principal_id schema_id parent_object_id type type_desc create_date modify_date is_ms_shipped is_published is_schema_publishedsp_Get_Sale 2037582297 NULL 5 0 P SQL_STORED_PROCEDURE 2018-04-27 16:26:37.643 2019-03-26 11:30:40.250 0 0 0 Код: sql 1. 2. 3. 4. database_id object_id type type_desc sql_handle plan_handle cached_time last_execution_time execution_count total_worker_time last_worker_time min_worker_time max_worker_time total_physical_reads last_physical_reads min_physical_reads max_physical_reads total_logical_writes last_logical_writes min_logical_writes max_logical_writes total_logical_reads last_logical_reads min_logical_reads max_logical_reads total_elapsed_time last_elapsed_time min_elapsed_time max_elapsed_time10 2037582297 P SQL_STORED_PROCEDURE 0x03000A00D9097379CBB2BD001CAA00000100000000000000 0x05000A00D90973794081933E0E0000000000000000000000 2019-03-26 11:31:48.977 2019-03-26 11:31:48.987 1 30181726 30181726 30181726 30181726 94552 94552 94552 94552 11411 11411 11411 11411 5845485 5845485 5845485 5845485 30997773 30997773 30997773 30997773 Код: sql 1. 2. 3. bucketid refcounts usecounts size_in_bytes memory_object_address cacheobjtype objtype plan_handle pool_id22449 2 1 16384 0x00000004FF25A060 Compiled Plan Prepared 0x06000A003AC0EC2040A125FF040000000000000000000000 1 Код: sql 1. 2. 3. attribute value is_cache_keyset_options 249 1objectid 552386618 1dbid 10 1dbid_execute 0 1user_id -2 1language_id 0 1date_format 1 1date_first 7 1compat_level 100 1status 0 1required_cursor_options 0 1acceptable_cursor_options 0 1merge_action_type 0 1is_replication_specific 0 1optional_spid 0 1optional_clr_trigger_dbid 0 1optional_clr_trigger_objid 0 1inuse_exec_context 1 0free_exec_context 0 0hits_exec_context 0 0misses_exec_context 1 0removed_exec_context 0 0inuse_cursors 0 0free_cursors 0 0hits_cursors 0 0misses_cursors 0 0removed_cursors 0 0sql_handle 0x01000A003AC0EC20707926050A0000000000000000000000 0 Во вложении файл с планом, но он странный ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 14:51 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, вам нужна два раза ее запустить, один раз из ssms, второй раз вашим ssis пакетом (или где там у вас тормозит). и в процедурном кэше искать не по тексту LIKE '%sp_Get_Sale%', а по sys.dm_exec_plan_attributes where attribute = 'objectid' and value = object_id('имя вашей хранимки') ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 14:53 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
felix_ff, Код: sql 1. 2. 3. 4. 5. 6. 7. Пока такой запрос возвращает, план полученный из SSMS. Запрос и SSIS еще выполняется. В предыдущем моем посте выведено вся "статистика" , которую получили при запуске из SSIS. А именно вот plan_handle cacheobjtype objtype plan_handle textCompiled Plan Prepared 0x06000A003AC0EC2040A125FF040000000000000000000000 (@P1 datetime2(0);@P2 datetime2(0);@P3 smallint);EXEC [etl].[sp_Get_Sale] @P1; @P2; @P3 А также, что он привязан к объекту objectid = 552386618 Для этого объекта запрос Код: sql 1. 2. 3. 4. 5. 6. 7. возвращает "странный" план, который я выложил в предыдущем посте ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 15:20 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, Код: sql 1. 2. 3. 4. 5. 6. 7. 8. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 15:38 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
invm, Такой запрос возвращает план, с plan_handle = 0x05000A00D90973794081933E0E0000000000000000000000. Он получился при запуске моей процедуры из SSMS и с ним проблемы нет. Он привязан к объекту с object_id = 2037582297 Запуск SSIS-пакета добавил в sys.dm_exec_cached_plans cp еще одну запись, у которой plan_handle = 0x06000A003AC0EC2040A125FF040000000000000000000000 Выборка из sys.dm_exec_sql_text с последним хендлером возвращает такой запрос Код: sql 1. Из sys.dm_exec_plan_attributes вижу, что данный план привязан к объекту object_id = 552386618, а это уже не моя процедура. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 17:32 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, не путайте планы, под хранимую процедуру (именно под сам модуль) и план батча который содержит код запуска хп. это разные планы. я уже уточнил вам почему не следует использовать поиск по dm_exec_cached_plans + dm_exec_sql_text, он вам даст план батча и план хранимки их сравнивать не нужно. вот для примера Код: sql 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. 15. 16. 17. 18. 19. и потом сравните результаты: Код: sql 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. 13. 14. потом их последнего резалтсета возьмите два хендла: Код: sql 1. 2. 3. 4. 5. 6. и сравните, у них sql_handle будет один и тотже, а вот set_options будут различаться ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 18:54 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, invm вам кстати компактней написал как получить только планы вашей хранимки. его запрос вам сколько строк возвращает? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 18:56 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
Yagrus2, хотя я уже по вашим скринам видно что для исполнения SSIS пакета ARITHABORT выключен. попробуйте в Execute-SQL task пакета добавить SET ARITHABORT ON; или наоборот в SSMS SET ARITHABORT OFF и выполните процедуру, посмотрите изменится в плане алгоритмы соединений. что еще заметил: у вас план для SSIS пакета зависим от пользователя user_id = 5 это id конкретного пользователя БД, овнера схемы etl. вам по хорошему еще надо моделировать запуск из под идентичных пользователей. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 26.03.2019, 19:17 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
felix_ffYagrus2, не путайте планы, под хранимую процедуру (именно под сам модуль) и план батча который содержит код запуска хп. это разные планы. я уже уточнил вам почему не следует использовать поиск по dm_exec_cached_plans + dm_exec_sql_text, он вам даст план батча и план хранимки их сравнивать не нужно. Спасибо, с этим разобрался! ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 27.03.2019, 13:38 |
|
||
|
SSIS. Увеличилось время работы Data Flow Task.
|
|||
|---|---|---|---|
|
#18+
felix_ffYagrus2, invm вам кстати компактней написал как получить только планы вашей хранимки. его запрос вам сколько строк возвращает? Возвращается две строки. А как понять, какой из планов используется во время выполнения конкретного батча? То есть, у процедуры есть два плана. Пусть я запустил из SSIS-пакет. Как понять какой из планов он выбрал? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 27.03.2019, 13:41 |
|
||
|
|

start [/forum/topic.php?all=1&fid=46&tid=1688056]: |
0ms |
get settings: |
11ms |
get forum list: |
18ms |
check forum access: |
4ms |
check topic access: |
4ms |
track hit: |
87ms |
get topic data: |
12ms |
get forum data: |
4ms |
get page messages: |
91ms |
get tp. blocked users: |
2ms |
| others: | 275ms |
| total: | 508ms |

| 0 / 0 |
