AlmBufWaitForSemaphore - Error зависает Historian

[asutegus]

Доброго времени суток уважаемые специалисты!
Мы не разработчики проекта - а обслуживающая АСУТП организация, помогите, пожалуйста разобраться у нас проблема с Historian Server.

На АРМах часто и непрерывно мониторят HistClientTrend, Historical Trend, AlmDbViewCtrl.
Периодически, после перезагрузки Historian Server с каждым днем чаще и чаще зависают тренды HistClientTrend и Historical Trend, история аварий AlmDbViewCtrl, а позже и сами АРМы с запущенным WindowViewer.
Спасает от зависания перезагрузка Historian Server, затем через неделю нормальной работы начинаются подвисания АРМ минут на 5-10 раз в сутки, затем через пару дней 3-4 раза в сутки, затем "зависают" и не "отвисают" АРМы, тогда уже решаемся на перезагрузку АРМ и Historian Server.
view.exe потребляет в рабочем режиме в среднем 150 Мб при зависании без изменений.

версии WW и версии ОС:
InTouch Application Manager и InTouch WindowMaker: Version 10.1.301
Archestra IDE: 3.1.301
Historian Client 3/1/10

АРМ - Microsoft Windows XP Professional 2002 SP3 32-битная
IO сервера ввода/вывода - Microsoft Window Server 2003 R2 SP2 32-битная
Historian Server - Microsoft Window Server 2003 R2 SP2 32-битная
SQL 2005

в Historian Server в таблице PublicNameSpace в бд Runtime таблицы dbo.PublicNameSpace 1378 записей, в бд WWALMDB таблица dbo.Events 1845000 записей.
WWALMDB.mdf занимает 70 Gb
WWALMDB_log.LDF 130 Gb

Логи SMC Historian Server "GTES-HISTORIAN":
28.12.2014 02:10:53 aahCfgSvc GTES-HISTORIAN 051 Warning aahCfgSvc Driver stopped (System driver, 2014/12/28 02:10:21.496) [GTES-HISTORIAN; aahCfgSvc.cpp; 8401]
28.12.2014 02:11:17 aaBootstrap GTES-HISTORIAN 498 Warning aaBootstrap This process failed to send heartbeat and it exceeds maximum WatchdogFault.. This process will be restarted.
28.12.2014 02:14:09 AlarmBuf GTES-HISTORIAN 067 Error alarmmgr !AlmBufWaitForSemaphore - Error: (0) - The operation completed successfully.
28.12.2014 02:17:45 AlarmBuf GTES-HISTORIAN 283 Error alarmmgr !ERR Failed semaphore wait [for Local\CBThreadSemaphore] in AlmBufWaitForSemaphore [last_err=0]
28.12.2014 02:17:45 aaBootstrap GTES-HISTORIAN 283 Warning aaBootstrap Pid:11440 Path:C:\Program Files\ArchestrA\Framework\Bin\aaEngine.exe Cmd:Deploy=False,Restart=True, ScanState=Last,CheckpointPath=,ClsId={BE4A11B6-86C2-49C6-883E ABA501A6BCC7},EngineId=1,EngineName=GTES_HISTORIAN,EngineSignature=0,IsPlatformEngine=-1, PlatformId=5 Ctrl:-p -v
28.12.2014 02:17:45 AlarmBuf GTES-HISTORIAN 299 Error alarmmgr !ERR Semaphore wait failed in CBThrd_CallbackThreadMain [hCBThreadSemaphore=00000160]
28.12.2014 02:26:09 aahCfgSvc GTES-HISTORIAN 728 Warning aahCfgSvc Driver stopped (System driver, 2014/12/28 02:25:43.405) [GTES-HISTORIAN; aahCfgSvc.cpp; 8401]
28.12.2014 02:26:36 aaBootstrap GTES-HISTORIAN 583 Warning aaBootstrap This process failed to send heartbeat and it exceeds maximum WatchdogFault.. This process will be restarted.
28.12.2014 02:27:12 aaBootstrap GTES-HISTORIAN 576 Warning aaBootstrap Pid:11664 Path:C:\Program Files\ArchestrA\Framework\Bin\aaEngine.exe Cmd:Deploy=False,Restart=True, ScanState=Last,CheckpointPath=,ClsId={BE4A11B6-86C2-49C6-883E-ABA501A6BCC7},EngineId=1,EngineName=GTES_HISTORIAN,EngineSignature=0,IsPlatformEngine=-1,PlatformId=5 Ctrl:-p -v

29.12.2014 00:44:43 aaBootstrap GTES-HISTORIAN 634 Warning aaBootstrap This process failed to send heartbeat and it exceeds maximum WatchdogFault.. This process will be restarted.
... -/- аналогично 28.12.2014 02:11:17
29.12.2014 00:50:33 AlarmBuf GTES-HISTORIAN 743 Error alarmmgr !ERR Semaphore wait failed in CBThrd_CallbackThreadMain [hCBThreadSemaphore=00000160]
29.12.2014 00:52:49 aahStoreSvc GTES-HISTORIAN 087 Warning aahCfgSvc Attempt to store values in the future; timestamps were overwritten with current time (pipe name, TagName, wwTagKey, system time (UTC), time difference (sec)) (GTES-HISTORIAN_mdas, Unit_dAna_10.Value, 1758, 2014/12/28 19:48:36.603, 1) [GTES-HISTORIAN; pipeserver.cpp; 1831; 18845]
29.12.2014 00:52:51 aahStoreSvc GTES-HISTORIAN 150 Warning aahCfgSvc Attempt to store values in the future; timestamps were overwritten with current time (pipe name, TagName, wwTagKey, system time (UTC), time difference (sec)) (GTES-HISTORIAN_mdas, GS1_PDIA.Value, 1920, 2014/12/28 19:52:49.165, 1) [GTES-HISTORIAN; pipeserver.cpp; 1831]
29.12.2014 00:57:01 aahStoreSvc GTES-HISTORIAN 337 Warning aahCfgSvc Attempt to store values in the future; timestamps were overwritten with current time (pipe name, TagName, wwTagKey, system time (UTC), time difference (sec)) (GTES-HISTORIAN_mdas, KNS.P_16bit, 1882, 2014/12/28 19:57:01.368, 1) [GTES-HISTORIAN; pipeserver.cpp; 1831]

24.01.2015 04:33:27 aaBootstrap GTES-HISTORIAN 961 Warning aaBootstrap This process failed to send heartbeat and it exceeds maximum WatchdogFault.. This process will be restarted.
24.01.2015 04:33:33 aahCfgSvc GTES-HISTORIAN 586 Warning aahCfgSvc Driver stopped (System driver, 2015/01/24 04:33:07.415) [GTES-HISTORIAN; aahCfgSvc.cpp; 8401]
24.01.2015 04:36:25 AlarmBuf GTES-HISTORIAN 696 Error alarmmgr !AlmBufWaitForSemaphore - Error: (0) - The operation completed successfully.
24.01.2015 04:40:52 aahIDASSvc (local) GTES-HISTORIAN 649 Warning aahIDASSvc GTES-HISTORIAN_2: Failed to send acquisition status. Connection to server timed out (This operation returned because the timeout period expired)
24.01.2015 04:41:22 aahDrvSvc GTES-HISTORIAN 586 Warning aahDrvSvc GTES-HISTORIAN_1: Failed to send acquisition status. Connection to server timed out (This operation returned because the timeout period expired)
24.01.2015 04:42:36 AlarmBuf GTES-HISTORIAN 368 Error alarmmgr !ERR Failed semaphore wait [for Local\CBThreadSemaphore] in AlmBufWaitForSemaphore [last_err=0]
24.01.2015 04:42:36 AlarmBuf GTES-HISTORIAN 368 Error alarmmgr !ERR Semaphore wait failed in CBThrd_CallbackThreadMain [hCBThreadSemaphore=00000160]
24.01.2015 04:42:36 aaBootstrap GTES-HISTORIAN 368 Warning aaBootstrap Pid:5888 Path:C:\Program Files\ArchestrA\Framework\Bin\aaEngine.exe Cmd:Deploy=False,Restart=True,ScanState=Last,CheckpointPath=,ClsId={BE4A11B6-86C2-49C6-883E-ABA501A6BCC7},EngineId=1,EngineName=GTES_HISTORIAN,EngineSignature=0,IsPlatformEngine=-1,
PlatformId=5 Ctrl:-p -v
24.01.2015 04:43:41 aahCfgSvc GTES-HISTORIAN 993 Warning aahCfgSvc Driver stopped (System driver, 2015/01/24 04:43:16.477) [GTES-HISTORIAN; aahCfgSvc.cpp; 8401]
24.01.2015 04:45:12 GTES_HISTORIAN.aaEngine GTES-HISTORIAN 571 Error aaEngine Unknown error 0xC0000005 (c0000005) raised.
24.01.2015 04:45:13 GTES_HISTORIAN.aaEngine GTES-HISTORIAN 930 Error aaEngine Unknown error 0xC0000005 (c0000005) raised.
24.01.2015 04:45:14 GTES_HISTORIAN.aaEngine GTES-HISTORIAN 883 Error aaEngine Unknown error 0xC0000005 (c0000005) caught at line 238 in FsEngine.cpp (in Z:\SysObjectDev\src\FsEngine\).
24.01.2015 04:45:14 GTES_HISTORIAN.aaEngine GTES-HISTORIAN 883 Error aaEngine WinMain exiting error code c0000005


Логи SMC АРМ "GTES-ARM5":
31.12.2014 14:44:35 AlarmViewer GTES-ARM5 187 Error view There are no records to show, cannot call "AckVisible".
01.01.2015 21:02:53 AlarmBuf GTES-ARM5 763 Error alarmmgr !AlmBufWaitForSemaphore - Error: (0) - Операция успешно завершена.
01.01.2015 21:02:53 AlarmBuf GTES-ARM5 763 Error alarmmgr !ERR Failed semaphore wait [for Local\CBThreadSemaphore] in AlmBufWaitForSemaphore [last_err=0]
01.01.2015 21:02:53 AlarmBuf GTES-ARM5 763 Error alarmmgr !ERR Semaphore wait failed in CBThrd_CallbackThreadMain [hCBThreadSemaphore=00000134]

Логи SMC сервера ввода вывода "GTES-IO2"
24.01.2015 09:55:52 ITAlarmProvider GTES-IO2 977 Error aaEngine Failed to send GTES_OSO_Unit_00.R4.Input.InputSource.'Event' message to InTouch!! hr = 1; Status = -21
24.01.2015 09:55:52 ITAlarmProvider GTES-IO2 977 Error aaEngine Failed to send GTES_OSO_Unit_00.R4.Output.OutputDest.'Event' message to InTouch!! hr = 1; Status = -21
24.01.2015 09:55:52 ITAlarmProvider GTES-IO2 977 Error aaEngine Failed to send GTES_OSO_Unit_00.CTRL_AI00.Input.InputSource.'Event' message to InTouch!! hr = 1; Status = -21
24.01.2015 09:55:52 ITAlarmProvider GTES-IO2 977 Error aaEngine Failed to send GTES_OSO_Unit_00.CTRL_AI00.Output.OutputDest.'Event' message to InTouch!! hr = 1; Status = -21
24.01.2015 09:55:52 ITAlarmProvider GTES-IO2 977 Error aaEngine Failed to send GTES_OSO_Unit_00.CTRL_AI01.Input.InputSource.'Event' message to InTouch!! hr = 1; Status = -21

Подскажите пожалуйста как с этим хозяйством быть.

[beachbear]

а не перегружен ли SQL Server при такой распухшей WWALMDB, которая, если я правильно понял, на той же машине, что и хисториан? посмотрите сколько ресурсов кушает SQL Server - memory, disk I/O. может быть, что ресурсов для хисториана уже и не остаётся. WWALMDB надо перодически чистить от старых данных, иначе неизбежно наступает эпоха стабильности.

[asutegus]

"посмотрите сколько ресурсов кушает SQL Server - memory, disk I/O. может быть, что ресурсов для хисториана уже и не остаётся"
Sqlservr.exe потребляет 1,7 Gb оперативки из всего доступной 4Gb, занято в рабочем режиме оперативной памяти - 55%.
"WWALMDB, которая, если я правильно понял, на той же машине, что и хисториан?"
Да, WWALMDB находится на той же машине что и хисториан.

Зависание Historian Server "GTES-HISTORIAN" отмечается сообщения в логах SMC "GTES-HISTORIAN" Error alarmmgr !AlmBufWaitForSemaphore - Error: (0) - The operation completed successfully.
Не могли бы вы прокомментировать или отправить к конкретному пункту руководства по вопросам:
1. Что такое AlmBufWaitForSemaphore , с чем связан этот процесс, почему он вызывает зависание системы?
2. Почему происходит остановка драйвера aahCfgSvc.cpp? Если какие то ошибки в конфигурировании хисториан, можно ли их выявить, исправить?
Driver stopped (System driver, 2014/12/28 02:10:21.496) [GTES-HISTORIAN; aahCfgSvc.cpp; 8401]
3. Из за чего происходит перезапуск aaBootstrap?
aaBootstrap This process failed to send heartbeat and it exceeds maximum WatchdogFault.. This process will be restarted.
4. Логи сервера ввода/вывода GTES-IO2 непрерывно забиваются сообщениями наподобие:
Failed to send GTES_OSO_Unit_00.R4.Input.InputSource.'Event' message to InTouch!! hr = 1; Status = -21
до появления этих сообщений было следующее:
27.10.2014 00:44:46 aahMDAS GTES-IO2 618 Warning aaEngine Failed to create directory '\\GTES-HISTORIAN\InSQL8SF$\MDAS\A05244193214_581' (The specified network name is no longer available.) [aahMDAS.cpp,260]
27.10.2014 00:45:54 aahMDAS GTES-IO2 867 Warning aaEngine Failed to create directory '\\GTES-HISTORIAN\InSQL8SF$\MDAS\A06580193237_252' (The specified network name is no longer available.) [aahMDAS.cpp,260]
Могут ли эти сообщения влиять на запись в хисториан, что приводит к зависанию и как эти ошибки исправить?
5. Общий вопрос: Как можно диагностировать или на что обратить внимание, где у нас проблема в железе, сети, Windows, SQL Server, настройки каких служб, настройки Historian?

[Генератор зла]

На каком ПК расположена и работает утилита AlarmDBLogger Manager ?

Sqlservr.exe потребляет 1,7 Gb оперативки из всего доступной 4Gb, занято в рабочем режиме оперативной памяти - 55%.

На сколько тегов используются SP и Historian ? 4 GB - не так много. С таким кол- вом памяти я бы ограничил в св-вах MSSQL аппетиты по памяти в 1.5 - 2 ГБ

WWALMDB надо периодически чистить от старых данных, иначе неизбежно наступает эпоха стабильности.

+
Много записей в БД - долго происходит выборка данных из неё. При этом проц и память жрутся по-максимуму. Из-за этого могут обрушиться службы, для нормальной работы которых не хватает ресурсов.

Проверьте так же в AlarmDBLogger Manager, сколько аварий в буфере при зависаниях. Возможно, у Вас слишком много генерится аварий в единицу времени

[beachbear]

Все сообщения лога, которые вы опубликовали вызваны перегрузкой машины из-за слишкой большой WWALMDB.
Например, сообщение об остановке системого драйвера хисториана вызвано не его фактической остановкой, а тем, что служба конфигурации не получила подтверждения от него, что он жив и здоров в течении определённого достаточно короткого интервала времени. Запрос просто вывалился по таймауту. Сетевой путь тоже не отвечает, скорее всего по той же причине. Вываливается по таймауту. SQL Server отличаетя тем, что он всегда думает, что он самый важный на машине и потребляет все возможные ресурсы для своих целей. Поэтому ВСЕГДА необходимо ограничивать его потребление памяти и других ресурсов если на той-же машине выполняются другие важные процессы. На машине с всего лишь 4GB памяти и тем количеством софта, которое там выполяется я бы разрешил ему кушать не более 700MB. Это первое, что надо сделать. Следующим делом надо забэкапить WWALMDB для сохранности желательно на отдельный диск, где для неё хватит места. Потом отключить машину от сети, если возможно, чтобы уменьшить блокировки базы клиентами, и почистить WWALMDB с помощью специальной утилиты, которая с ней должна идти. Это может занять определённое время. В будущем надо периодически проверять размер WWALMDB и запускать эту утилиту до появления наблюдаемых симптомов.

[asutegus]

В начале сделали rebuild И reorganize для index physical таблиц WWALMDB в mysql server management studio, некоторые таблицы выполнялись в среднем 5-6 часов, при условии что клиенты обращались к базе, такое длительное время без истории техпроцесс не может работать без паники.
Затем запустили утилиту Alarm DB Purge-Arhiv настроили что нужно сжать данные после 900 дней, т.е. 900 хранить остальные сжать. Почему 900 потому что пробовали сжимать данные после 365 дней, процесс purge откатывал изменения назад, также как и 630. Всего база около 1100 дней. После сжатия данных, база не сильно естественно сжалась.
И стоит отметить что процесс сжатия очень длительный, около 8 часов происходил, при этом жоские зависания были. А также не ясно как она выполнена успешно или нет?, процесс закончился последней записью в логе "purge database..." при этом окно утилиты закрылось по кнопке close, кнопки cancel purge не активны.

логи purge-arhiv при настройки 185, 365, 610,1100 и последний 900 дней:
Purge Started On 14:40:45 31-01-2015
Starting transaction ....
Archiving Table ProviderSession ...
Archiving Table Query ...
Archiving Table Cause ...
Archiving Table Alarm Master ...
Seek failed on C:\Purge_historian\20150131.1440\AlarmMaster_01312015_1440.tempArchive Failed for Alarm Master ...
Transaction rolled back //(185 дней)
Purge Started On 15:34:57 31-01-2015
Starting transaction ....
Archiving Table ProviderSession ...
Archiving Table Query ...
Archiving Table Cause ...
Archiving Table Alarm Master ...
Seek failed on C:\Purge_historian\20150131.1534\AlarmMaster_01312015_1534.tempArchive Failed for Alarm Master ... //Почему seek failed?
Transaction rolled back //(365 дней)
Purge Started On 16:47:48 31-01-2015
Starting transaction ....
Archiving Table ProviderSession ...
Archive Failed for Table ProviderSession
Transaction rolled back
Purge Started On 16:48:55 31-01-2015
Starting transaction ....
Archiving Table ProviderSession ...
Archiving Table Query ...
Archiving Table Cause ...
Archiving Table Alarm Master ...
Seek failed on C:\Purge_historian\20150131.1648\AlarmMaster_01312015_1648.tempArchive Failed for Alarm Master ...
Transaction rolled back //(610 дней)
Purge Started On 17:32:57 31-01-2015
Starting transaction ....
Archiving Table ProviderSession ...
Archiving Table Query ...
Archiving Table Cause ...
Archiving Table Alarm Master ...
Archiving Table OperatorDetails...
Archiving table Alarm Detail ...
Archiving Table Comment ...
Archiving Table Events ...
Archiving Table TagStatus ....
Purging records in the database ...
Committing ....
Purge Completed On 17:33:00 31-01-2015 //это когда указали не верный интервал для purge 1100 дней, видимо такое сообщение должно быть в случае успешного выполнения
0 records from AlarmMaster were purged along with the related records from other tables.
Purge Started On 17:35:36 31-01-2015
Starting transaction ....
Archiving Table ProviderSession ...
Archiving Table Query ...
Archiving Table Cause ...
Archiving Table Alarm Master ...
Archiving Table OperatorDetails...
Archiving table Alarm Detail ...
Archiving Table Comment ...
Archiving Table Events ...
Archiving Table TagStatus ....
Purging records in the database ... //а закончилось вот этим 900 дней

1) Как можно продиагностировать БД еще жива или скорее мертва? Может имеет смысл делать восстановление бд после rebuild и вновь повторить purge но уже на отключенном сервере от сети? А может откатиться вообще до первоначальной бд до rebuild, может быть rebuild было выполнено с ошибками, т.к. бд была в работе в сети и из-за этого все пошло не так?
И снова сделать rebuild потом purge но уже на отключенном historian serverе? Почему в purge-arhiv не видно чем закончился процесс или куда посмотреть о результате? Почему не удается выполнить purge-arhiv за 365 дней, происходит rolled back? Как узнать purge arhiv выполнена успешно или нет?
После rebuild завершения, выполнил бэкап бд и поставил копирование бэкап на внешний диск, бд не читалась клиентами длительное время - зависли тренды, процесс копирования не удалось отменить и сервер был отправлен на перезагрузку (каюсь,надо было ждать, не хватило терпения)
после перезагрузки не удается стартовать неизвестную службу выходит предупреждение windows
"at least one service or driver failed during system startup. use event viewer to example the event log for details"

2) Какие может известные службы могут остановится в такой ситуации и не запускаются?
в SMC в Starus historian server 2-е ошибки fatal error
01.02.2015 23:19:40 aahCfgSvc GTES-HISTORIAN 171 Error aahCfgSvc FATAL: Configuration object failed to reload DB changes [GTES-HISTORIAN; aahCfgSvc.cpp; 7742]
01.02.2015 23:19:40 aahCfgSvc GTES-HISTORIAN 171 Error aahCfgSvc ERROR: Failed to open connection to configuration database [GTES-HISTORIAN; Config.cpp; 2542]
02.2015 23:24:52 aahCfgSvc GTES-HISTORIAN 187 Error aahCfgSvc FATAL: Real-time storage did not start within the expected time period [GTES-HISTORIAN; aahCfgSvc.cpp; 7807]
01.02.2015 23:25:02 aahStoreSvc GTES-HISTORIAN 437 Warning aahCfgSvc ReaderLock failed. Data from Active Image is not accessible! (F0FF00F0, 118, 01000001) [GTES-HISTORIAN; activeimage.cpp; 826]
01.02.2015 23:25:02 aahStoreSvc GTES-HISTORIAN 437 Warning aahCfgSvc WriterLock failed. Data from Active Image is not accessible! (F0FF00F0, 118, 00000001) [GTES-HISTORIAN; activeimage.cpp; 748]
В SMC в Starus historian server остановлены модули:
Storage
Manual Storage
OLE-DB provider
Historian I/O server и другие не запускаются, только после перезагрузки все модули подключились

Сообщения в eventviewer windows на сервере:
Event ID 7018 Historian The time of the point for the specific stream is outside the required cyclic return time
Event ID 1623 Historian GetAllConfiguration failed - configuration object not created
Event ID 1620 LoaderThread did not start within specified timeout - configuration object not created
Event ID 7000 The WPS service failed to start due to the following error: The system cannot find the file specified.
Event ID 7000 wonderware historian retrieval service failed to start due to the folowing error :the service did not respond to the start or control request in a timely fashion
Event ID 7022 The Wonderware Historian Configuration service hung on starting.
Event ID 7009 Timeout 30000 miliseconds waiting for the wonderware historian
Event ID 7026
The following boot-start or system-start driver(s) failed to load:
SysPlant
WPS
retrieval service to connect
3) Из-за чего и как исправить, что конфигурационый файл и модули OLE-DB и прочие не загружаются, загружаются через раз? Какие это драйверы и как их запустить, почему они не запускаются wps, SysPlant?

4) Тренды насколько мы разобрались лежат в папке historian/circular она очень большая: размер: 250 Gb и на диске: 200 Gb (непонятный мне случай, почему разница такая), последние файлы от 01.02.2012 может нужно оставить за год остальное перенести на внешний носитель, хотя в принципе свободного места 250 Gb.

Будьте добры, помогите оценить ситуацию.

[beachbear]

Служба конфигурации хисториана aahCfgSvc.exe при запуске подключается к базе данных Runtime и грузит оттуда описания тэгов и другую конфигурационную информацию. Если по какой-то причине SQL Server долго не отвечает, то хисториан не может правильно проинициализироваться и появляются сообщения, котрые вы наблюдаете. Если хотя бы раз хисториану удалось запуститься нормально, то возможно, что повреждения базы данных Runtime не произошло, и просто проблема лишь в каком-то временном заторе возникающем в SQL Server-е из-за той злополучной WWALMDB. Например, он может проигрывать лог транзакций, даже если компьютер отключён от сети и новые алармы не приходят. Честно скажу, что я не специалист по чистке WWALMDB. Может быть, надо обратиться в официальную службу поддержки за помощью в этой процедуре. Главное - всегда делать бэкапы базы данных Runtime и блоков истории до любых инженерно-восстановительных работ, чтобы в случае чего, ничего не пропало. В общем случае, если бюджет позволяет, я бы рекомендовал перенести WWALMDB на отдельный компьютер, а в идеальном случае кроме хисториана на его компьютере ничего другого быть не должно.