Queue in data_engine

[Miller Echagarreta]

Hi everyone...

I have many queue on data_engine. I think that the problem is bad performance of the db server. But I see this line on the logs file data_engine.

Anyone know what is that????

 

Apr 15 15:57:28:064 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:28:064 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:29:065 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:29:065 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:29:119 [19664] de: Commit - inserted   11 rows to RN_QOS_DATA_0176 in 1792 ms (ms/r:162)

Apr 15 15:57:30:065 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:30:065 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:30:065 [9388] de: qos_data_thread - messages on hub: 12,117, messages in data_engine: 149,430 ( bulk buffers: 149,430, process queue: 0, limit: 100,000 )

Apr 15 15:57:31:066 [9388] de: qos_check - Check Queue Loop.  Connected: 1 vbQueue: 1

Apr 15 15:57:31:066 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:31:066 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:32:067 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:32:067 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:33:067 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:33:067 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:34:068 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:34:068 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:35:068 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:35:068 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:35:068 [9388] de: qos_data_thread - messages on hub: 12,117, messages in data_engine: 149,430 ( bulk buffers: 149,430, process queue: 0, limit: 100,000 )

Apr 15 15:57:36:069 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:36:069 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:37:070 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:37:070 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:38:071 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:38:072 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:39:099 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:39:099 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:40:109 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:40:109 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:40:109 [9388] de: qos_data_thread - messages on hub: 12,117, messages in data_engine: 149,430 ( bulk buffers: 149,430, process queue: 0, limit: 100,000 )

Apr 15 15:57:41:110 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:41:110 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:42:111 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:42:111 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:43:112 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:43:112 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:44:113 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:44:113 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:45:115 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:45:115 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:45:115 [9388] de: qos_data_thread - messages on hub: 12,117, messages in data_engine: 149,430 ( bulk buffers: 149,430, process queue: 0, limit: 100,000 )

Apr 15 15:57:46:115 [9388] de: qos_check - Check Queue Loop.  Connected: 1 vbQueue: 1

Apr 15 15:57:46:115 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:46:115 [9388] de: lockStatisticsFile UNLOCK

Apr 15 15:57:47:116 [9388] de: lockStatisticsFile LOCK

Apr 15 15:57:47:116 [9388] de: lockStatisticsFile UNLOCK

[David Michel]

The place to start is with:

data_engine best practices - CA Knowledge 

[Miller Echagarreta]

Yes David, I know the document and this was applied. But I see the message on the logs and I don't know if this is normal

[David Michel]

I've not found anything to indicate it is a problem.

[Stephen Danseglio]

You see these messages at loglevel 5.

 

Locking and unlocking entries in the log are normal when loglevel is set to 5. SQL Server by default uses locks for transaction isolation. The Lock command locks an object, either for shared or exclusive use, within the context of the currently active transaction. A lock on an object prevents transactions from committing until the lock is removed.

 

See also:

 

Transaction Locking and Row Versioning Guide
https://docs.microsoft.com/en-us/sql/relational-databases/sql-server-transaction-locking-and-row-versioning-guide?view=sql-server-2017#Lock_Engine

 

At loglevel 4 you only see database GLOBAL lock and unlock and much less frequent, in case you'd like to avoid these entries in the log entries.

 

If you'd like to view the status of locks/sessions you can use:

 

sp_lock

 

or

 

SELECT *
FROM sys.dm_exec_requests
WHERE DB_NAME(database_id) = 'CA_UIM'
AND blocking_session_id <> 0

Steve

[Waseem Siddiqui]

Hi,

I see the same lock unlock messages in the data_engine log file at log level 5 and my data_engine queue is stuck. I do not see any other information in the data_engine log as to why the queue is not flowing.

Regards,
Vinay.D.

[Garin Walsh]

The log line

 qos_data_thread - messages on hub: 12,117, messages in data_engine: 149,430 ( bulk buffers: 149,430, process queue: 0, limit: 100,000 )

indicates that you are trying to push more data through data_engine than it can support. When it gets behind, it will stop processing the inbound queue and work only on trying to commit data to the database. It will then go back and read data from the inbound queue again.

In this scenario you need to decide how to fix it - either by collecting less data or by making the database faster.

On the database side of things, have a DBA look at the configuration. Data_engine can insert data in parallel and the default configuration is good for small installs. If you're "big" then maybe increasing the number of threads on the data_engine probe will help.

Go back over the data_engine best practices document.