OLE DB error: OLE DB or ODBC error: Query timeout expired; HYT00.

Summary:
When running Proactive Caching in SQL Server Analysis Services Event ID 3, Category 289 is logged repeatedly.  This is due to Proactive Caching Notification, tracking tables, and the ExternalCommandTimeout.  The Event ID 3 errors can be ignored.

I recently setup a new install of SQL Server 2014 Analysis Services.  I watched the server over the next few days and noticed a pattern of errors, which take the following form depending on where you look:

Application Log:

Log Name:      Application
Source:        MSSQLServerOLAPService
Date:          4/11/2016 2:11:10 PM
Event ID:      3
Task Category: (289)
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      FQDN
Description:
OLE DB error: OLE DB or ODBC error: Query timeout expired; HYT00.

msmdsrv.log (AKA Flight Recorder):

(4/11/2016 2:11:11 PM) Message: OLE DB error: OLE DB or ODBC error: Query timeout expired; HYT00. (Source: ...\msmdsrv.log, Type: 3, Category: 289, Event ID: 0xC1210003)

Inputbuffer:

DECLARE @OlapEvent BIGINT;SELECT @OlapEvent = ObjIdUpdate(3);SELECT (@OlapEvent & convert(bigint, 0xffff000000000000)) / 0x0001000000000000 AS Status, (@OlapEvent & convert(bigint, 0x0000ffff00000000)) / 0x0000000100000000 AS DbId, @OlapEvent & convert(bigint, 0xffffffff) AS ObjId;

sql_text:

SELECT @OlapEvent = ObjIdUpdate(x)

Profiler Trace (I know I know, we should be using Extended Events...):

RowNumber 3696
EventClass 39
EventSubclass 5
TextData OLE DB error: OLE DB or ODBC error: Query timeout expired; HYT00. Trace: The SQL Server notification read operation failed. SQL Trace status code: 0.
ConnectionID NULL
NTUserName NULL
ApplicationName NULL
IntegerData NULL
StartTime 4/11/16 13:11
CurrentTime 4/11/16 13:11
Duration 0
DatabaseName My_DB
ObjectName My_SSAS_DataSourceName
Error NULL
ClientProcessID NULL
SPID NULL
CPUTime NULL
NTDomainName NULL
RequestParameters NULL
RequestProperties NULL
BinaryData NULL


The pattern is that the errors, in either the application log, flight recorder, or trace, repeat based on the SSAS ExternalCommandTimeout setting.  After much searching and finding the referenced article I was able to put together that SSAS uses a process for the proactive caching notification tables that will repeatedly timeout and report "TRACEWRITE" wait_info.  I was able to validate this most directly by relating my application log, default trace (EventClass = 175), and executions of sp_WhoIsActive.

Watch this.

With my ExternalCommandTimeout set to 2 hours.  I have the following logged:

Log Name:      Application
Source:        MSSQLServerOLAPService
Date:          4/11/2016 1:56:46 PM
Event ID:      3
Task Category: (289)
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      FQDN
Description:
OLE DB error: OLE DB or ODBC error: Query timeout expired; HYT00.

I run SP_whoisactive @ 3:55:46 PM (I was intently watching this)

dd hh:mm:ss.mss	00 01:58:46.196
session_id	65
sql_text	query --SELECT @OlapEvent = ObjIdUpdate(3)
wait_info	(1906ms)TRACEWRITE
status	suspended
open_tran_count	0
percent_complete	NULL
program_name	Microsoft SQL Server
start_time	4/11/16 13:56
login_time	4/11/16 9:56
request_id	0
collection_time	4/11/16 15:55

The following is then logged:
Log Name:      Application
Source:        MSSQLServerOLAPService
Date:          4/11/2016 3:56:48 PM
Event ID:      3
Task Category: (289)
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      FQDN
Description:
OLE DB error: OLE DB or ODBC error: Query timeout expired; HYT00.

And...the session is recycled:

dd hh:mm:ss.mss	00 00:00:01.053
session_id	65
sql_text	query --SELECT @OlapEvent = ObjIdUpdate(3)
wait_info	(1051ms)TRACEWRITE
status	suspended
open_tran_count	0
percent_complete	NULL
program_name	Microsoft SQL Server
start_time	4/11/16 15:56
login_time	4/11/16 9:56
request_id	0
collection_time	4/11/16 15:56

Incidentally I also pulled these from the default trace:
StartTime TextData
2016-04-11 13:56:48.350 SELECT @OlapEvent = ObjIdUpdate(3)
2016-04-11 15:56:51.850 SELECT @OlapEvent = ObjIdUpdate(3)

So now that I know what's going on, the remaining question is: HOW DO I GET THIS TO STOP!?


REF:
What are the @OlapEvent queries hanging around in my SQL Server?