Updated: Sorry! I may have missled you because of the old description. The problem did not exist right after migration, it started to appear 1 week after the migration
We recently migrated our database and report server to a new database server and a new report server.
Configurations Before:
- Database Server: 2008 Enterprise, DB01/NamedInstance
- Report Server: same server as database server, native mode, database credentials is NT AUTHORITY\NETWORK SERVICE
Configurations Now:
- Database Server: 2012 Enterprise, DC01 (default instance, NOT named instance)
- Reporting Services: moved to RP01 (native mode), database credentials is SQL Account(sa)
The migration is following MSDN migration instructions and works finally (although we had to mannually remove a redunant scale-out deployment server (same name as the old server) to make it work which I think it's SSRS bug).
1 week after migration, reports started to run extremely slow on the new report server.
So I did the following analysis:
Execute the report in the old report server (database connection of reports points to new database server) and the new report server, the old report server is running fast as before (1 second), but the new report server is running extremely slow (31 second).
Execute the stored procedures directly that the report calls, it's very fast as before (50 ms).
Diagnostics [ReportServer$Instance].[dbo].[ExecutionLog] database, TimeDataRetrival is 50 ms in old server, but 30050 ms in new server.
Run SQL Server Profiler, execute the report in the old server, everything seems fine. execute the report in the new server, something caught my attention. After last event of each batch, it will "hang" (run) for a long time before "Audit Logout" is generated. The sample below actually runs for 10 seconds but all the statements actually run for less than 1 seconds.
I suspect that: a). some configuration like account access have been changed without my acknowledgement. b). the new report server is trying to authenticate a user which does not have proper access and "hang" there for seconds before alternative solution.
Start of profiler output:
Audit Login -- network protocol: TCP/IP set quoted_identifier on set arithabort off set numeric_roundabort off set ansi_warnings on set ansi_padding on set ansi_nulls on set concat_null_yields_null on set cursor_close_on_commit off set implicit_transactions off set language us_english set dateformat mdy set datefirst 7 set transaction isolation level read committed
Report Server sa 1440 100 2013-04-16 16:10:14.393 0X2000002838F4010000000000
SQL:BatchStarting
declare @BatchID uniqueidentifier
set @BatchID = NEWID()
UPDATE [Event] WITH (TABLOCKX)
SET [BatchID] = @BatchID,
[ProcessStart] = GETUTCDATE(),
[ProcessHeartbeat] = GETUTCDATE()
FROM (
SELECT TOP 8 [EventID] FROM [Event] WITH (TABLOCKX) WHERE [ProcessStart] is NULL ORDER BY [TimeEntered]
) AS t1
WHERE [Event].[EventID] = t1.[EventID]
select top 8
E.[EventID],
E.[EventType],
E.[EventData]
from
[Event] E WITH (TABLOCKX)
where
[BatchID] = @BatchID
ORDER BY [TimeEntered]
Report Server sa 1440 100 2013-04-16 16:10:14.393
SQL:BatchCompleted
declare @BatchID uniqueidentifier
set @BatchID = NEWID()
UPDATE [Event] WITH (TABLOCKX)
SET [BatchID] = @BatchID,
[ProcessStart] = GETUTCDATE(),
[ProcessHeartbeat] = GETUTCDATE()
FROM (
SELECT TOP 8 [EventID] FROM [Event] WITH (TABLOCKX) WHERE [ProcessStart] is NULL ORDER BY [TimeEntered]
) AS t1
WHERE [Event].[EventID] = t1.[EventID]
select top 8
E.[EventID],
E.[EventType],
E.[EventData]
from
[Event] E WITH (TABLOCKX)
where
[BatchID] = @BatchID
ORDER BY [TimeEntered]
Report Server sa 0 7 0 0 1440 100 2013-04-16 16:10:14.393 2013-04-16 16:10:14.393
SQL:BatchStarting
declare @BatchID uniqueidentifier
set @BatchID = newid()
UPDATE [Notifications] WITH (TABLOCKX)
SET [BatchID] = @BatchID,
[ProcessStart] = GETUTCDATE(),
[ProcessHeartbeat] = GETUTCDATE()
FROM (
SELECT TOP 8 [NotificationID] FROM [Notifications] WITH (TABLOCKX) WHERE ProcessStart is NULL and
(ProcessAfter is NULL or ProcessAfter < GETUTCDATE()) ORDER BY [NotificationEntered]
) AS t1
WHERE [Notifications].[NotificationID] = t1.[NotificationID]
select top 8
-- Notification data
N.[NotificationID],
N.[SubscriptionID],
N.[ActivationID],
N.[ReportID],
N.[SnapShotDate],
N.[DeliveryExtension],
N.[ExtensionSettings],
N.[Locale],
N.[Parameters],
N.[SubscriptionLastRunTime],
N.[ProcessStart],
N.[NotificationEntered],
N.[Attempt],
N.[IsDataDriven],
SUSER_SNAME(Owner.[Sid]),
Owner.[UserName],
-- Report Data
O.[Path],
N.[ReportZone],
O.[Type],
SD.NtSecDescPrimary,
N.[Version],
Owner.[AuthType]
from
[Notifications] N with (TABLOCKX) inner join [Catalog] O on O.[ItemID] = N.[ReportID]
inner join [Users] Owner on N.SubscriptionOwnerID = Owner.UserID
left outer join [SecData] SD on O.[PolicyID] = SD.[PolicyID] AND SD.AuthType = Owner.AuthType
where
N.[BatchID] = @BatchID
ORDER BY [NotificationEntered]
Report Server sa 1440 100 2013-04-16 16:10:14.393
SQL:BatchCompleted
declare @BatchID uniqueidentifier
set @BatchID = newid()
UPDATE [Notifications] WITH (TABLOCKX)
SET [BatchID] = @BatchID,
[ProcessStart] = GETUTCDATE(),
[ProcessHeartbeat] = GETUTCDATE()
FROM (
SELECT TOP 8 [NotificationID] FROM [Notifications] WITH (TABLOCKX) WHERE ProcessStart is NULL and
(ProcessAfter is NULL or ProcessAfter < GETUTCDATE()) ORDER BY [NotificationEntered]
) AS t1
WHERE [Notifications].[NotificationID] = t1.[NotificationID]
select top 8
-- Notification data
N.[NotificationID],
N.[SubscriptionID],
N.[ActivationID],
N.[ReportID],
N.[SnapShotDate],
N.[DeliveryExtension],
N.[ExtensionSettings],
N.[Locale],
N.[Parameters],
N.[SubscriptionLastRunTime],
N.[ProcessStart],
N.[NotificationEntered],
N.[Attempt],
N.[IsDataDriven],
SUSER_SNAME(Owner.[Sid]),
Owner.[UserName],
-- Report Data
O.[Path],
N.[ReportZone],
O.[Type],
SD.NtSecDescPrimary,
N.[Version],
Owner.[AuthType]
from
[Notifications] N with (TABLOCKX) inner join [Catalog] O on O.[ItemID] = N.[ReportID]
inner join [Users] Owner on N.SubscriptionOwnerID = Owner.UserID
left outer join [SecData] SD on O.[PolicyID] = SD.[PolicyID] AND SD.AuthType = Owner.AuthType
where
N.[BatchID] = @BatchID
ORDER BY [NotificationEntered]
Report Server sa 0 7 0 0 1440 100 2013-04-16 16:10:14.393 2013-04-16 16:10:14.393
Audit Logout
Report Server sa 0 3836 6 10140 1440 100 2013-04-16 16:10:14.393 2013-04-16 16:10:24.533
