Вести с полей посттестирования v5

Решил прогнать на кодовой базе v5 модульные тесты встроенного клиента к Firebird. В качестве жертв были выбраны FB3.0.4 и FB2.5.6.

100 лет уже эти тесты не запускал — ограничивался основными тестами. Они тоже неплохо так разные варианты перебирают.

В процессе перезапуска тестов на FB2.5.6 (дорабатывал их устаревший код) нарвался на тупняк сервера со списками запросов. Ну, думаю, сейчас тройку замучаю и если на ней тест «RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts» тоже будет тупить — держите меня семеро.

Тесты прогоняются четыре раза ([debug,release]x[32bit,64bit]). В четыре потока. Сам сервер 64битный (релизный код, superserver).

Смотрю четвертый (последний) прогон:

[THR:028840] [15.02.2019 09:18:23] ***********************************************
[THR:028840] [15.02.2019 09:18:23] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
[THR:028840] [15.02.2019 09:18:23] *
[THR:028840] [15.02.2019 09:18:23] [test] Hello from test!
[THR:028840] [15.02.2019 09:18:23] [test] RemoteFB__Connector::ConnectToDatabase ...OK
[THR:028840] [15.02.2019 09:18:23] [test] RemoteFB__Connector::StartTransaction ...OK
[THR:028840] [15.02.2019 09:18:23] [test] Allocate statements ...
[THR:028840] [15.02.2019 09:18:43] [test] OK. We got the error.
[THR:028840] [15.02.2019 09:18:43] [test] 1. [Firebird] too many open handles to database
[THR:028840] [15.02.2019 09:18:43] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса.
[THR:028840] [15.02.2019 09:18:43] [test] nMaxStatements: 64999
[THR:028840] [15.02.2019 09:18:43] [test] RemoteFB__Connector::ConnectToDatabase ...OK
[THR:028840] [15.02.2019 09:18:43] [test] RemoteFB__Connector::StartTransaction ...OK
[THR:028840] [15.02.2019 09:18:43] [test] -------------------------------- pass: 1
[THR:028840] [15.02.2019 09:18:43] [test] Allocate statements ...
[THR:028840] [15.02.2019 09:18:43] [test] ----
[THR:028840] [15.02.2019 09:19:04] [test] Drop statements ...
[THR:028840] [15.02.2019 09:19:04] [test] -------------------------------- pass: 2
[THR:028840] [15.02.2019 09:19:04] [test] Allocate statements ...
[THR:028840] [15.02.2019 09:19:47] [test] ----
[THR:028840] [15.02.2019 09:20:08] [test] Drop statements ...
[THR:028840] [15.02.2019 09:20:08] [test] -------------------------------- pass: 3
[THR:028840] [15.02.2019 09:20:08] [test] Allocate statements ...
[THR:028840] [15.02.2019 09:20:54] [test] ----
[THR:028840] [15.02.2019 09:21:13] [test] Drop statements ...
[THR:028840] [15.02.2019 09:21:13] [test] RemoteFB__Connector::Commit ...OK
[THR:028840] [15.02.2019 09:21:18] [test] RemoteFB__Connector::DetachDatabase ...OK
[THR:028840] [15.02.2019 09:21:18] *
[THR:028840] [15.02.2019 09:21:18] * REAL   TIME:1753422293    [00:02:55.3422293]
[THR:028840] [15.02.2019 09:21:18] * USER   TIME:103593750     [00:00:10.3593750]
[THR:028840] [15.02.2019 09:21:18] * KERNEL TIME:54531250      [00:00:05.4531250]
[THR:028840] [15.02.2019 09:21:18] * TOTAL  TIME:158125000     [00:00:15.8125000]
[THR:028840] [15.02.2019 09:21:18] *
[THR:028840] [15.02.2019 09:21:18] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
[THR:028840] [15.02.2019 09:21:18] 

«Ух ты, вот это скорость!» (с) Шматрица.

Третий прогон:

[THR:017468] [15.02.2019 07:22:25] ***********************************************
[THR:017468] [15.02.2019 07:22:25] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
[THR:017468] [15.02.2019 07:22:25] *
[THR:017468] [15.02.2019 07:22:25] [test] Hello from test!
[THR:017468] [15.02.2019 07:22:25] [test] RemoteFB__Connector::ConnectToDatabase ...OK
[THR:017468] [15.02.2019 07:22:25] [test] RemoteFB__Connector::StartTransaction ...OK
[THR:017468] [15.02.2019 07:22:25] [test] Allocate statements ...
[THR:017468] [15.02.2019 07:22:48] [test] OK. We got the error.
[THR:017468] [15.02.2019 07:22:48] [test] 1. [Firebird] too many open handles to database
[THR:017468] [15.02.2019 07:22:48] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса.
[THR:017468] [15.02.2019 07:22:48] [test] nMaxStatements: 64999
[THR:017468] [15.02.2019 07:22:49] [test] RemoteFB__Connector::ConnectToDatabase ...OK
[THR:017468] [15.02.2019 07:22:49] [test] RemoteFB__Connector::StartTransaction ...OK
[THR:017468] [15.02.2019 07:22:49] [test] -------------------------------- pass: 1
[THR:017468] [15.02.2019 07:22:49] [test] Allocate statements ...
[THR:017468] [15.02.2019 07:22:49] [test] ----
[THR:017468] [15.02.2019 07:23:12] [test] Drop statements ...
[THR:017468] [15.02.2019 07:23:12] [test] -------------------------------- pass: 2
[THR:017468] [15.02.2019 07:23:12] [test] Allocate statements ...
[THR:017468] [15.02.2019 07:23:45] [test] ----
[THR:017468] [15.02.2019 07:24:09] [test] Drop statements ...
[THR:017468] [15.02.2019 07:24:10] [test] -------------------------------- pass: 3
[THR:017468] [15.02.2019 07:24:10] [test] Allocate statements ...
[THR:017468] [15.02.2019 07:24:45] [test] ----
[THR:017468] [15.02.2019 07:25:09] [test] Drop statements ...
[THR:017468] [15.02.2019 07:25:09] [test] RemoteFB__Connector::Commit ...OK
[THR:017468] [15.02.2019 07:25:14] [test] RemoteFB__Connector::DetachDatabase ...OK
[THR:017468] [15.02.2019 07:25:14] *
[THR:017468] [15.02.2019 07:25:14] * REAL   TIME:1693444756    [00:02:49.3444756]
[THR:017468] [15.02.2019 07:25:14] * USER   TIME:337656250     [00:00:33.7656250]
[THR:017468] [15.02.2019 07:25:14] * KERNEL TIME:58906250      [00:00:05.8906250]
[THR:017468] [15.02.2019 07:25:14] * TOTAL  TIME:396562500     [00:00:39.6562500]
[THR:017468] [15.02.2019 07:25:14] *
[THR:017468] [15.02.2019 07:25:14] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]

Так, так…

Первый прогон (руки крюки жеж):

[THR:007156] [15.02.2019 04:12:50] ***********************************************
[THR:007156] [15.02.2019 04:12:50] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
[THR:007156] [15.02.2019 04:12:50] *
[THR:007156] [15.02.2019 04:12:50] [test] Hello from test!
[THR:007156] [15.02.2019 04:12:51] [test] RemoteFB__Connector::ConnectToDatabase ...OK
[THR:007156] [15.02.2019 04:12:51] [test] RemoteFB__Connector::StartTransaction ...OK
[THR:007156] [15.02.2019 04:12:51] [test] Allocate statements ...
[THR:007156] [15.02.2019 04:13:33] [test] OK. We got the error.
[THR:007156] [15.02.2019 04:13:33] [test] 1. [Firebird] too many open handles to database
[THR:007156] [15.02.2019 04:13:33] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса.
[THR:007156] [15.02.2019 04:13:33] [test] nMaxStatements: 64999
[THR:007156] [15.02.2019 04:13:34] [test] RemoteFB__Connector::ConnectToDatabase ...OK
[THR:007156] [15.02.2019 04:13:34] [test] RemoteFB__Connector::StartTransaction ...OK
[THR:007156] [15.02.2019 04:13:34] [test] -------------------------------- pass: 1
[THR:007156] [15.02.2019 04:13:34] [test] Allocate statements ...
[THR:007156] [15.02.2019 04:13:34] [test] ----
[THR:007156] [15.02.2019 04:14:07] [test] Drop statements ...
[THR:007156] [15.02.2019 04:14:08] [test] -------------------------------- pass: 2
[THR:007156] [15.02.2019 04:14:08] [test] Allocate statements ...
[THR:007156] [15.02.2019 04:16:02] [test] ----
[THR:007156] [15.02.2019 04:16:27] [test] Drop statements ...
[THR:007156] [15.02.2019 04:16:28] [test] -------------------------------- pass: 3
[THR:007156] [15.02.2019 04:16:28] [test] Allocate statements ...
[THR:007156] [15.02.2019 04:18:20] [test] ----
[THR:007156] [15.02.2019 04:18:45] [test] Drop statements ...
[THR:007156] [15.02.2019 04:18:45] [test] RemoteFB__Connector::Commit ...OK
[THR:007156] [15.02.2019 04:18:50] [test] RemoteFB__Connector::DetachDatabase ...OK
[THR:007156] [15.02.2019 04:18:50] *
[THR:007156] [15.02.2019 04:18:50] * REAL   TIME:3603889572    [00:06:00.3889572]
[THR:007156] [15.02.2019 04:18:50] * USER   TIME:302031250     [00:00:30.2031250]
[THR:007156] [15.02.2019 04:18:50] * KERNEL TIME:58906250      [00:00:05.8906250]
[THR:007156] [15.02.2019 04:18:50] * TOTAL  TIME:360937500     [00:00:36.0937500]
[THR:007156] [15.02.2019 04:18:50] *
[THR:007156] [15.02.2019 04:18:50] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]

Нет, я так не играю. Неужели починили?

Второй прогон:

[THR:001584] [15.02.2019 06:24:14] ***********************************************
[THR:001584] [15.02.2019 06:24:14] * START TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]
[THR:001584] [15.02.2019 06:24:14] *
[THR:001584] [15.02.2019 06:24:14] [test] Hello from test!
[THR:001584] [15.02.2019 06:24:14] [test] RemoteFB__Connector::ConnectToDatabase ...OK
[THR:001584] [15.02.2019 06:24:14] [test] RemoteFB__Connector::StartTransaction ...OK
[THR:001584] [15.02.2019 06:24:14] [test] Allocate statements ...
[THR:001584] [15.02.2019 06:24:34] [test] OK. We got the error.
[THR:001584] [15.02.2019 06:24:34] [test] 1. [Firebird] too many open handles to database
[THR:001584] [15.02.2019 06:24:34] [test] 2. [LCPI.IBProvider.5] [Подсистема: remote_fb.p13] Ошибка инициализации дескриптора запроса.
[THR:001584] [15.02.2019 06:24:34] [test] nMaxStatements: 64999
[THR:001584] [15.02.2019 06:24:34] [test] RemoteFB__Connector::ConnectToDatabase ... FAILED
[THR:001584] [15.02.2019 06:24:34] ERROR: [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts] [LCPI.IBProvider.5] [winsock] Сбой чтения данных из порта подключения. Ошибка WinSock: 10054.
[THR:001584] [15.02.2019 06:24:34] *
[THR:001584] [15.02.2019 06:24:34] * REAL   TIME:201587949     [00:00:20.1587949]
[THR:001584] [15.02.2019 06:24:34] * USER   TIME:26406250      [00:00:02.6406250]
[THR:001584] [15.02.2019 06:24:34] * KERNEL TIME:19843750      [00:00:01.9843750]
[THR:001584] [15.02.2019 06:24:34] * TOTAL  TIME:46250000      [00:00:04.6250000]
[THR:001584] [15.02.2019 06:24:34] *
[THR:001584] [15.02.2019 06:24:34] * STOP TEST [RemoteFB.WORK.013.StmtAllocate.v2.ptype__lazy_send.011.check_release_of_dropped_stmts]

Сервер таки навернулся и перезапустился:

Даже немного грустно стало, он достаточно долго прожил:

Состояние на 12 февраля 2019 года.

Дескрипторы текут. Думал — сейчас через неделю еще один screenshot сделаю. Не судьба.

В логе сервера по поводу этого краша — пусто.

В журнале Windows:

Служба Firebird Server — DefaultInstance была неожиданно завершена. Это произошло 1 раз(а). Следующее корректирующее действие будет предпринято через 0 мсек: Перезапуск службы.

В других потоках этого прогона пишут:

[THR:007372] [15.02.2019 06:24:34] ***********************************************
[THR:007372] [15.02.2019 06:24:34] * START TEST [RemoteFB.WORK.019.StmtExecute.v1.ptype__batch_send.S008.insert.with_param3]
[THR:007372] [15.02.2019 06:24:34] *
[THR:007372] [15.02.2019 06:24:34] [test] Hello from test!
[THR:007372] [15.02.2019 06:24:34] [test] RemoteFB__Connector::ConnectToDatabase ... FAILED
[THR:007372] [15.02.2019 06:24:34] ERROR: [RemoteFB.WORK.019.StmtExecute.v1.ptype__batch_send.S008.insert.with_param3] [LCPI.IBProvider.5] [winsock] Сбой чтения данных из порта подключения. Ошибка WinSock: 10054.

Параллельно на сервере работало стандартное нагрузочное тестирование. На другой базе. Там пишут следующее:

[THR:035180] [15.02.2019 06:21:08] ***********************************************
[THR:035180] [15.02.2019 06:21:08] * START TEST [rowset.large_row.rw_update__asynch_fetch.cache_1024]
[THR:035180] [15.02.2019 06:21:08] *
[THR:035180] [15.02.2019 06:21:08] * PREPARE
[THR:035180] [15.02.2019 06:21:08] * RUN
[THR:035180] [15.02.2019 06:21:08] [test] Test row ids: [1...65537)
[THR:035180] [15.02.2019 06:21:08] [test] create pooled data source...
[THR:035180] [15.02.2019 06:21:08] [test] connect to database ...OK
[THR:035180] [15.02.2019 06:21:08] [test] Session Create ...
[THR:035180] [15.02.2019 06:21:08] [test] START TRANSACTION ...
[THR:035180] [15.02.2019 06:21:08] [test] ------------- [Read and check row data]
[THR:035180] [15.02.2019 06:21:08] [test] RowCacheSize: 1024
[THR:035180] [15.02.2019 06:21:08] [test] Create command ...
[THR:035180] [15.02.2019 06:21:08] [test] "IRowsetUpdate"=[TRUE [-1]] ...OK
[THR:035180] [15.02.2019 06:21:08] [test] "IRowsetChange"=[TRUE [-1]] ...OK
[THR:035180] [15.02.2019 06:21:08] [test] Set Command Prop [201][{C8B522BE-5CF3-11CE-ADE5-00AA0044773D}]: 8L
[THR:035180] [15.02.2019 06:21:08] [test] OK. We got the correct result status of call: [S_OK][DBPROPSTATUS_OK]
[THR:035180] [15.02.2019 06:21:08] [test] Prepare Command:

"select test_id,large_text from TEST_LARGE_ROW
where test_id>=? and test_id<?
order by test_id"

[THR:035180] [15.02.2019 06:21:08] [test] EXECUTE COMMAND (or=true,rpi=true) 
[THR:035180] [15.02.2019 06:21:08] [test]  [0][in][]:I8[S_OK][1]
[THR:035180] [15.02.2019 06:21:08] [test]  [1][in][]:I8[S_OK][65537]
[THR:035180] [15.02.2019 06:21:08] [test] 
[THR:035180] [15.02.2019 06:21:08] [test] pass: 1
[THR:035180] [15.02.2019 06:21:08] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:21:56] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:21:56] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:21:56] [test] 
[THR:035180] [15.02.2019 06:21:56] [test] pass: 2
[THR:035180] [15.02.2019 06:21:56] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:22:19] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:22:19] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:22:19] [test] 
[THR:035180] [15.02.2019 06:22:19] [test] pass: 3
[THR:035180] [15.02.2019 06:22:19] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:22:40] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:22:40] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:22:40] [test] 
[THR:035180] [15.02.2019 06:22:40] [test] pass: 4
[THR:035180] [15.02.2019 06:22:40] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:23:03] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:23:03] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:23:03] [test] 
[THR:035180] [15.02.2019 06:23:03] [test] pass: 5
[THR:035180] [15.02.2019 06:23:03] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:23:35] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:23:35] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:23:35] [test] 
[THR:035180] [15.02.2019 06:23:35] [test] pass: 6
[THR:035180] [15.02.2019 06:23:35] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:23:59] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:23:59] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:23:59] [test] 
[THR:035180] [15.02.2019 06:23:59] [test] pass: 7
[THR:035180] [15.02.2019 06:23:59] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:24:25] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:24:25] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:24:25] [test] 
[THR:035180] [15.02.2019 06:24:25] [test] pass: 8
[THR:035180] [15.02.2019 06:24:25] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:24:49] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:24:49] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:24:49] [test] 
[THR:035180] [15.02.2019 06:24:49] [test] pass: 9
[THR:035180] [15.02.2019 06:24:49] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:25:22] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:25:22] [test] CURSOR RESTART...OK
[THR:035180] [15.02.2019 06:25:22] [test] 
[THR:035180] [15.02.2019 06:25:22] [test] pass: 10
[THR:035180] [15.02.2019 06:25:22] [test] LARGE_TEXT length:8100
[THR:035180] [15.02.2019 06:25:51] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:035180] [15.02.2019 06:25:51] [test] COMMIT TRANSACTION [RETAINING=false]...
[THR:035180] [15.02.2019 06:25:51] ERROR: [rowset.large_row.rw_update__asynch_fetch.cache_1024] Commit transaction
1. [LCPI.IBProvider.5]: [winsock] Сбой записи данных в порт подключения. Ошибка WinSock: 10054.
2. [LCPI.IBProvider.5]: Ошибка подтверждения транзакции. Транзакция будет отменена.
3. [LCPI.IBProvider.5]: [Подсистема: remote_fb] Запись в порт невозможна. Предыдущая операция записи завершилась с ошибками.
4. [LCPI.IBProvider.5]: Ошибка отката транзакции.
Неопознанная ошибка

COM Error Code: E_FAIL
[THR:035180] [15.02.2019 06:25:51] *
[THR:035180] [15.02.2019 06:25:51] * REAL   TIME: 2836405955    [00:04:43.6405955]
[THR:035180] [15.02.2019 06:25:51] * USER   TIME: 1949375000    [00:03:14.9375000]
[THR:035180] [15.02.2019 06:25:51] * KERNEL TIME: 94218750      [00:00:09.4218750]
[THR:035180] [15.02.2019 06:25:51] * TOTAL  TIME: 2043593750    [00:03:24.3593750]
[THR:035180] [15.02.2019 06:25:51] *
[THR:035180] [15.02.2019 06:25:51] * ERROR   COUNT: 1
[THR:035180] [15.02.2019 06:25:51] * WARNING COUNT: 0
[THR:035180] [15.02.2019 06:25:51] *
[THR:035180] [15.02.2019 06:25:51] * STOP TEST [rowset.large_row.rw_update__asynch_fetch.cache_1024]
[THR:035180] [15.02.2019 06:25:51] 
[THR:044488] [15.02.2019 06:20:00] ***********************************************
[THR:044488] [15.02.2019 06:20:00] * START TEST [rowset.large_row.rw_update__asynch_fetch.cache_128]
[THR:044488] [15.02.2019 06:20:00] *
[THR:044488] [15.02.2019 06:20:00] * PREPARE
[THR:044488] [15.02.2019 06:20:00] * RUN
[THR:044488] [15.02.2019 06:20:00] [test] Test row ids: [1...65537)
[THR:044488] [15.02.2019 06:20:00] [test] create pooled data source...
[THR:044488] [15.02.2019 06:20:00] [test] connect to database ...OK
[THR:044488] [15.02.2019 06:20:00] [test] Session Create ...
[THR:044488] [15.02.2019 06:20:00] [test] START TRANSACTION ...
[THR:044488] [15.02.2019 06:20:00] [test] ------------- [Read and check row data]
[THR:044488] [15.02.2019 06:20:00] [test] RowCacheSize: 128
[THR:044488] [15.02.2019 06:20:00] [test] Create command ...
[THR:044488] [15.02.2019 06:20:00] [test] "IRowsetUpdate"=[TRUE [-1]] ...OK
[THR:044488] [15.02.2019 06:20:00] [test] "IRowsetChange"=[TRUE [-1]] ...OK
[THR:044488] [15.02.2019 06:20:00] [test] Set Command Prop [201][{C8B522BE-5CF3-11CE-ADE5-00AA0044773D}]: 8L
[THR:044488] [15.02.2019 06:20:00] [test] OK. We got the correct result status of call: [S_OK][DBPROPSTATUS_OK]
[THR:044488] [15.02.2019 06:20:00] [test] Prepare Command:

"select test_id,large_text from TEST_LARGE_ROW
where test_id>=? and test_id<?
order by test_id"

[THR:044488] [15.02.2019 06:20:00] [test] EXECUTE COMMAND (or=true,rpi=true) 
[THR:044488] [15.02.2019 06:20:00] [test]  [0][in][]:I8[S_OK][1]
[THR:044488] [15.02.2019 06:20:00] [test]  [1][in][]:I8[S_OK][65537]
[THR:044488] [15.02.2019 06:20:00] [test] 
[THR:044488] [15.02.2019 06:20:00] [test] pass: 1
[THR:044488] [15.02.2019 06:20:00] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:20:59] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:20:59] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:20:59] [test] 
[THR:044488] [15.02.2019 06:20:59] [test] pass: 2
[THR:044488] [15.02.2019 06:20:59] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:21:24] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:21:24] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:21:24] [test] 
[THR:044488] [15.02.2019 06:21:24] [test] pass: 3
[THR:044488] [15.02.2019 06:21:24] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:21:47] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:21:47] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:21:47] [test] 
[THR:044488] [15.02.2019 06:21:47] [test] pass: 4
[THR:044488] [15.02.2019 06:21:47] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:22:10] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:22:10] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:22:10] [test] 
[THR:044488] [15.02.2019 06:22:10] [test] pass: 5
[THR:044488] [15.02.2019 06:22:10] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:22:31] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:22:31] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:22:31] [test] 
[THR:044488] [15.02.2019 06:22:31] [test] pass: 6
[THR:044488] [15.02.2019 06:22:31] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:22:54] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:22:54] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:22:54] [test] 
[THR:044488] [15.02.2019 06:22:54] [test] pass: 7
[THR:044488] [15.02.2019 06:22:54] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:23:23] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:23:23] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:23:23] [test] 
[THR:044488] [15.02.2019 06:23:23] [test] pass: 8
[THR:044488] [15.02.2019 06:23:23] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:23:49] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:23:49] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:23:49] [test] 
[THR:044488] [15.02.2019 06:23:49] [test] pass: 9
[THR:044488] [15.02.2019 06:23:49] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:24:14] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:24:14] [test] CURSOR RESTART...OK
[THR:044488] [15.02.2019 06:24:14] [test] 
[THR:044488] [15.02.2019 06:24:14] [test] pass: 10
[THR:044488] [15.02.2019 06:24:14] [test] LARGE_TEXT length:8100
[THR:044488] [15.02.2019 06:24:39] [test] Result Storage Size: DEC[S_OK][539156480]
[THR:044488] [15.02.2019 06:24:39] [test] COMMIT TRANSACTION [RETAINING=false]...
[THR:044488] [15.02.2019 06:24:39] ERROR: [rowset.large_row.rw_update__asynch_fetch.cache_128] Commit transaction
1. [LCPI.IBProvider.5]: [winsock] Сбой записи данных в порт подключения. Ошибка WinSock: 10054.
2. [LCPI.IBProvider.5]: Ошибка подтверждения транзакции. Транзакция будет отменена.
3. [LCPI.IBProvider.5]: [Подсистема: remote_fb] Запись в порт невозможна. Предыдущая операция записи завершилась с ошибками.
4. [LCPI.IBProvider.5]: Ошибка отката транзакции.
Неопознанная ошибка

COM Error Code: E_FAIL
[THR:044488] [15.02.2019 06:24:39] *
[THR:044488] [15.02.2019 06:24:39] * REAL   TIME: 2795972264    [00:04:39.5972264]
[THR:044488] [15.02.2019 06:24:39] * USER   TIME: 1882656250    [00:03:08.2656250]
[THR:044488] [15.02.2019 06:24:39] * KERNEL TIME: 90312500      [00:00:09.0312500]
[THR:044488] [15.02.2019 06:24:39] * TOTAL  TIME: 1972968750    [00:03:17.2968750]
[THR:044488] [15.02.2019 06:24:39] *
[THR:044488] [15.02.2019 06:24:39] * ERROR   COUNT: 1
[THR:044488] [15.02.2019 06:24:39] * WARNING COUNT: 0
[THR:044488] [15.02.2019 06:24:39] *
[THR:044488] [15.02.2019 06:24:39] * STOP TEST [rowset.large_row.rw_update__asynch_fetch.cache_128]
[THR:044488] [15.02.2019 06:24:39] 

В остальных двух потоках ошибки в том же духе.

Сижу и думаю, это у меня уже профессиональное чутьё или инстинкт самосохранения сработал — не запускать эти тесты в процессе финального тестирования v5. Я бы кучу времени потерял.

Leave a Comment